libMesh
Public Types | Public Member Functions | Private Member Functions | Private Attributes | Static Private Attributes | List of all members
libMesh::PerfLog Class Reference

The PerfLog class allows monitoring of specific events. More...

#include <perf_log.h>

Public Types

typedef std::map< std::pair< const char *, const char * >, PerfDatalog_type
 Typdef for the underlying logging data structure. More...
 

Public Member Functions

 PerfLog (const std::string &label_name="", const bool log_events=true)
 Constructor. More...
 
 ~PerfLog ()
 Destructor. More...
 
void clear ()
 Clears all the internal data and restores the data structures to a pristine state. More...
 
void disable_logging ()
 Disables performance logging for an active object. More...
 
void enable_logging ()
 Enables performance logging for an active object. More...
 
bool logging_enabled () const
 
void fast_push (const char *label, const char *header="")
 Push the event label onto the stack, pausing any active event. More...
 
void push (const char *label, const char *header="")
 Push the event label onto the stack, pausing any active event. More...
 
void push (const std::string &label, const std::string &header="")
 Push the event label onto the stack, pausing any active event. More...
 
void fast_pop (const char *label, const char *header="")
 Pop the event label off the stack, resuming any lower event. More...
 
void pop (const char *label, const char *header="")
 Pop the event label off the stack, resuming any lower event. More...
 
void pop (const std::string &label, const std::string &header="")
 Pop the event label off the stack, resuming any lower event. More...
 
void start_event (const std::string &label, const std::string &header="")
 Start monitoring the event named label. More...
 
void stop_event (const std::string &label, const std::string &header="")
 Stop monitoring the event named label. More...
 
void pause_event (const std::string &label, const std::string &header="")
 Suspend monitoring of the event. More...
 
void restart_event (const std::string &label, const std::string &header="")
 Restart monitoring the event. More...
 
std::string get_log () const
 
std::string get_info_header () const
 
std::string get_perf_info () const
 
void print_log () const
 Print the log. More...
 
double get_elapsed_time () const
 
double get_active_time () const
 
PerfData get_perf_data (const std::string &label, const std::string &header="")
 Return the PerfData object associated with a label and header. More...
 
const log_typeget_log_raw () const
 

Private Member Functions

void split_on_whitespace (const std::string &input, std::vector< std::string > &output) const
 Splits a string on whitespace into a vector of separate strings. More...
 

Private Attributes

const std::string label_name
 The label for this object. More...
 
bool log_events
 Flag to optionally disable all logging. More...
 
double total_time
 The total running time for recorded events. More...
 
struct timeval tstart
 The time we were constructed or last cleared. More...
 
log_type log
 The actual log. More...
 
std::stack< PerfData * > log_stack
 A stack to hold the current performance log trace. More...
 
std::map< std::string, const char * > non_temporary_strings
 Workaround to give us fixed pointers to character arrays for every string. More...
 

Static Private Attributes

static bool called = false
 Flag indicating if print_log() has been called. More...
 

Detailed Description

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 Responsible for timing and summarizing events.

Definition at line 125 of file perf_log.h.

Member Typedef Documentation

typedef std::map<std::pair<const char *, const char *>, PerfData> libMesh::PerfLog::log_type

Typdef for the underlying logging data structure.

Definition at line 295 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 52 of file perf_log.C.

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

53  :
54  label_name(ln),
55  log_events(le),
56  total_time(0.)
57 {
58  gettimeofday (&tstart, libmesh_nullptr);
59 
60  if (log_events)
61  this->clear();
62 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
double total_time
The total running time for recorded events.
Definition: perf_log.h:328
const class libmesh_nullptr_t libmesh_nullptr
const std::string label_name
The label for this object.
Definition: perf_log.h:318
void clear()
Clears all the internal data and restores the data structures to a pristine state.
Definition: perf_log.C:77
struct timeval tstart
The time we were constructed or last cleared.
Definition: perf_log.h:333
libMesh::PerfLog::~PerfLog ( )

Destructor.

Calls clear() and print_log().

Definition at line 66 of file perf_log.C.

References log_events, non_temporary_strings, and print_log().

67 {
68  if (log_events)
69  this->print_log();
70 
71  for (const auto & pos : non_temporary_strings)
72  delete [] pos.second;
73 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
void print_log() const
Print the log.
Definition: perf_log.C:684
std::map< std::string, const char * > non_temporary_strings
Workaround to give us fixed pointers to character arrays for every string.
Definition: perf_log.h:371

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 77 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().

78 {
79  if (log_events)
80  {
81  // check that all events are closed
82  for (auto pos : log)
83  if (pos.second.open)
84  libmesh_error_msg("ERROR clearing performance log for class " \
85  << label_name \
86  << "\nevent " \
87  << pos.first.second \
88  << " is still being monitored!");
89 
90  gettimeofday (&tstart, libmesh_nullptr);
91 
92  log.clear();
93 
94  while (!log_stack.empty())
95  log_stack.pop();
96  }
97 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
const class libmesh_nullptr_t libmesh_nullptr
log_type log
The actual log.
Definition: perf_log.h:342
std::stack< PerfData * > log_stack
A stack to hold the current performance log trace.
Definition: perf_log.h:347
const std::string label_name
The label for this object.
Definition: perf_log.h:318
struct timeval tstart
The time we were constructed or last cleared.
Definition: perf_log.h:333
void libMesh::PerfLog::disable_logging ( )

Disables performance logging for an active object.

Definition at line 156 of file perf_log.h.

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

156 { log_events = false; }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
void libMesh::PerfLog::enable_logging ( )

Enables performance logging for an active object.

Definition at line 161 of file perf_log.h.

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

161 { log_events = true; }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
void libMesh::PerfLog::fast_pop ( const char *  label,
const char *  header = "" 
)

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

This method must be passed the exact same pointers as were passed to fast_push, not merely pointers to identical strings.

Definition at line 486 of file perf_log.h.

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

Referenced by pop(), and libMesh::PerfItem::~PerfItem().

488 {
489  if (this->log_events)
490  {
491  libmesh_assert (!log_stack.empty());
492 
493 #ifndef NDEBUG
494  PerfData * perf_data = &(log[std::make_pair(header,label)]);
495  if (perf_data != log_stack.top())
496  {
497  libMesh::err << "PerfLog can't pop (" << header << ',' << label << ')' << std::endl;
498  libMesh::err << "From top of stack of running logs:" << std::endl;
499  for (auto i : log)
500  if (&(i.second) == log_stack.top())
501  libMesh::err << '(' << i.first.first << ',' << i.first.second << ')' << std::endl;
502 
503  libmesh_assert_equal_to (perf_data, log_stack.top());
504  }
505 #endif
506 
507  total_time += log_stack.top()->stopit();
508 
509  log_stack.pop();
510 
511  if (!log_stack.empty())
512  log_stack.top()->restart();
513  }
514 }
OStreamProxy err
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
double total_time
The total running time for recorded events.
Definition: perf_log.h:328
log_type log
The actual log.
Definition: perf_log.h:342
libmesh_assert(j)
std::stack< PerfData * > log_stack
A stack to hold the current performance log trace.
Definition: perf_log.h:347
void libMesh::PerfLog::fast_push ( const char *  label,
const char *  header = "" 
)

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

Note - for speed the PerfLog directly considers the pointers here. Supply pointers to string literals or other character arrays whose lifetime will exceed the lifetime of the PerfLog object, not to temporarily allocated arrays.

Definition at line 466 of file perf_log.h.

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

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

468 {
469  if (this->log_events)
470  {
471  // Get a reference to the event data to avoid
472  // repeated map lookups
473  PerfData * perf_data = &(log[std::make_pair(header,label)]);
474 
475  if (!log_stack.empty())
476  total_time += log_stack.top()->pause_for(*perf_data);
477  else
478  perf_data->start();
479  log_stack.push(perf_data);
480  }
481 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
double total_time
The total running time for recorded events.
Definition: perf_log.h:328
log_type log
The actual log.
Definition: perf_log.h:342
std::stack< PerfData * > log_stack
A stack to hold the current performance log trace.
Definition: perf_log.h:347
double libMesh::PerfLog::get_active_time ( ) const
Returns
The active time

Definition at line 531 of file perf_log.h.

532 {
533  return total_time;
534 }
double total_time
The total running time for recorded events.
Definition: perf_log.h:328
double libMesh::PerfLog::get_elapsed_time ( ) const
Returns
The total time spent on this event.

Definition at line 519 of file perf_log.h.

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

520 {
521  struct timeval tnow;
522 
523  gettimeofday (&tnow, libmesh_nullptr);
524 
525  const double elapsed_time = (static_cast<double>(tnow.tv_sec - tstart.tv_sec) +
526  static_cast<double>(tnow.tv_usec - tstart.tv_usec)*1.e-6);
527  return elapsed_time;
528 }
const class libmesh_nullptr_t libmesh_nullptr
struct timeval tstart
The time we were constructed or last cleared.
Definition: perf_log.h:333
std::string libMesh::PerfLog::get_info_header ( ) const
Returns
A string containing ONLY the information header.

Definition at line 170 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().

171 {
172  std::ostringstream oss;
173 
174  if (log_events)
175  {
176  std::string date = Utility::get_timestamp();
177 
178 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
179  // Get system information
180  struct utsname sysInfo;
181  uname(&sysInfo);
182 #endif
183 
184  // Get user information
185  //
186  // Some systems, for example Crays, actually have getpwuid on the head-node
187  // but (if I understand correctly) a dynamically-linked glibc is not available
188  // on the backend, which is running a reduced operating system like Compute
189  // Node Linux. Thus functions like getpwuid cannot be called. This makes
190  // automatically testing for the existence of getpwuid on the login node
191  // difficult. The configure test would work on the login node but will fail
192  // on the backend. Hence we have added a configure flag, --disable-getpwuid,
193  // to manually turn this off.
194 #ifdef LIBMESH_HAVE_GETPWUID
195  struct passwd * p = getpwuid(getuid());
196 #endif
197  oss << "\n";
198 
199  // Construct string stream objects for each of the outputs
200  std::ostringstream
201  pid_stream,
202  nprocs_stream,
203  time_stream,
204  os_stream,
205  host_stream,
206  osrel_stream,
207  osver_stream,
208  machine_stream,
209  user_stream;
210 
211 
212  // Put pointers to these streams in a vector
213  std::vector<std::ostringstream*> v;
214  v.push_back(&pid_stream);
215  v.push_back(&nprocs_stream);
216  v.push_back(&time_stream);
217  v.push_back(&os_stream);
218  v.push_back(&host_stream);
219  v.push_back(&osrel_stream);
220  v.push_back(&osver_stream);
221  v.push_back(&machine_stream);
222  v.push_back(&user_stream);
223 
224  // Fill string stream objects
226  {
227  pid_stream << "| Processor id: " << libMesh::global_processor_id();
228  nprocs_stream << "| Num Processors: " << libMesh::global_n_processors();
229  }
230 
231  time_stream << "| Time: ";
232  os_stream << "| OS: ";
233  host_stream << "| HostName: ";
234  osrel_stream << "| OS Release: ";
235  osver_stream << "| OS Version: ";
236  machine_stream << "| Machine: ";
237 
238  time_stream << date;
239 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
240  os_stream << sysInfo.sysname ;
241  host_stream << sysInfo.nodename ;
242  osrel_stream << sysInfo.release ;
243  osver_stream << sysInfo.version ;
244  machine_stream << sysInfo.machine ;
245 #else
246  os_stream << "Unknown";
247  host_stream << "Unknown";
248  osrel_stream << "Unknown";
249  osver_stream << "Unknown";
250  machine_stream << "Unknown";
251 
252 #endif
253  user_stream << "| Username: ";
254 #ifdef LIBMESH_HAVE_GETPWUID
255  if (p && p->pw_name)
256  user_stream << p->pw_name;
257  else
258 #endif
259  user_stream << "Unknown";
260 
261  // Parse the LIBMESH_CONFIGURE_INFO string literal before using it in PerfLog output
262  std::string libmesh_configure_info(LIBMESH_CONFIGURE_INFO);
263  std::vector<std::string> parsed_libmesh_configure_info;
264  this->split_on_whitespace(libmesh_configure_info,
265  parsed_libmesh_configure_info);
266 
267  // There should always be at at least one entry in
268  // parsed_libmesh_configure_info, even if the user just ran
269  // ../configure.
270  libmesh_assert_greater (parsed_libmesh_configure_info.size(), 0);
271 
272  // Find the longest string in all the streams
273  unsigned int max_length = 0;
274  for (std::size_t i=0; i<v.size(); ++i)
275  if (v[i]->str().size() > max_length)
276  max_length = cast_int<unsigned int>
277  (v[i]->str().size());
278 
279  // Find the longest string in the parsed_libmesh_configure_info
280  for (std::size_t i=0; i<parsed_libmesh_configure_info.size(); ++i)
281  if (parsed_libmesh_configure_info[i].size() > max_length)
282  max_length = cast_int<unsigned int>
283  (parsed_libmesh_configure_info[i].size());
284 
285  // Print dashed line for the header
286  oss << ' '
287  << std::string(max_length+1, '-')
288  << '\n';
289 
290  // Loop over all the strings and add end formatting
291  for (std::size_t i=0; i<v.size(); ++i)
292  {
293  if (v[i]->str().size())
294  oss << v[i]->str()
295  << std::setw (cast_int<int>
296  (max_length + 4 - v[i]->str().size()))
297  << std::right
298  << "|\n";
299  }
300 
301  // Print out configuration header plus first parsed string. The
302  // magic number 18 below accounts for the length of the word
303  // 'Configuration'.
304  oss << "| Configuration: "
305  << parsed_libmesh_configure_info[0]
306  << std::setw (cast_int<int>
307  (max_length + 4 -
308  parsed_libmesh_configure_info[0].size() - 18))
309  << std::right
310  << "|\n";
311 
312  // Loop over the parsed_libmesh_configure_info and add end formatting. The magic
313  // number 3 below accounts for the leading 'pipe' character and indentation
314  for (std::size_t i=1; i<parsed_libmesh_configure_info.size(); ++i)
315  {
316  oss << "| "
317  << parsed_libmesh_configure_info[i]
318  << std::setw (cast_int<int>
319  (max_length + 4 -
320  parsed_libmesh_configure_info[i].size() - 3))
321  << std::right
322  << "|\n";
323  }
324 
325 
326  // Print dashed line
327  oss << ' '
328  << std::string(max_length+1, '-')
329  << '\n';
330  }
331 
332  return oss.str();
333 }
processor_id_type global_n_processors()
Definition: libmesh_base.h:104
std::string get_timestamp()
Definition: timestamp.C:37
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
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
Splits a string on whitespace into a vector of separate strings.
Definition: perf_log.C:749
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 658 of file perf_log.C.

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

Referenced by print_log().

659 {
660  std::ostringstream oss;
661 
662  if (log_events)
663  {
664  // Only print the log
665  // if it isn't empty
666  if (!log.empty())
667  {
668  // Possibly print machine info,
669  // but only do this once
670  if (!called)
671  {
672  called = true;
673  oss << get_info_header();
674  }
675  oss << get_perf_info();
676  }
677  }
678 
679  return oss.str();
680 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
log_type log
The actual log.
Definition: perf_log.h:342
std::string get_perf_info() const
Definition: perf_log.C:338
std::string get_info_header() const
Definition: perf_log.C:170
static bool called
Flag indicating if print_log() has been called.
Definition: perf_log.h:354
const log_type& libMesh::PerfLog::get_log_raw ( ) const
Returns
the raw underlying data structure for the entire performance log.
Deprecated:
because encapsulation is good.

Also probably broken by the switch from string to const char *, though users who are liberal with "auto" might be safe.

Definition at line 305 of file perf_log.h.

306  {
307  libmesh_deprecated();
308  return log;
309  }
log_type log
The actual log.
Definition: perf_log.h:342
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 696 of file perf_log.C.

References libMesh::libmesh_assert(), log, and non_temporary_strings.

697 {
698  if (non_temporary_strings.count(label) &&
699  non_temporary_strings.count(header))
700  {
701  const char * label_c_str = non_temporary_strings[label];
702  const char * header_c_str = non_temporary_strings[header];
703  return log[std::make_pair(header_c_str, label_c_str)];
704  }
705 
706  auto iter = std::find_if
707  (log.begin(), log.end(),
708  [&label, &header] (log_type::const_reference a)
709  { return !std::strcmp(header.c_str(), a.first.first) &&
710  !std::strcmp(label.c_str(), a.first.second); });
711 
712  libmesh_assert(iter != log.end());
713 
714  return iter->second;
715 }
log_type log
The actual log.
Definition: perf_log.h:342
libmesh_assert(j)
std::map< std::string, const char * > non_temporary_strings
Workaround to give us fixed pointers to character arrays for every string.
Definition: perf_log.h:371
std::string libMesh::PerfLog::get_perf_info ( ) const
Returns
A string containing ONLY the log information

Definition at line 338 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().

339 {
340  std::ostringstream oss;
341 
342  if (log_events && !log.empty())
343  {
344  // Stop timing for this event.
345  struct timeval tstop;
346 
347  gettimeofday (&tstop, libmesh_nullptr);
348 
349  const double elapsed_time = (static_cast<double>(tstop.tv_sec - tstart.tv_sec) +
350  static_cast<double>(tstop.tv_usec - tstart.tv_usec)*1.e-6);
351 
352  // Figure out the formatting required based on the event names
353  // Unsigned ints for each of the column widths
354  unsigned int event_col_width = 30;
355  const unsigned int ncalls_col_width = 11;
356  const unsigned int tot_time_col_width = 12;
357  const unsigned int avg_time_col_width = 12;
358  const unsigned int tot_time_incl_sub_col_width = 12;
359  const unsigned int avg_time_incl_sub_col_width = 12;
360  const unsigned int pct_active_col_width = 9;
361  const unsigned int pct_active_incl_sub_col_width = 9;
362 
363  // Reset the event column width based on the longest event name plus
364  // a possible 2-character indentation, plus a space.
365  for (auto pos : log)
366  if (std::strlen(pos.first.second)+3 > event_col_width)
367  event_col_width = cast_int<unsigned int>
368  (std::strlen(pos.first.second)+3);
369 
370  // Set the total width of the column
371  const unsigned int total_col_width =
372  event_col_width +
373  ncalls_col_width +
374  tot_time_col_width +
375  avg_time_col_width +
376  tot_time_incl_sub_col_width +
377  avg_time_incl_sub_col_width +
378  pct_active_col_width+
379  pct_active_incl_sub_col_width+1;
380 
381  // Print dashed line
382  oss << ' '
383  << std::string(total_col_width, '-')
384  << '\n';
385 
386  {
387  // Construct temporary message string
388  std::ostringstream temp;
389  temp << "| " << label_name << " Performance: Alive time=" << elapsed_time
390  << ", Active time=" << total_time;
391 
392  // Get the size of the temporary string
393  const unsigned int temp_size = cast_int<unsigned int>
394  (temp.str().size());
395 
396  // Send the temporary message to the output
397  oss << temp.str();
398 
399  // If this string is longer than the previously computed total
400  // column width, skip the additional formatting... this shouldn't
401  // happen often, hopefully. Add two additional characters for a
402  // space and a "|" character at the end.
403  if (temp_size < total_col_width+2)
404  oss << std::setw(total_col_width - temp_size + 2)
405  << std::right
406  << "|";
407 
408  oss << '\n';
409  }
410 
411  // Print dashed line
412  oss << ' '
413  << std::string(total_col_width, '-')
414  << '\n';
415 
416 
417  // Write out the header for the events listing
418  oss << "| "
419  << std::setw(event_col_width)
420  << std::left
421  << "Event"
422  << std::setw(ncalls_col_width)
423  << std::left
424  << "nCalls"
425  << std::setw(tot_time_col_width)
426  << std::left
427  << "Total Time"
428  << std::setw(avg_time_col_width)
429  << std::left
430  << "Avg Time"
431  << std::setw(tot_time_incl_sub_col_width)
432  << std::left
433  << "Total Time"
434  << std::setw(avg_time_incl_sub_col_width)
435  << std::left
436  << "Avg Time"
437  << std::setw(pct_active_col_width+pct_active_incl_sub_col_width)
438  << std::left
439  << "% of Active Time"
440  << "|\n"
441  << "| "
442  << std::setw(event_col_width)
443  << std::left
444  << ""
445  << std::setw(ncalls_col_width)
446  << std::left
447  << ""
448  << std::setw(tot_time_col_width)
449  << std::left
450  << "w/o Sub"
451  << std::setw(avg_time_col_width)
452  << std::left
453  << "w/o Sub"
454  << std::setw(tot_time_incl_sub_col_width)
455  << std::left
456  << "With Sub"
457  << std::setw(avg_time_incl_sub_col_width)
458  << std::left
459  << "With Sub"
460  << std::setw(pct_active_col_width)
461  << std::left
462  << "w/o S"
463  << std::setw(pct_active_incl_sub_col_width)
464  << std::left
465  << "With S"
466  << "|\n|"
467  << std::string(total_col_width, '-')
468  << "|\n|"
469  << std::string(total_col_width, ' ')
470  << "|\n";
471 
472  unsigned int summed_function_calls = 0;
473  double summed_total_time = 0;
474  double summed_percentage = 0;
475 
476  std::string last_header("");
477 
478  // Make a new log to sort entries alphabetically
479  std::map<std::pair<std::string, std::string>, PerfData> string_log;
480 
481  for (auto char_data : log)
482  string_log[std::make_pair(char_data.first.first,
483  char_data.first.second)] =
484  char_data.second;
485 
486  for (auto pos : string_log)
487  {
488  const PerfData & perf_data = pos.second;
489 
490  // Only print the event if the count is non-zero.
491  if (perf_data.count != 0)
492  {
493  const unsigned int perf_count = perf_data.count;
494  const double perf_time = perf_data.tot_time;
495  const double perf_avg_time = perf_time / static_cast<double>(perf_count);
496  const double perf_time_incl_sub = perf_data.tot_time_incl_sub;
497  const double perf_avg_time_incl_sub = perf_time_incl_sub / static_cast<double>(perf_count);
498  const double perf_percent = (total_time != 0.) ? perf_time / total_time * 100. : 0.;
499  const double perf_percent_incl_sub = (total_time != 0.) ? perf_time_incl_sub / total_time * 100. : 0.;
500 
501  summed_function_calls += perf_count;
502  summed_total_time += perf_time;
503  summed_percentage += perf_percent;
504 
505  // Print the event name
506  if (pos.first.first == "")
507  oss << "| "
508  << std::setw(event_col_width)
509  << std::left
510  << pos.first.second;
511 
512  else
513  {
514  if (last_header != pos.first.first)
515  {
516  last_header = pos.first.first;
517 
518  // print blank line followed by header name
519  // (account for additional space before the
520  // header)
521  oss << "|"
522  << std::string(total_col_width, ' ')
523  << "|\n| "
524  << std::setw(total_col_width-1)
525  << std::left
526  << pos.first.first
527  << "|\n";
528  }
529 
530  oss << "| "
531  << std::setw(event_col_width-2)
532  << std::left
533  << pos.first.second;
534  }
535 
536 
537  // Print the number of calls to the event.
538  oss << std::setw(ncalls_col_width)
539  << perf_count;
540 
541  // Save the original stream flags
542  std::ios_base::fmtflags out_flags = oss.flags();
543 
544  // Print the total time spent in the event
545  oss << std::fixed
546  << std::setprecision(4)
547  << std::setw(tot_time_col_width)
548  << std::left
549  << perf_time;
550 
551 
552  // Print the average time per function call
553  oss << std::fixed
554  << std::setprecision(6)
555  << std::setw(avg_time_col_width)
556  << std::left
557  << perf_avg_time;
558 
559  // Print the total time spent in the event incl. sub-events
560  oss << std::fixed
561  << std::setprecision(4)
562  << std::setw(tot_time_incl_sub_col_width)
563  << std::left
564  << perf_time_incl_sub;
565 
566  // Print the average time per function call incl. sub-events
567  oss << std::fixed
568  << std::setprecision(6)
569  << std::setw(avg_time_incl_sub_col_width)
570  << std::left
571  << perf_avg_time_incl_sub;
572 
573  // Print the percentage of the time spent in the event
574  oss << std::fixed
575  << std::setprecision(2)
576  << std::setw(pct_active_col_width)
577  << std::left
578  << perf_percent;
579 
580  // Print the percentage of the time spent in the event incl. sub-events
581  oss << std::fixed
582  << std::setprecision(2)
583  << std::setw(pct_active_incl_sub_col_width)
584  << std::left
585  << perf_percent_incl_sub;
586 
587  // Reset the stream flags
588  oss.flags(out_flags);
589 
590  oss << "|\n";
591  }
592  }
593 
594  oss << ' '
595  << std::string(total_col_width, '-')
596  << "\n| "
597  << std::setw(event_col_width)
598  << std::left
599  << "Totals:";
600 
601  // Print the total number of logged function calls
602  // For routines which are called many times, summed_function_calls may
603  // exceed 7 digits. If this happens use, scientific notation.
604  if (summed_function_calls < 9999999)
605  oss << std::setw(ncalls_col_width)
606  << summed_function_calls;
607 
608  else
609  {
610  // Save the original stream flags
611  std::ios_base::fmtflags out_flags = oss.flags();
612 
613  oss << std::scientific
614  << std::setprecision(3)
615  << std::setw(ncalls_col_width)
616  << std::left
617  << static_cast<Real>(summed_function_calls);
618 
619  // Reset the stream flags
620  oss.flags(out_flags);
621  }
622 
623  // Print the total time spent in logged function calls. Don't bother saving/restoring
624  // the flags here since we are almost done with this stream anyway...
625  oss << std::fixed
626  << std::setprecision(4)
627  << std::setw(tot_time_col_width)
628  << std::left
629  << summed_total_time;
630 
631  // Null, the average time doesn't make sense as a total
632  oss << std::setw(avg_time_col_width) << "";
633 
634  // Same for times that include sub-events
635  oss << std::setw(tot_time_incl_sub_col_width)
636  << ""
637  << std::setw(avg_time_incl_sub_col_width)
638  << "";
639 
640  // Print the total percentage followed by dashed line
641  oss << std::fixed
642  << std::setprecision(2)
643  << std::setw(pct_active_col_width)
644  << std::left
645  << summed_percentage
646  << std::setw(pct_active_incl_sub_col_width)
647  << ""
648  << "|\n "
649  << std::string(total_col_width, '-')
650  << '\n';
651  }
652 
653  return oss.str();
654 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
double total_time
The total running time for recorded events.
Definition: perf_log.h:328
const class libmesh_nullptr_t libmesh_nullptr
log_type log
The actual log.
Definition: perf_log.h:342
const std::string label_name
The label for this object.
Definition: perf_log.h:318
DIE A HORRIBLE DEATH HERE typedef LIBMESH_DEFAULT_SCALAR_TYPE Real
struct timeval tstart
The time we were constructed or last cleared.
Definition: perf_log.h:333
bool libMesh::PerfLog::logging_enabled ( ) const
Returns
true iff performance logging is enabled

Definition at line 166 of file perf_log.h.

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

166 { return log_events; }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
void libMesh::PerfLog::pause_event ( const std::string &  label,
const std::string &  header = "" 
)

Suspend monitoring of the event.

Definition at line 733 of file perf_log.C.

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

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

This method will eventually be deprecated. Use fast_pop() (with the exact same pointers supplied to fast_push()) instead.

Definition at line 162 of file perf_log.C.

Referenced by assemble_biharmonic(), assemble_laplace(), assemble_poisson(), main(), and stop_event().

164 {
165  this->pop(std::string(label), std::string(header));
166 }
void pop(const char *label, const char *header="")
Pop the event label off the stack, resuming any lower event.
Definition: perf_log.C:162
void libMesh::PerfLog::pop ( const std::string &  label,
const std::string &  header = "" 
)

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

This method will eventually be deprecated. String manipulation is too low performance to use when performance monitoring hot spots. Use fast_pop() instead.

Definition at line 142 of file perf_log.C.

References fast_pop(), libMesh::libmesh_assert(), log_events, and non_temporary_strings.

144 {
145 
146  const char * label_c_str = non_temporary_strings[label];
147  const char * header_c_str = non_temporary_strings[header];
148 
149  // This could happen if users are *mixing* string and char* APIs for
150  // the same label/header combination. For perfect backwards
151  // compatibility we should handle that, but there's just no fast way
152  // to do so.
153  libmesh_assert(label_c_str);
154  libmesh_assert(header_c_str);
155 
156  if (this->log_events)
157  this->fast_pop(label_c_str, header_c_str);
158 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
libmesh_assert(j)
void fast_pop(const char *label, const char *header="")
Pop the event label off the stack, resuming any lower event.
Definition: perf_log.h:486
std::map< std::string, const char * > non_temporary_strings
Workaround to give us fixed pointers to character arrays for every string.
Definition: perf_log.h:371
void libMesh::PerfLog::print_log ( ) const

Print the log.

Definition at line 684 of file perf_log.C.

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

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

685 {
686  if (log_events)
687  {
688  // Check to see if the log_string is empty, and if so,
689  // avoid printing an unnecessary newline.
690  std::string log_string = this->get_log();
691  if (log_string.size() > 0)
692  libMesh::out << log_string << std::endl;
693  }
694 }
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
OStreamProxy out
std::string get_log() const
Definition: perf_log.C:658
void libMesh::PerfLog::push ( const char *  label,
const char *  header = "" 
)

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

This method will eventually be deprecated. For backwards compatibility, the PerfLog must copy the contents of these character arrays into strings, which ironically damages the performance we are trying to profile. Use fast_push() (with compatible long-lived character array data) instead.

Definition at line 132 of file perf_log.C.

Referenced by assemble_biharmonic(), assemble_laplace(), assemble_poisson(), main(), and start_event().

134 {
135  this->push(std::string(label), std::string(header));
136 }
void push(const char *label, const char *header="")
Push the event label onto the stack, pausing any active event.
Definition: perf_log.C:132
void libMesh::PerfLog::push ( const std::string &  label,
const std::string &  header = "" 
)

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

This method will eventually be deprecated. String manipulation is too low performance to use when performance monitoring hot spots. Use fast_push() instead.

Definition at line 101 of file perf_log.C.

References fast_push(), log_events, and non_temporary_strings.

103 {
104  const char * label_c_str;
105  const char * header_c_str;
106  if (non_temporary_strings.count(label))
107  label_c_str = non_temporary_strings[label];
108  else
109  {
110  char * newcopy = new char [label.size()+1];
111  strcpy(newcopy, label.c_str());
112  label_c_str = newcopy;
113  non_temporary_strings[label] = label_c_str;
114  }
115 
116  if (non_temporary_strings.count(header))
117  header_c_str = non_temporary_strings[header];
118  else
119  {
120  char * newcopy = new char [header.size()+1];
121  strcpy(newcopy, header.c_str());
122  header_c_str = newcopy;
123  non_temporary_strings[header] = header_c_str;
124  }
125 
126  if (this->log_events)
127  this->fast_push(label_c_str, header_c_str);
128 }
void fast_push(const char *label, const char *header="")
Push the event label onto the stack, pausing any active event.
Definition: perf_log.h:466
bool log_events
Flag to optionally disable all logging.
Definition: perf_log.h:323
std::map< std::string, const char * > non_temporary_strings
Workaround to give us fixed pointers to character arrays for every string.
Definition: perf_log.h:371
void libMesh::PerfLog::restart_event ( const std::string &  label,
const std::string &  header = "" 
)

Restart monitoring the event.

Definition at line 741 of file perf_log.C.

743 {
744  // nothing to do. popping the top off the stack will handle it.
745 }
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 749 of file perf_log.C.

Referenced by get_info_header().

750 {
751  // Check for easy return
752  if (input.size()==0)
753  return;
754 
755  // Here we hard-code the string to split on, since the algorithm below
756  // is somewhat specific to it...
757  const std::string split_on("' '");
758 
759  size_t current_pos = 0;
760  while (true)
761  {
762  // Find next end location
763  size_t end_pos = input.find(split_on, current_pos);
764 
765  if (end_pos != std::string::npos)
766  {
767  // Create substring. Note: the second argument to substr is
768  // the *length* of string to create, not the ending position!
769  output.push_back( input.substr(current_pos, end_pos - current_pos + 1) );
770 
771  // Update search starting position, make sure to go past the end of the split_on string, but
772  // include the previous single quote (hence the -1).
773  current_pos = end_pos + split_on.size() - 1;
774  }
775  else
776  {
777  // Push back whatever remains of the string onto the output.
778  // Note that substr with only 1 argument pushes back
779  // whatever remains of the string. This also handles the
780  // case where the string does not contain any matches.
781  output.push_back( input.substr(current_pos) );
782 
783  // We are done searching the string, so break out of the while loop
784  break;
785  }
786  }
787 }
void libMesh::PerfLog::start_event ( const std::string &  label,
const std::string &  header = "" 
)

Start monitoring the event named label.

Definition at line 717 of file perf_log.C.

References push().

719 {
720  this->push(label,header);
721 }
void push(const char *label, const char *header="")
Push the event label onto the stack, pausing any active event.
Definition: perf_log.C:132
void libMesh::PerfLog::stop_event ( const std::string &  label,
const std::string &  header = "" 
)

Stop monitoring the event named label.

Definition at line 725 of file perf_log.C.

References pop().

727 {
728  this->pop(label,header);
729 }
void pop(const char *label, const char *header="")
Pop the event label off the stack, resuming any lower event.
Definition: perf_log.C:162

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 354 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 318 of file perf_log.h.

Referenced by clear(), and get_perf_info().

log_type libMesh::PerfLog::log
private

The actual log.

An unsorted_map would work fine here and would be asymptotically faster, but in my tests for our log sizes there was no improvement.

Definition at line 342 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 323 of file perf_log.h.

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

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

A stack to hold the current performance log trace.

Definition at line 347 of file perf_log.h.

Referenced by clear().

std::map<std::string, const char *> libMesh::PerfLog::non_temporary_strings
private

Workaround to give us fixed pointers to character arrays for every string.

Using std::set instead might work: it won't invalidate iterators, which I think means it doesn't have any reason to modify or copy their contents or otherwise invalidate their c_str() pointers... but I can't prove it from the standards doc, so let's be safe.

Definition at line 371 of file perf_log.h.

Referenced by get_perf_data(), pop(), push(), and ~PerfLog().

double libMesh::PerfLog::total_time
private

The total running time for recorded events.

Definition at line 328 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 333 of file perf_log.h.

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


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