Teuchos - Trilinos Tools Package  Version of the Day
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
Teuchos_StackedTimer.hpp
1 // @HEADER
2 // *****************************************************************************
3 // Teuchos: Common Tools Package
4 //
5 // Copyright 2004 NTESS and the Teuchos contributors.
6 // SPDX-License-Identifier: BSD-3-Clause
7 // *****************************************************************************
8 // @HEADER
9 
10 #ifndef TEUCHOS_STACKED_TIMER_HPP
11 #define TEUCHOS_STACKED_TIMER_HPP
12 
13 #include "Teuchos_ConfigDefs.hpp"
14 #include "Teuchos_Comm.hpp"
15 #include "Teuchos_DefaultComm.hpp"
16 #include "Teuchos_CommHelpers.hpp"
17 #include "Teuchos_RCP.hpp"
18 #include "Teuchos_Array.hpp"
20 #include <string>
21 #include <vector>
22 #include <cassert>
23 #include <chrono>
24 #include <climits>
25 #include <cstdlib> // for std::getenv and atoi
26 #include <ctime> // for timestamp support
27 #include <iostream>
28 
29 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
30 namespace Kokkos {
31 namespace Tools {
32 extern void pushRegion (const std::string&);
33 extern void popRegion ();
34 } // namespace Profiling
35 } // namespace Kokkos
36 #endif
37 
38 
39 namespace Teuchos {
40 
42 TEUCHOSCOMM_LIB_DLL_EXPORT void error_out(const std::string& msg, const bool fail_all = false);
43 
53 class BaseTimer {
54 
55 public:
56 
57  using Clock = std::chrono::high_resolution_clock;
58 
59  BaseTimer() : accumulation_(0.0), count_started_(0), count_updates_(0), running_(false) {}
60 
62  void start(){
63  if (running_)
64  error_out("Base_Timer:start Failed timer already running");
65  start_time_ = Clock::now();
66 
67  count_started_++;
68  running_ = true;
69  }
70 
72  void stop(){
73  if (!running_)
74  error_out("Base_Timer:stop Failed timer not running");
75  accumulation_ += std::chrono::duration_cast<std::chrono::duration<double>>(Clock::now() - start_time_).count();
76  running_ = false;
77  }
78 
80  unsigned long long incrementUpdates(unsigned long long count=1) {count_updates_ += count; return count_updates_;}
81 
83  double accumulatedTime() const {return accumulation_;}
84 
86  void setAccumulatedTime(double accum=0) {accumulation_=accum;}
87  double accumulatedTimePerUpdate() const {
97  if (count_updates_ > 0) {
98  return accumulation_/count_updates_;
99  } else {
100  return 0;
101  }
102  }
103 
104 
113  if (count_started_> 0) {
114  return accumulation_/count_started_;
115  } else {
116  return 0;
117  }
118  }
119 
126  double difference(const BaseTimer &from) const {
127  return accumulation_ - from.accumulation_;
128  }
129 
131  void reset() {
132  if (running_)
133  error_out("BaseTimer, cannot reset a running timer");
134  accumulation_ = 0.0;
135  count_started_ = count_updates_ = 0;
136  }
137 
139  bool running() const { return running_;}
140 
142  unsigned long numCalls() const { return count_started_; }
143 
145  unsigned long long numUpdates() const { return count_updates_; }
146 
148  void overrideNumCallsForUnitTesting(const unsigned long num_calls)
149  { count_started_ = num_calls; }
150 
152  void overrideNumUpdatesForUnitTesting(const unsigned long long num_updates)
153  { count_updates_ = num_updates; }
154 
155  struct TimeInfo {
156  TimeInfo():time(0.0), count(0), updates(0), running(false){}
157  TimeInfo(BaseTimer* t): time(t->accumulation_), count(t->count_started_), updates(t->count_updates_), running(t->running()) {}
158  double time;
159  unsigned long count;
160  unsigned long long updates;
161  bool running;
162  };
163 
164 protected:
165  double accumulation_; // total time
166  unsigned long count_started_; // Number of times this timer has been started
167  unsigned long long count_updates_; // Total count of items updated during this timer
168  Clock::time_point start_time_;
169  bool running_;
170 
171  friend struct TimeInfo;
172 };
173 
191 class TEUCHOSCOMM_LIB_DLL_EXPORT StackedTimer
192 {
193 protected:
194 
203  class LevelTimer : public BaseTimer {
204  protected:
205 
206  // TODO: implement operator=
207 
208  unsigned level_;
209  std::string name_;
210  LevelTimer *parent_;
211  std::vector<LevelTimer> sub_timers_;
212  public:
214  LevelTimer();
215 
223  LevelTimer(int level,
224  const char* name = "RootTimer",
225  LevelTimer *parent=nullptr,
226  bool start_timer=true) :
227  BaseTimer(),
228  level_(level),
229  name_(name),
230  parent_(parent)
231  {
232  if ( start_timer )
234 
235  }
236 
238  LevelTimer(const LevelTimer &src) :
239  BaseTimer(src), level_(src.level_), name_(src.name_),parent_(src.parent_), sub_timers_(src.sub_timers_)
240  {
241  for (unsigned i=0;i<sub_timers_.size();++i)
242  sub_timers_[i].parent_ = this;
243  }
244 
250  LevelTimer* start(const char* sub_name) {
251  for (unsigned i=0;i<sub_timers_.size();i++ )
252  if (sub_name == sub_timers_[i].name_ ) {
253  sub_timers_[i].BaseTimer::start();
254  return &sub_timers_[i];
255  }
256  sub_timers_.push_back(LevelTimer(level_+1,sub_name,this,true));
257  return &sub_timers_[sub_timers_.size()-1];
258  }
259 
267  LevelTimer* stop(const std::string &name = "RootTimer") {
268  if (name != name_)
269  error_out("Stopping timer "+name+" But top level running timer is "+name_);
270  BaseTimer::stop();
271  return parent_;
272  }
273 
274 
279  std::string get_full_name() const {
280  std::string parent_name("");
281  if ((parent_ != nullptr))
282  parent_name = parent_->get_full_name() + "@";
283 
284  std::string my_name(name_);
285 
286  std::string full_name = parent_name + my_name;
287  return full_name;
288  }
289 
295  int countTimers() {
296  int count=1;
297  for (unsigned i=0;i<sub_timers_.size(); ++i)
298  count += sub_timers_[i].countTimers();
299  return count;
300  }
301 
302  void addTimerNames(Array<std::string> &names, unsigned &pos) {
303  names[pos++] = get_full_name();
304  for (unsigned i=0;i<sub_timers_.size(); ++i)
305  sub_timers_[i].addTimerNames(names, pos);
306  }
307 
313  double accumulatedTime(const std::string &locate_name="") {
314 
315  if (locate_name == "")
317 
318  std::string first_name,second_name;
319 
320  size_t i = locate_name.find_first_of('@');
321  if ( i >= locate_name.size() ) {
322  first_name = locate_name;
323  second_name = "";
324  } else {
325  first_name.assign(locate_name,0,i);
326  second_name.assign(locate_name,i+1,locate_name.size()-i-1);
327  }
328  for (unsigned j=0;j<sub_timers_.size();++j)
329  if ( first_name == sub_timers_[j].name_)
330  return sub_timers_[j].accumulatedTime(second_name);
331  return 0;
332  }
333 
335  unsigned level() const
336  {return level_;}
337 
338  protected:
345  void splitString(const std::string &locate_name, std::string &first_name, std::string &second_name) {
346  size_t i = locate_name.find_first_of('@');
347  if ( i >= locate_name.size() ) {
348  first_name = locate_name;
349  second_name = "";
350  } else {
351  first_name.assign(locate_name,0,i);
352  second_name.assign(locate_name,i+1,locate_name.size()-i-1);
353  }
354  }
355 
356  public:
362  double accumulatedTimePerUpdate(const std::string &locate_name="") {
363 
364  if (locate_name == "")
366 
367  std::string first_name,second_name;
368  splitString(locate_name, first_name, second_name);
369 
370  for (unsigned j=0;j<sub_timers_.size();j++)
371  if ( first_name == sub_timers_[j].name_)
372  return sub_timers_[j].accumulatedTimePerUpdate(second_name);
373  return 0;
374  }
375 
381  double accumulatedTimePerTimerCall(const std::string &locate_name="") {
382 
383  if (locate_name == "")
385 
386  std::string first_name,second_name;
387  splitString(locate_name, first_name, second_name);
388 
389  for (unsigned j=0;j<sub_timers_.size();j++)
390  if ( first_name == sub_timers_[j].name_)
391  return sub_timers_[j].accumulatedTimePerTimerCall(second_name);
392  return 0;
393  }
394 
398  void pack();
399 
405  LevelTimer* unpack(unsigned from);
406 
411  void report(std::ostream &os);
412 
418  const BaseTimer* findBaseTimer(const std::string &name) const;
419 
426  BaseTimer::TimeInfo findTimer(const std::string &name,bool& found);
427 
428  }; // LevelTimer
429 
430 
431 public:
437  explicit StackedTimer(const char *name, const bool start_base_timer = true)
438  : timer_(0,name,nullptr,false),
439  global_mpi_aggregation_called_(false),
440  enable_verbose_(false),
441  verbose_timestamp_levels_(0), // 0 disables
442  verbose_ostream_(Teuchos::rcpFromRef(std::cout)),
443  enable_timers_(true)
444  {
445  top_ = &timer_;
446  if (start_base_timer)
447  this->startBaseTimer();
448 
449  auto check_verbose = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMERS");
450  if (check_verbose != nullptr)
451  enable_verbose_ = true;
452 
453  auto check_timestamp = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
454  if (check_timestamp != nullptr) {
455  verbose_timestamp_levels_ = std::atoi(check_timestamp);
456  }
457  }
458 
462  void startBaseTimer() {
463  timer_.BaseTimer::start();
464 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
465  ::Kokkos::Tools::pushRegion(timer_.get_full_name());
466 #endif
467  }
468 
472  void stopBaseTimer() {
473  timer_.BaseTimer::stop();
474 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
475  ::Kokkos::Tools::popRegion();
476 #endif
477  }
478 
484  void start(const std::string name,
485  const bool push_kokkos_profiling_region = true) {
486  if (enable_timers_) {
487  if (top_ == nullptr)
488  top_ = timer_.start(name.c_str());
489  else
490  top_ = top_->start(name.c_str());
491 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
492  if (push_kokkos_profiling_region) {
493  ::Kokkos::Tools::pushRegion(name);
494  }
495 #endif
496  }
497  if (enable_verbose_) {
498  if (!verbose_timestamp_levels_) {
499  *verbose_ostream_ << "STARTING: " << name << std::endl;
500  }
501  // gcc 4.X is incomplete in c++11 standard - missing
502  // std::put_time. We'll disable this feature for gcc 4.
503 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
504  else if (top_ != nullptr) {
505  if ( top_->level() <= verbose_timestamp_levels_) {
506  auto now = std::chrono::system_clock::now();
507  auto now_time = std::chrono::system_clock::to_time_t(now);
508  auto gmt = gmtime(&now_time);
509  auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
510  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
511  *verbose_ostream_ << "STARTING: " << name << " LEVEL: " << top_->level() << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
512  }
513  }
514 #endif
515  }
516  }
517 
523  void stop(const std::string &name,
524  const bool pop_kokkos_profiling_region = true) {
525  if (enable_timers_) {
526  if (top_)
527  top_ = top_->stop(name);
528  else
529  timer_.BaseTimer::stop();
530 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
531  if (pop_kokkos_profiling_region) {
532  ::Kokkos::Tools::popRegion();
533  }
534 #endif
535  }
536  if (enable_verbose_) {
537  if (!verbose_timestamp_levels_) {
538  *verbose_ostream_ << "STOPPING: " << name << std::endl;
539  }
540  // gcc 4.X is incomplete in c++11 standard - missing
541  // std::put_time. We'll disable this feature for gcc 4.
542 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
543  // The stop adjusts the top level, need to adjust by +1 for printing
544  else if (top_ != nullptr) {
545  if ( (top_->level()+1) <= verbose_timestamp_levels_) {
546  auto now = std::chrono::system_clock::now();
547  auto now_time = std::chrono::system_clock::to_time_t(now);
548  auto gmt = gmtime(&now_time);
549  auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
550  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
551  *verbose_ostream_ << "STOPPING: " << name << " LEVEL: " << top_->level()+1 << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
552  }
553  }
554 #endif
555  }
556  }
557 
562  void incrementUpdates(const long long i = 1) {
563  top_->incrementUpdates(i);
564  }
565 
571  double accumulatedTime(const std::string &name="") {
572  if (top_) // Top is null for the head node when nothing is running
573  return top_->accumulatedTime(name);
574  else
575  return timer_.accumulatedTime(name);
576  }
577 
583  double accumulatedTimePerUpdate(const std::string &name="") {
584  if (top_) // Top is null for the head node when nothing is running
585  return top_->accumulatedTimePerUpdate(name);
586  else
587  return timer_.accumulatedTimePerUpdate(name);
588  }
594  double accumulatedTimePerTimerCall(const std::string &name="") {
595  if (top_) // Top is null for the head node when nothing is running
596  return top_->accumulatedTimePerTimerCall(name);
597  else
598  return timer_.accumulatedTimePerTimerCall(name);
599  }
600 
606  const BaseTimer* findBaseTimer(const std::string &name) const {
607  const BaseTimer* baseTimer = timer_.findBaseTimer(name);
608  TEUCHOS_TEST_FOR_EXCEPTION(baseTimer == nullptr, std::runtime_error,
609  "StackedTimer::findBaseTimer() failed to find a timer named \"" << name << "\"!\n");
610  return baseTimer;
611  }
612 
618  BaseTimer::TimeInfo findTimer(const std::string &name) {
619  bool foundTimer = false;
620  const auto timeInfo = timer_.findTimer(name,foundTimer);
621  TEUCHOS_TEST_FOR_EXCEPTION(!foundTimer, std::runtime_error,
622  "StackedTimer::findTimer() failed to find a timer named \"" << name << "\"!\n");
623  return timeInfo;
624  }
625 
626  void report(std::ostream &os) {
627  timer_.report(os);
628  }
629 
643  struct OutputOptions {
644  OutputOptions() : output_fraction(false), output_total_updates(false), output_histogram(false),
645  output_minmax(false), output_proc_minmax(false), num_histogram(10), max_levels(INT_MAX),
646  print_warnings(true), align_columns(false), print_names_before_values(true),
647  drop_time(-1.0) {}
648  bool output_fraction;
649  bool output_total_updates;
650  bool output_histogram;
651  bool output_minmax;
652  bool output_proc_minmax;
653  int num_histogram;
654  int max_levels;
655  bool print_warnings;
656  bool align_columns;
657  bool print_names_before_values;
658  double drop_time;
659  };
660 
667  void report(std::ostream &os, Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());
668 
678  void reportXML(std::ostream &os, const std::string& datestamp, const std::string& timestamp, Teuchos::RCP<const Teuchos::Comm<int> > comm);
679 
711  std::string reportWatchrXML(const std::string& name, Teuchos::RCP<const Teuchos::Comm<int> > comm);
712 
714  void enableVerbose(const bool enable_verbose);
715 
717  void enableVerboseTimestamps(const unsigned levels);
718 
720  void setVerboseOstream(const Teuchos::RCP<std::ostream>& os);
721 
724  void disableTimers();
725 
728  void enableTimers();
729 
735  void aggregateMpiData(Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());
736 
745  double getMpiAverageTime(const std::string& flat_timer_name);
746 
755  double getMpiAverageCount(const std::string& flat_timer_name);
756 
765  bool isTimer(const std::string& flat_timer_name);
766 
767 protected:
772 
773  // Global MPI aggregation arrays
774  Array<std::string> flat_names_;
775  Array<double> min_;
776  Array<double> max_;
777  Array<int> procmin_;
778  Array<int> procmax_;
779  Array<double> sum_;
780  Array<double> sum_sq_;
781  Array<Array<int>> hist_;
782  Array<unsigned long> count_;
783  Array<unsigned long long> updates_;
784  Array<int> active_;
785  bool global_mpi_aggregation_called_;
786 
789  std::string::size_type timer_names_;
790  std::string::size_type average_time_;
791  std::string::size_type fraction_;
792  std::string::size_type count_;
793  std::string::size_type total_updates_;
794  std::string::size_type min_;
795  std::string::size_type max_;
796  std::string::size_type procmin_;
797  std::string::size_type procmax_;
798  std::string::size_type stddev_;
799  std::string::size_type histogram_;
800  AlignmentWidths() :
801  timer_names_(0),
802  average_time_(0),
803  fraction_(0),
804  count_(0),
805  total_updates_(0),
806  min_(0),
807  max_(0),
808  procmax_(0),
809  stddev_(0),
810  histogram_(0){}
811  } alignments_;
812 
815 
818 
821 
824 
828  void flatten();
829 
834  void merge(Teuchos::RCP<const Teuchos::Comm<int> > comm);
835 
839  void collectRemoteData(Teuchos::RCP<const Teuchos::Comm<int> > comm, const OutputOptions &options );
840 
844  int getFlatNameIndex(const std::string& flat_timer_name);
845 
852  double computeColumnWidthsForAligment(std::string prefix, int print_level,
853  std::vector<bool> &printed, double parent_time,
854  const OutputOptions &options);
855 
859  double printLevel(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed,
860  double parent_time, const OutputOptions &options);
861 
866  double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed, double parent_time, const std::string& rootName = "");
867 
868 }; //StackedTimer
869 
870 
871 } //namespace Teuchos
872 
873 #endif /* TEUCHOS_STACKED_TIMER_HPP */
void setAccumulatedTime(double accum=0)
Setter for accumulated time.
double accumulatedTimePerTimerCall(const std::string &name="")
double difference(const BaseTimer &from) const
Return the difference between two timers in seconds,.
StackedTimer(const char *name, const bool start_base_timer=true)
void overrideNumUpdatesForUnitTesting(const unsigned long long num_updates)
Sets the number of counts for this timer. This is only used for unit testing.
double accumulatedTime() const
Get the total accumulated time since last reset or construction when the timer is running...
void splitString(const std::string &locate_name, std::string &first_name, std::string &second_name)
split a string into two parts split by a &#39;@&#39; if no &#39;@&#39; first gets the full string ...
void stop(const std::string &name, const bool pop_kokkos_profiling_region=true)
LevelTimer(int level, const char *name="RootTimer", LevelTimer *parent=nullptr, bool start_timer=true)
unsigned long long incrementUpdates(unsigned long long count=1)
Increment the total number of items updated between a start stop.
bool running() const
Returns true if the timer is currently accumulating time.
double accumulatedTimePerTimerCall() const
return the average time per timer start/stop
#define TEUCHOS_TEST_FOR_EXCEPTION(throw_exception_test, Exception, msg)
Macro for throwing an exception with breakpointing to ease debugging.
double accumulatedTimePerUpdate() const
return the average time per item updated
Teuchos header file which uses auto-configuration information to include necessary C++ headers...
bool enable_verbose_
If set to true, prints to the debug ostream. At construction, default value is set from environment v...
void incrementUpdates(const long long i=1)
void start()
Start a currently stopped timer.
LevelTimer * top_
Current level running.
bool enable_timers_
Used to disable timers for asynchronous work.
double accumulatedTimePerUpdate(const std::string &name="")
unsigned verbose_timestamp_levels_
If set to a value greater than 0, verbose mode will print that many levels of timers with timestamps...
unsigned long numCalls() const
Returns the number of calls to start().
double accumulatedTime(const std::string &name="")
void start(const std::string name, const bool push_kokkos_profiling_region=true)
double accumulatedTime(const std::string &locate_name="")
void overrideNumCallsForUnitTesting(const unsigned long num_calls)
Sets the number of calls to start() for this timer. This is only used for unit testing.
void error_out(const std::string &msg, const bool)
Error reporting function for stacked timer.
The basic timer used internally, uses std::chrono::high_resolution_clock.
Stores the column widths for output alignment.
LevelTimer(const LevelTimer &src)
Copy constructor.
Timer info at a given level and all the children.
const BaseTimer * findBaseTimer(const std::string &name) const
double accumulatedTimePerUpdate(const std::string &locate_name="")
Teuchos::RCP< std::ostream > verbose_ostream_
For debugging, this is the ostream used for printing.
LevelTimer timer_
Base timer.
double accumulatedTimePerTimerCall(const std::string &locate_name="")
Templated array class derived from the STL std::vector.
LevelTimer * stop(const std::string &name="RootTimer")
void reset()
Reset all the timer stats, throws if it is already running.
void stop()
Stop a current running timer and accumulate time difference.
unsigned level() const
Returns the level of the timer in the stack.
Smart reference counting pointer class for automatic garbage collection.
BaseTimer::TimeInfo findTimer(const std::string &name)
This class allows one to push and pop timers on and off a stack.
Common capabilities for collecting and reporting performance data collectively across MPI processes...
unsigned long long numUpdates() const
Returns the number of updates added to this timer.
Reference-counted pointer class and non-member templated function implementations.
LevelTimer * start(const char *sub_name)