libMesh::PerfLog Class Reference

Responsible for timing and summarizing events. More...

#include <perf_log.h>

Public Member Functions

 PerfLog (const std::string &label_name="", const bool log_events=true)
 
 ~PerfLog ()
 
void clear ()
 
void disable_logging ()
 
void enable_logging ()
 
bool logging_enabled () const
 
void push (const char *label, const char *header="")
 
void push (const std::string &label, const std::string &header="")
 
void pop (const char *label, const char *header="")
 
void pop (const std::string &label, const std::string &header="")
 
void start_event (const std::string &label, const std::string &header="")
 
void stop_event (const std::string &label, const std::string &header="")
 
void pause_event (const std::string &label, const std::string &header="")
 
void restart_event (const std::string &label, const std::string &header="")
 
std::string get_log () const
 
std::string get_info_header () const
 
std::string get_perf_info () const
 
void print_log () const
 
double get_elapsed_time () const
 
double get_active_time () const
 
PerfData get_perf_data (const std::string &label, const std::string &header="")
 
const std::map< std::pair< std::string, std::string >, PerfData > & get_log_raw () const
 

Private Member Functions

void split_on_whitespace (const std::string &input, std::vector< std::string > &output) const
 

Private Attributes

const std::string label_name
 
bool log_events
 
double total_time
 
struct timeval tstart
 
std::map< std::pair< std::string, std::string >, PerfDatalog
 
std::stack< PerfData * > log_stack
 

Static Private Attributes

static bool called = false
 

Detailed Description

Responsible for timing and summarizing events.

The PerfLog class allows monitoring of specific events. An event is defined by a unique string that functions as a label. Each time the event is executed data are recorded. This class is particularly useful for finding performance bottlenecks.

Author
Benjamin Kirk
Date
2003

Definition at line 124 of file perf_log.h.

Constructor & Destructor Documentation

libMesh::PerfLog::PerfLog ( const std::string &  label_name = "",
const bool  log_events = true 
)

Constructor. label_name is the name of the object, which will bw print in the log to distinguish it from other objects. log_events is a flag to optionally disable logging. You can use this flag to turn off logging without touching any other code.

Definition at line 50 of file perf_log.C.

References clear(), libmesh_nullptr, log_events, and tstart.

51  :
52  label_name(ln),
53  log_events(le),
54  total_time(0.)
55 {
56  gettimeofday (&tstart, libmesh_nullptr);
57 
58  if (log_events)
59  this->clear();
60 }
double total_time
Definition: perf_log.h:273
const class libmesh_nullptr_t libmesh_nullptr
const std::string label_name
Definition: perf_log.h:263
void clear()
Definition: perf_log.C:72
struct timeval tstart
Definition: perf_log.h:278
libMesh::PerfLog::~PerfLog ( )

Destructor. Calls clear() and print_log().

Definition at line 64 of file perf_log.C.

References log_events, and print_log().

65 {
66  if (log_events)
67  this->print_log();
68 }
void print_log() const
Definition: perf_log.C:605

Member Function Documentation

void libMesh::PerfLog::clear ( )

Clears all the internal data and restores the data structures to a pristine state. This function checks to see if it is currently monitoring any events, and if so errors. Be sure you are not logging any events when you call this function.

Definition at line 72 of file perf_log.C.

References label_name, libmesh_nullptr, log, log_events, log_stack, and tstart.

Referenced by libMesh::libmesh_terminate_handler(), libMesh::LibMeshInit::LibMeshInit(), and PerfLog().

73 {
74  if (log_events)
75  {
76  // check that all events are closed
77  for (std::map<std::pair<std::string,std::string>, PerfData>::iterator
78  pos = log.begin(); pos != log.end(); ++pos)
79  if (pos->second.open)
80  libmesh_error_msg("ERROR clearing performance log for class " \
81  << label_name \
82  << "\nevent " \
83  << pos->first.second \
84  << " is still being monitored!");
85 
86  gettimeofday (&tstart, libmesh_nullptr);
87 
88  log.clear();
89 
90  while (!log_stack.empty())
91  log_stack.pop();
92  }
93 }
const class libmesh_nullptr_t libmesh_nullptr
std::map< std::pair< std::string, std::string >, PerfData > log
Definition: perf_log.h:285
std::stack< PerfData * > log_stack
Definition: perf_log.h:290
const std::string label_name
Definition: perf_log.h:263
struct timeval tstart
Definition: perf_log.h:278
void libMesh::PerfLog::disable_logging ( )
inline

Disables performance logging for an active object.

Definition at line 155 of file perf_log.h.

Referenced by libMesh::LibMeshInit::LibMeshInit(), and libMesh::Threads::task_scheduler_init::terminate().

155 { log_events = false; }
void libMesh::PerfLog::enable_logging ( )
inline

Enables performance logging for an active object.

Definition at line 160 of file perf_log.h.

Referenced by libMesh::Threads::task_scheduler_init::terminate().

160 { log_events = true; }
double libMesh::PerfLog::get_active_time ( ) const
inline
Returns
The active time

Definition at line 469 of file perf_log.h.

470 {
471  return total_time;
472 }
double total_time
Definition: perf_log.h:273
double libMesh::PerfLog::get_elapsed_time ( ) const
inline
Returns
The total time spent on this event.

Definition at line 457 of file perf_log.h.

References libmesh_nullptr, and libMesh::PerfData::tstart.

458 {
459  struct timeval tnow;
460 
461  gettimeofday (&tnow, libmesh_nullptr);
462 
463  const double elapsed_time = (static_cast<double>(tnow.tv_sec - tstart.tv_sec) +
464  static_cast<double>(tnow.tv_usec - tstart.tv_usec)*1.e-6);
465  return elapsed_time;
466 }
const class libmesh_nullptr_t libmesh_nullptr
struct timeval tstart
Definition: perf_log.h:278
std::string libMesh::PerfLog::get_info_header ( ) const
Returns
A string containing ONLY the information header.

Definition at line 96 of file perf_log.C.

References libMesh::Utility::get_timestamp(), libMesh::global_n_processors(), libMesh::global_processor_id(), log_events, and split_on_whitespace().

Referenced by get_log().

97 {
98  std::ostringstream oss;
99 
100  if (log_events)
101  {
102  std::string date = Utility::get_timestamp();
103 
104 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
105  // Get system information
106  struct utsname sysInfo;
107  uname(&sysInfo);
108 #endif
109 
110  // Get user information
111  //
112  // Some systems, for example Crays, actually have getpwuid on the head-node
113  // but (if I understand correctly) a dynamically-linked glibc is not available
114  // on the backend, which is running a reduced operating system like Compute
115  // Node Linux. Thus functions like getpwuid cannot be called. This makes
116  // automatically testing for the existence of getpwuid on the login node
117  // difficult. The configure test would work on the login node but will fail
118  // on the backend. Hence we have added a configure flag, --disable-getpwuid,
119  // to manually turn this off.
120 #ifdef LIBMESH_HAVE_GETPWUID
121  struct passwd * p = getpwuid(getuid());
122 #endif
123  oss << "\n";
124 
125  // Construct string stream objects for each of the outputs
126  std::ostringstream
127  pid_stream,
128  nprocs_stream,
129  time_stream,
130  os_stream,
131  host_stream,
132  osrel_stream,
133  osver_stream,
134  machine_stream,
135  user_stream;
136 
137 
138  // Put pointers to these streams in a vector
139  std::vector<std::ostringstream*> v;
140  v.push_back(&pid_stream);
141  v.push_back(&nprocs_stream);
142  v.push_back(&time_stream);
143  v.push_back(&os_stream);
144  v.push_back(&host_stream);
145  v.push_back(&osrel_stream);
146  v.push_back(&osver_stream);
147  v.push_back(&machine_stream);
148  v.push_back(&user_stream);
149 
150  // Fill string stream objects
152  {
153  pid_stream << "| Processor id: " << libMesh::global_processor_id();
154  nprocs_stream << "| Num Processors: " << libMesh::global_n_processors();
155  }
156 
157  time_stream << "| Time: ";
158  os_stream << "| OS: ";
159  host_stream << "| HostName: ";
160  osrel_stream << "| OS Release: ";
161  osver_stream << "| OS Version: ";
162  machine_stream << "| Machine: ";
163 
164  time_stream << date;
165 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
166  os_stream << sysInfo.sysname ;
167  host_stream << sysInfo.nodename ;
168  osrel_stream << sysInfo.release ;
169  osver_stream << sysInfo.version ;
170  machine_stream << sysInfo.machine ;
171 #else
172  os_stream << "Unknown";
173  host_stream << "Unknown";
174  osrel_stream << "Unknown";
175  osver_stream << "Unknown";
176  machine_stream << "Unknown";
177 
178 #endif
179  user_stream << "| Username: ";
180 #ifdef LIBMESH_HAVE_GETPWUID
181  if (p && p->pw_name)
182  user_stream << p->pw_name;
183  else
184 #endif
185  user_stream << "Unknown";
186 
187  // Parse the LIBMESH_CONFIGURE_INFO string literal before using it in PerfLog output
188  std::string libmesh_configure_info(LIBMESH_CONFIGURE_INFO);
189  std::vector<std::string> parsed_libmesh_configure_info;
190  this->split_on_whitespace(libmesh_configure_info,
191  parsed_libmesh_configure_info);
192 
193  // There should always be at at least one entry in
194  // parsed_libmesh_configure_info, even if the user just ran
195  // ../configure.
196  libmesh_assert_greater (parsed_libmesh_configure_info.size(), 0);
197 
198  // Find the longest string in all the streams
199  unsigned int max_length = 0;
200  for (std::size_t i=0; i<v.size(); ++i)
201  if (v[i]->str().size() > max_length)
202  max_length = cast_int<unsigned int>
203  (v[i]->str().size());
204 
205  // Find the longest string in the parsed_libmesh_configure_info
206  for (std::size_t i=0; i<parsed_libmesh_configure_info.size(); ++i)
207  if (parsed_libmesh_configure_info[i].size() > max_length)
208  max_length = cast_int<unsigned int>
209  (parsed_libmesh_configure_info[i].size());
210 
211  // Print dashed line for the header
212  oss << ' '
213  << std::string(max_length+1, '-')
214  << '\n';
215 
216  // Loop over all the strings and add end formatting
217  for (std::size_t i=0; i<v.size(); ++i)
218  {
219  if (v[i]->str().size())
220  oss << v[i]->str()
221  << std::setw (cast_int<int>
222  (max_length + 4 - v[i]->str().size()))
223  << std::right
224  << "|\n";
225  }
226 
227  // Print out configuration header plus first parsed string. The
228  // magic number 18 below accounts for the length of the word
229  // 'Configuration'.
230  oss << "| Configuration: "
231  << parsed_libmesh_configure_info[0]
232  << std::setw (cast_int<int>
233  (max_length + 4 -
234  parsed_libmesh_configure_info[0].size() - 18))
235  << std::right
236  << "|\n";
237 
238  // Loop over the parsed_libmesh_configure_info and add end formatting. The magic
239  // number 3 below accounts for the leading 'pipe' character and indentation
240  for (std::size_t i=1; i<parsed_libmesh_configure_info.size(); ++i)
241  {
242  oss << "| "
243  << parsed_libmesh_configure_info[i]
244  << std::setw (cast_int<int>
245  (max_length + 4 -
246  parsed_libmesh_configure_info[i].size() - 3))
247  << std::right
248  << "|\n";
249  }
250 
251 
252  // Print dashed line
253  oss << ' '
254  << std::string(max_length+1, '-')
255  << '\n';
256  }
257 
258  return oss.str();
259 }
processor_id_type global_n_processors()
Definition: libmesh_base.h:104
std::string get_timestamp()
Definition: timestamp.C:37
processor_id_type global_processor_id()
Definition: libmesh_base.h:114
void split_on_whitespace(const std::string &input, std::vector< std::string > &output) const
Definition: perf_log.C:654
std::string libMesh::PerfLog::get_log ( ) const
Returns
A string containing: (1) Basic machine information (if first call) (2) The performance log

Definition at line 579 of file perf_log.C.

References called, get_info_header(), get_perf_info(), log, and log_events.

Referenced by print_log().

580 {
581  std::ostringstream oss;
582 
583  if (log_events)
584  {
585  // Only print the log
586  // if it isn't empty
587  if (!log.empty())
588  {
589  // Possibly print machine info,
590  // but only do this once
591  if (!called)
592  {
593  called = true;
594  oss << get_info_header();
595  }
596  oss << get_perf_info();
597  }
598  }
599 
600  return oss.str();
601 }
std::map< std::pair< std::string, std::string >, PerfData > log
Definition: perf_log.h:285
std::string get_perf_info() const
Definition: perf_log.C:264
std::string get_info_header() const
Definition: perf_log.C:96
static bool called
Definition: perf_log.h:297
const std::map< std::pair<std::string, std::string>, PerfData >& libMesh::PerfLog::get_log_raw ( ) const
inline
Returns
the raw underlying data structure for the entire performance log.

Definition at line 255 of file perf_log.h.

255 { return log; }
std::map< std::pair< std::string, std::string >, PerfData > log
Definition: perf_log.h:285
PerfData libMesh::PerfLog::get_perf_data ( const std::string &  label,
const std::string &  header = "" 
)

Return the PerfData object associated with a label and header.

Definition at line 617 of file perf_log.C.

References log.

618 {
619  return log[std::make_pair(header, label)];
620 }
std::map< std::pair< std::string, std::string >, PerfData > log
Definition: perf_log.h:285
std::string libMesh::PerfLog::get_perf_info ( ) const
Returns
A string containing ONLY the log information

Definition at line 264 of file perf_log.C.

References libMesh::PerfData::count, label_name, libmesh_nullptr, log, log_events, libMesh::Real, libMesh::PerfData::tot_time, libMesh::PerfData::tot_time_incl_sub, total_time, and tstart.

Referenced by get_log().

265 {
266  std::ostringstream oss;
267 
268  if (log_events && !log.empty())
269  {
270  // Stop timing for this event.
271  struct timeval tstop;
272 
273  gettimeofday (&tstop, libmesh_nullptr);
274 
275  const double elapsed_time = (static_cast<double>(tstop.tv_sec - tstart.tv_sec) +
276  static_cast<double>(tstop.tv_usec - tstart.tv_usec)*1.e-6);
277 
278  // Figure out the formatting required based on the event names
279  // Unsigned ints for each of the column widths
280  unsigned int event_col_width = 30;
281  const unsigned int ncalls_col_width = 11;
282  const unsigned int tot_time_col_width = 12;
283  const unsigned int avg_time_col_width = 12;
284  const unsigned int tot_time_incl_sub_col_width = 12;
285  const unsigned int avg_time_incl_sub_col_width = 12;
286  const unsigned int pct_active_col_width = 9;
287  const unsigned int pct_active_incl_sub_col_width = 9;
288 
289  // Iterator to be used to loop over the map of timed events
290  std::map<std::pair<std::string,std::string>, PerfData>::const_iterator pos;
291 
292  // Reset the event column width based on the longest event name plus
293  // a possible 2-character indentation, plus a space.
294  for (pos = log.begin(); pos != log.end(); ++pos)
295  if (pos->first.second.size()+3 > event_col_width)
296  event_col_width = cast_int<unsigned int>
297  (pos->first.second.size()+3);
298 
299  // Set the total width of the column
300  const unsigned int total_col_width =
301  event_col_width +
302  ncalls_col_width +
303  tot_time_col_width +
304  avg_time_col_width +
305  tot_time_incl_sub_col_width +
306  avg_time_incl_sub_col_width +
307  pct_active_col_width+
308  pct_active_incl_sub_col_width+1;
309 
310  // Print dashed line
311  oss << ' '
312  << std::string(total_col_width, '-')
313  << '\n';
314 
315  {
316  // Construct temporary message string
317  std::ostringstream temp;
318  temp << "| " << label_name << " Performance: Alive time=" << elapsed_time
319  << ", Active time=" << total_time;
320 
321  // Get the size of the temporary string
322  const unsigned int temp_size = cast_int<unsigned int>
323  (temp.str().size());
324 
325  // Send the temporary message to the output
326  oss << temp.str();
327 
328  // If this string is longer than the previously computed total
329  // column width, skip the additional formatting... this shouldn't
330  // happen often, hopefully. Add two additional characters for a
331  // space and a "|" character at the end.
332  if (temp_size < total_col_width+2)
333  oss << std::setw(total_col_width - temp_size + 2)
334  << std::right
335  << "|";
336 
337  oss << '\n';
338  }
339 
340  // Print dashed line
341  oss << ' '
342  << std::string(total_col_width, '-')
343  << '\n';
344 
345 
346  // Write out the header for the events listing
347  oss << "| "
348  << std::setw(event_col_width)
349  << std::left
350  << "Event"
351  << std::setw(ncalls_col_width)
352  << std::left
353  << "nCalls"
354  << std::setw(tot_time_col_width)
355  << std::left
356  << "Total Time"
357  << std::setw(avg_time_col_width)
358  << std::left
359  << "Avg Time"
360  << std::setw(tot_time_incl_sub_col_width)
361  << std::left
362  << "Total Time"
363  << std::setw(avg_time_incl_sub_col_width)
364  << std::left
365  << "Avg Time"
366  << std::setw(pct_active_col_width+pct_active_incl_sub_col_width)
367  << std::left
368  << "% of Active Time"
369  << "|\n"
370  << "| "
371  << std::setw(event_col_width)
372  << std::left
373  << ""
374  << std::setw(ncalls_col_width)
375  << std::left
376  << ""
377  << std::setw(tot_time_col_width)
378  << std::left
379  << "w/o Sub"
380  << std::setw(avg_time_col_width)
381  << std::left
382  << "w/o Sub"
383  << std::setw(tot_time_incl_sub_col_width)
384  << std::left
385  << "With Sub"
386  << std::setw(avg_time_incl_sub_col_width)
387  << std::left
388  << "With Sub"
389  << std::setw(pct_active_col_width)
390  << std::left
391  << "w/o S"
392  << std::setw(pct_active_incl_sub_col_width)
393  << std::left
394  << "With S"
395  << "|\n|"
396  << std::string(total_col_width, '-')
397  << "|\n|"
398  << std::string(total_col_width, ' ')
399  << "|\n";
400 
401  unsigned int summed_function_calls = 0;
402  double summed_total_time = 0;
403  double summed_percentage = 0;
404 
405  std::string last_header("");
406 
407  for (pos = log.begin(); pos != log.end(); ++pos)
408  {
409  const PerfData & perf_data = pos->second;
410 
411  // Only print the event if the count is non-zero.
412  if (perf_data.count != 0)
413  {
414  const unsigned int perf_count = perf_data.count;
415  const double perf_time = perf_data.tot_time;
416  const double perf_avg_time = perf_time / static_cast<double>(perf_count);
417  const double perf_time_incl_sub = perf_data.tot_time_incl_sub;
418  const double perf_avg_time_incl_sub = perf_time_incl_sub / static_cast<double>(perf_count);
419  const double perf_percent = (total_time != 0.) ? perf_time / total_time * 100. : 0.;
420  const double perf_percent_incl_sub = (total_time != 0.) ? perf_time_incl_sub / total_time * 100. : 0.;
421 
422  summed_function_calls += perf_count;
423  summed_total_time += perf_time;
424  summed_percentage += perf_percent;
425 
426  // Print the event name
427  if (pos->first.first == "")
428  oss << "| "
429  << std::setw(event_col_width)
430  << std::left
431  << pos->first.second;
432 
433  else
434  {
435  if (last_header != pos->first.first)
436  {
437  last_header = pos->first.first;
438 
439  // print blank line followed by header name
440  // (account for additional space before the
441  // header)
442  oss << "|"
443  << std::string(total_col_width, ' ')
444  << "|\n| "
445  << std::setw(total_col_width-1)
446  << std::left
447  << pos->first.first
448  << "|\n";
449  }
450 
451  oss << "| "
452  << std::setw(event_col_width-2)
453  << std::left
454  << pos->first.second;
455  }
456 
457 
458  // Print the number of calls to the event.
459  oss << std::setw(ncalls_col_width)
460  << perf_count;
461 
462  // Save the original stream flags
463  std::ios_base::fmtflags out_flags = oss.flags();
464 
465  // Print the total time spent in the event
466  oss << std::fixed
467  << std::setprecision(4)
468  << std::setw(tot_time_col_width)
469  << std::left
470  << perf_time;
471 
472 
473  // Print the average time per function call
474  oss << std::fixed
475  << std::setprecision(6)
476  << std::setw(avg_time_col_width)
477  << std::left
478  << perf_avg_time;
479 
480  // Print the total time spent in the event incl. sub-events
481  oss << std::fixed
482  << std::setprecision(4)
483  << std::setw(tot_time_incl_sub_col_width)
484  << std::left
485  << perf_time_incl_sub;
486 
487  // Print the average time per function call incl. sub-events
488  oss << std::fixed
489  << std::setprecision(6)
490  << std::setw(avg_time_incl_sub_col_width)
491  << std::left
492  << perf_avg_time_incl_sub;
493 
494  // Print the percentage of the time spent in the event
495  oss << std::fixed
496  << std::setprecision(2)
497  << std::setw(pct_active_col_width)
498  << std::left
499  << perf_percent;
500 
501  // Print the percentage of the time spent in the event incl. sub-events
502  oss << std::fixed
503  << std::setprecision(2)
504  << std::setw(pct_active_incl_sub_col_width)
505  << std::left
506  << perf_percent_incl_sub;
507 
508  // Reset the stream flags
509  oss.flags(out_flags);
510 
511  oss << "|\n";
512  }
513  }
514 
515  oss << ' '
516  << std::string(total_col_width, '-')
517  << "\n| "
518  << std::setw(event_col_width)
519  << std::left
520  << "Totals:";
521 
522  // Print the total number of logged function calls
523  // For routines which are called many times, summed_function_calls may
524  // exceed 7 digits. If this happens use, scientific notation.
525  if (summed_function_calls < 9999999)
526  oss << std::setw(ncalls_col_width)
527  << summed_function_calls;
528 
529  else
530  {
531  // Save the original stream flags
532  std::ios_base::fmtflags out_flags = oss.flags();
533 
534  oss << std::scientific
535  << std::setprecision(3)
536  << std::setw(ncalls_col_width)
537  << std::left
538  << static_cast<Real>(summed_function_calls);
539 
540  // Reset the stream flags
541  oss.flags(out_flags);
542  }
543 
544  // Print the total time spent in logged function calls. Don't bother saving/restoring
545  // the flags here since we are almost done with this stream anyway...
546  oss << std::fixed
547  << std::setprecision(4)
548  << std::setw(tot_time_col_width)
549  << std::left
550  << summed_total_time;
551 
552  // Null, the average time doesn't make sense as a total
553  oss << std::setw(avg_time_col_width) << "";
554 
555  // Same for times that include sub-events
556  oss << std::setw(tot_time_incl_sub_col_width)
557  << ""
558  << std::setw(avg_time_incl_sub_col_width)
559  << "";
560 
561  // Print the total percentage followed by dashed line
562  oss << std::fixed
563  << std::setprecision(2)
564  << std::setw(pct_active_col_width)
565  << std::left
566  << summed_percentage
567  << std::setw(pct_active_incl_sub_col_width)
568  << ""
569  << "|\n "
570  << std::string(total_col_width, '-')
571  << '\n';
572  }
573 
574  return oss.str();
575 }
double total_time
Definition: perf_log.h:273
const class libmesh_nullptr_t libmesh_nullptr
std::map< std::pair< std::string, std::string >, PerfData > log
Definition: perf_log.h:285
const std::string label_name
Definition: perf_log.h:263
DIE A HORRIBLE DEATH HERE typedef LIBMESH_DEFAULT_SCALAR_TYPE Real
struct timeval tstart
Definition: perf_log.h:278
bool libMesh::PerfLog::logging_enabled ( ) const
inline
Returns
true iff performance logging is enabled

Definition at line 165 of file perf_log.h.

Referenced by libMesh::Threads::task_scheduler_init::terminate().

165 { return log_events; }
void libMesh::PerfLog::pause_event ( const std::string &  label,
const std::string &  header = "" 
)

Suspend monitoring of the event.

Definition at line 638 of file perf_log.C.

640 {
641  // nothing to do. pushing the next object on the stack will handle it
642 }
void libMesh::PerfLog::pop ( const char *  label,
const char *  header = "" 
)
inline

Pop the event label off the stack, resuming any lower event.

Definition at line 447 of file perf_log.h.

Referenced by push(), stop_event(), and libMesh::PerfItem::~PerfItem().

449 {
450  if (this->log_events)
451  this->pop(std::string(label), std::string(header));
452 }
void pop(const char *label, const char *header="")
Definition: perf_log.h:447
void libMesh::PerfLog::pop ( const std::string &  label,
const std::string &  header = "" 
)

Pop the event label off the stack, resuming any lower event.

void libMesh::PerfLog::print_log ( ) const

Print the log.

Definition at line 605 of file perf_log.C.

References get_log(), log_events, and libMesh::out.

Referenced by libMesh::libmesh_terminate_handler(), libMesh::LibMeshInit::LibMeshInit(), and ~PerfLog().

606 {
607  if (log_events)
608  {
609  // Check to see if the log_string is empty, and if so,
610  // avoid printing an unnecessary newline.
611  std::string log_string = this->get_log();
612  if (log_string.size() > 0)
613  libMesh::out << log_string << std::endl;
614  }
615 }
std::string get_log() const
Definition: perf_log.C:579
OStreamProxy out(std::cout)
void libMesh::PerfLog::push ( const char *  label,
const char *  header = "" 
)
inline

Push the event label onto the stack, pausing any active event.

Definition at line 402 of file perf_log.h.

References libMesh::err, libMesh::libmesh_assert(), libMesh::libmesh_dbg_var(), and pop().

Referenced by libMesh::PerfItem::PerfItem(), and start_event().

404 {
405  if (this->log_events)
406  this->push(std::string(label), std::string(header));
407 }
void push(const char *label, const char *header="")
Definition: perf_log.h:402
void libMesh::PerfLog::push ( const std::string &  label,
const std::string &  header = "" 
)
inline

Push the event label onto the stack, pausing any active event.

Definition at line 381 of file perf_log.h.

References libMesh::PerfData::pause(), and libMesh::PerfData::start().

383 {
384  if (this->log_events)
385  {
386  // Get a reference to the event data to avoid
387  // repeated map lookups
388  PerfData * perf_data = &(log[std::make_pair(header,label)]);
389 
390  if (!log_stack.empty())
391  total_time +=
392  log_stack.top()->pause();
393 
394  perf_data->start();
395  log_stack.push(perf_data);
396  }
397 }
double total_time
Definition: perf_log.h:273
std::map< std::pair< std::string, std::string >, PerfData > log
Definition: perf_log.h:285
std::stack< PerfData * > log_stack
Definition: perf_log.h:290
void libMesh::PerfLog::restart_event ( const std::string &  label,
const std::string &  header = "" 
)

Restart monitoring the event.

Definition at line 646 of file perf_log.C.

648 {
649  // nothing to do. popping the top off the stack will handle it.
650 }
void libMesh::PerfLog::split_on_whitespace ( const std::string &  input,
std::vector< std::string > &  output 
) const
private

Splits a string on whitespace into a vector of separate strings. This is used to make the LIBMESH_CONFIGURE_INFO a little more manageable.

Definition at line 654 of file perf_log.C.

Referenced by get_info_header().

655 {
656  // Check for easy return
657  if (input.size()==0)
658  return;
659 
660  // Here we hard-code the string to split on, since the algorithm below
661  // is somewhat specific to it...
662  const std::string split_on("' '");
663 
664  size_t current_pos = 0;
665  while (true)
666  {
667  // Find next end location
668  size_t end_pos = input.find(split_on, current_pos);
669 
670  if (end_pos != std::string::npos)
671  {
672  // Create substring. Note: the second argument to substr is
673  // the *length* of string to create, not the ending position!
674  output.push_back( input.substr(current_pos, end_pos - current_pos + 1) );
675 
676  // Update search starting position, make sure to go past the end of the split_on string, but
677  // include the previous single quote (hence the -1).
678  current_pos = end_pos + split_on.size() - 1;
679  }
680  else
681  {
682  // Push back whatever remains of the string onto the output.
683  // Note that substr with only 1 argument pushes back
684  // whatever remains of the string. This also handles the
685  // case where the string does not contain any matches.
686  output.push_back( input.substr(current_pos) );
687 
688  // We are done searching the string, so break out of the while loop
689  break;
690  }
691  }
692 }
void libMesh::PerfLog::start_event ( const std::string &  label,
const std::string &  header = "" 
)

Start monitoring the event named label.

Definition at line 622 of file perf_log.C.

References push().

624 {
625  this->push(label,header);
626 }
void push(const char *label, const char *header="")
Definition: perf_log.h:402
void libMesh::PerfLog::stop_event ( const std::string &  label,
const std::string &  header = "" 
)

Stop monitoring the event named label.

Definition at line 630 of file perf_log.C.

References pop().

632 {
633  this->pop(label,header);
634 }
void pop(const char *label, const char *header="")
Definition: perf_log.h:447

Member Data Documentation

bool libMesh::PerfLog::called = false
staticprivate

Flag indicating if print_log() has been called. This is used to print a header with machine-specific data the first time that print_log() is called.

Definition at line 297 of file perf_log.h.

Referenced by get_log().

const std::string libMesh::PerfLog::label_name
private

The label for this object.

Definition at line 263 of file perf_log.h.

Referenced by clear(), and get_perf_info().

std::map<std::pair<std::string, std::string>, PerfData> libMesh::PerfLog::log
private

The actual log.

Definition at line 285 of file perf_log.h.

Referenced by clear(), get_log(), get_perf_data(), and get_perf_info().

bool libMesh::PerfLog::log_events
private

Flag to optionally disable all logging.

Definition at line 268 of file perf_log.h.

Referenced by clear(), get_info_header(), get_log(), get_perf_info(), PerfLog(), print_log(), and ~PerfLog().

std::stack<PerfData*> libMesh::PerfLog::log_stack
private

A stack to hold the current performance log trace.

Definition at line 290 of file perf_log.h.

Referenced by clear().

double libMesh::PerfLog::total_time
private

The total running time for recorded events.

Definition at line 273 of file perf_log.h.

Referenced by get_perf_info().

struct timeval libMesh::PerfLog::tstart
private

The time we were constructed or last cleared.

Definition at line 278 of file perf_log.h.

Referenced by clear(), get_perf_info(), and PerfLog().


The documentation for this class was generated from the following files: