perf_log.h
Go to the documentation of this file.
1 // The libMesh Finite Element Library.
2 // Copyright (C) 2002-2018 Benjamin S. Kirk, John W. Peterson, Roy H. Stogner
3 
4 // This library is free software; you can redistribute it and/or
5 // modify it under the terms of the GNU Lesser General Public
6 // License as published by the Free Software Foundation; either
7 // version 2.1 of the License, or (at your option) any later version.
8 
9 // This library is distributed in the hope that it will be useful,
10 // but WITHOUT ANY WARRANTY; without even the implied warranty of
11 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
12 // Lesser General Public License for more details.
13 
14 // You should have received a copy of the GNU Lesser General Public
15 // License along with this library; if not, write to the Free Software
16 // Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
17 
18 
19 
20 #ifndef LIBMESH_PERFLOG_H
21 #define LIBMESH_PERFLOG_H
22 
23 
24 // Local includes
25 #include "libmesh/libmesh_common.h"
26 
27 // C++ includes
28 #include <cstddef>
29 #include <map>
30 #include <stack>
31 #include <string>
32 #include <vector>
33 #include <sys/time.h>
34 
35 namespace libMesh
36 {
37 
46 class PerfData
47 {
48 public:
49 
53  PerfData () :
54  tot_time(0.),
56  tstart(),
58  count(0),
59  open(false),
61  {}
62 
63 
67  double tot_time;
68 
73 
78  struct timeval tstart;
79 
84  struct timeval tstart_incl_sub;
85 
90  unsigned int count;
91 
97  bool open;
98 
99  void start ();
100  void restart ();
101  double pause ();
102  double pause_for(PerfData & other);
103  double stopit ();
104 
106 
107 protected:
108  double stop_or_pause(const bool do_stop);
109 };
110 
111 
112 
113 
125 class PerfLog
126 {
127 public:
128 
136  PerfLog(const std::string & label_name="",
137  const bool log_events=true);
138 
142  ~PerfLog();
143 
151  void clear();
152 
156  void disable_logging() { log_events = false; }
157 
161  void enable_logging() { log_events = true; }
162 
166  bool logging_enabled() const { return log_events; }
167 
176  void fast_push (const char * label,
177  const char * header="");
178 
188  void push (const char * label,
189  const char * header="");
190 
198  void push (const std::string & label,
199  const std::string & header="");
200 
207  void fast_pop (const char * label,
208  const char * header="");
209 
216  void pop (const char * label,
217  const char * header="");
218 
226  void pop (const std::string & label,
227  const std::string & header="");
228 
232  void start_event(const std::string & label,
233  const std::string & header="");
234 
238  void stop_event(const std::string & label,
239  const std::string & header="");
240 
244  void pause_event(const std::string & label,
245  const std::string & header="");
246 
250  void restart_event(const std::string & label,
251  const std::string & header="");
252 
258  std::string get_log() const;
259 
263  std::string get_info_header() const;
264 
268  std::string get_perf_info() const;
269 
273  void print_log() const;
274 
278  double get_elapsed_time() const;
279 
283  double get_active_time() const;
284 
288  PerfData get_perf_data(const std::string & label, const std::string & header="");
289 
293  typedef std::map<std::pair<const char *,
294  const char *>,
304 #ifdef LIBMESH_ENABLE_DEPRECATED
305  const log_type & get_log_raw() const
306  {
307  libmesh_deprecated();
308  return log;
309  }
310 #endif
311 
312 private:
313 
314 
318  const std::string label_name;
319 
324 
328  double total_time;
329 
333  struct timeval tstart;
334 
343 
347  std::stack<PerfData*> log_stack;
348 
354  static bool called;
355 
360  void split_on_whitespace(const std::string & input,
361  std::vector<std::string> & output) const;
362 
371  std::map<std::string, const char *> non_temporary_strings;
372 };
373 
374 
375 
376 // ------------------------------------------------------------
377 // PerfData class member functions
378 inline
380 {
381  this->count++;
382  this->called_recursively++;
383  gettimeofday (&(this->tstart), nullptr);
384  this->tstart_incl_sub = this->tstart;
385 }
386 
387 
388 
389 inline
391 {
392  gettimeofday (&(this->tstart), nullptr);
393 }
394 
395 
396 
397 inline
399 {
400  return this->stop_or_pause(false);
401 }
402 
403 
404 inline
405 double PerfData::stop_or_pause(const bool do_stop)
406 {
407  // save the start times, reuse the structure we have rather than create
408  // a new one.
409  const time_t
410  tstart_tv_sec = this->tstart.tv_sec,
411  tstart_tv_usec = this->tstart.tv_usec;
412 
413  gettimeofday (&(this->tstart), nullptr);
414 
415  const double elapsed_time = (static_cast<double>(this->tstart.tv_sec - tstart_tv_sec) +
416  static_cast<double>(this->tstart.tv_usec - tstart_tv_usec)*1.e-6);
417 
418  this->tot_time += elapsed_time;
419 
420  if (do_stop)
421  {
422  const double elapsed_time_incl_sub = (static_cast<double>(this->tstart.tv_sec - this->tstart_incl_sub.tv_sec) +
423  static_cast<double>(this->tstart.tv_usec - this->tstart_incl_sub.tv_usec)*1.e-6);
424 
425  this->tot_time_incl_sub += elapsed_time_incl_sub;
426  }
427 
428  return elapsed_time;
429 }
430 
431 
432 
433 inline
435 {
436  gettimeofday (&(other.tstart), nullptr);
437 
438  const double elapsed_time = (static_cast<double>(other.tstart.tv_sec - this->tstart.tv_sec) +
439  static_cast<double>(other.tstart.tv_usec - this->tstart.tv_usec)*1.e-6);
440  this->tot_time += elapsed_time;
441 
442  other.count++;
443  other.called_recursively++;
444  other.tstart_incl_sub = other.tstart;
445 
446  return elapsed_time;
447 }
448 
449 
450 
451 inline
453 {
454  // stopit is just similar to pause except that it decrements the
455  // recursive call counter
456 
457  this->called_recursively--;
458  return this->stop_or_pause(true);
459 }
460 
461 
462 
463 // ------------------------------------------------------------
464 // PerfLog class inline member functions
465 inline
466 void PerfLog::fast_push (const char * label,
467  const char * header)
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 }
482 
483 
484 
485 inline
486 void PerfLog::fast_pop(const char * libmesh_dbg_var(label),
487  const char * libmesh_dbg_var(header))
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 }
515 
516 
517 
518 inline
520 {
521  struct timeval tnow;
522 
523  gettimeofday (&tnow, 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 }
529 
530 inline
532 {
533  return total_time;
534 }
535 
536 } // namespace libMesh
537 
538 
539 
540 #endif // LIBMESH_PERFLOG_H
double pause()
Definition: perf_log.h:398
double tot_time_incl_sub
Definition: perf_log.h:72
void pop(const char *label, const char *header="")
Definition: perf_log.C:162
int called_recursively
Definition: perf_log.h:105
double stopit()
Definition: perf_log.h:452
const log_type & get_log_raw() const
Definition: perf_log.h:305
void fast_push(const char *label, const char *header="")
Definition: perf_log.h:466
Data object managed by PerfLog.
Definition: perf_log.h:46
void enable_logging()
Definition: perf_log.h:161
double total_time
Definition: perf_log.h:328
double get_elapsed_time() const
Definition: perf_log.h:519
double pause_for(PerfData &other)
Definition: perf_log.h:434
PerfLog(const std::string &label_name="", const bool log_events=true)
Definition: perf_log.C:52
void stop_event(const std::string &label, const std::string &header="")
Definition: perf_log.C:728
log_type log
Definition: perf_log.h:342
std::stack< PerfData * > log_stack
Definition: perf_log.h:347
PerfData get_perf_data(const std::string &label, const std::string &header="")
Definition: perf_log.C:696
Responsible for timing and summarizing events.
Definition: perf_log.h:125
void fast_pop(const char *label, const char *header="")
Definition: perf_log.h:486
std::string get_perf_info() const
Definition: perf_log.C:338
const std::string label_name
Definition: perf_log.h:318
double stop_or_pause(const bool do_stop)
Definition: perf_log.h:405
double get_active_time() const
Definition: perf_log.h:531
std::map< std::pair< const char *, const char * >, PerfData > log_type
Definition: perf_log.h:295
std::string get_log() const
Definition: perf_log.C:658
std::string get_info_header() const
Definition: perf_log.C:170
void push(const char *label, const char *header="")
Definition: perf_log.C:132
void restart_event(const std::string &label, const std::string &header="")
Definition: perf_log.C:744
bool logging_enabled() const
Definition: perf_log.h:166
OStreamProxy err(std::cerr)
void split_on_whitespace(const std::string &input, std::vector< std::string > &output) const
Definition: perf_log.C:752
struct timeval tstart
Definition: perf_log.h:78
struct timeval tstart_incl_sub
Definition: perf_log.h:84
void clear()
Definition: perf_log.C:77
double tot_time
Definition: perf_log.h:67
void print_log() const
Definition: perf_log.C:684
void pause_event(const std::string &label, const std::string &header="")
Definition: perf_log.C:736
unsigned int count
Definition: perf_log.h:90
struct timeval tstart
Definition: perf_log.h:333
std::map< std::string, const char * > non_temporary_strings
Definition: perf_log.h:371
static bool called
Definition: perf_log.h:354
void disable_logging()
Definition: perf_log.h:156
void start_event(const std::string &label, const std::string &header="")
Definition: perf_log.C:720