Teuchos Package Browser (Single Doxygen Collection)  Version of the Day
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
Teuchos_StackedTimer.hpp
Go to the documentation of this file.
1 // @HEADER
2 // ***********************************************************************
3 //
4 // Teuchos: Common Tools Package
5 // Copyright (2004) Sandia Corporation
6 //
7 // Under terms of Contract DE-AC04-94AL85000, there is a non-exclusive
8 // license for use of this work by or on behalf of the U.S. Government.
9 //
10 // Redistribution and use in source and binary forms, with or without
11 // modification, are permitted provided that the following conditions are
12 // met:
13 //
14 // 1. Redistributions of source code must retain the above copyright
15 // notice, this list of conditions and the following disclaimer.
16 //
17 // 2. Redistributions in binary form must reproduce the above copyright
18 // notice, this list of conditions and the following disclaimer in the
19 // documentation and/or other materials provided with the distribution.
20 //
21 // 3. Neither the name of the Corporation nor the names of the
22 // contributors may be used to endorse or promote products derived from
23 // this software without specific prior written permission.
24 //
25 // THIS SOFTWARE IS PROVIDED BY SANDIA CORPORATION "AS IS" AND ANY
26 // EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
27 // IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
28 // PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL SANDIA CORPORATION OR THE
29 // CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL,
30 // EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
31 // PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
32 // PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
33 // LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
34 // NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
35 // SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
36 //
37 // ***********************************************************************
38 // @HEADER
39 
40 #ifndef TEUCHOS_STACKED_TIMER_HPP
41 #define TEUCHOS_STACKED_TIMER_HPP
42 
43 #include "Teuchos_ConfigDefs.hpp"
44 #include "Teuchos_Comm.hpp"
45 #include "Teuchos_DefaultComm.hpp"
46 #include "Teuchos_CommHelpers.hpp"
47 #include "Teuchos_RCP.hpp"
48 #include "Teuchos_Array.hpp"
50 #include <string>
51 #include <vector>
52 #include <cassert>
53 #include <chrono>
54 #include <climits>
55 #include <cstdlib> // for std::getenv and atoi
56 #include <ctime> // for timestamp support
57 #include <iostream>
58 
59 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
60 namespace Kokkos {
61 namespace Profiling {
62 extern void pushRegion (const std::string&);
63 extern void popRegion ();
64 } // namespace Profiling
65 } // namespace Kokkos
66 #endif
67 
68 
69 namespace Teuchos {
70 
72 void error_out(const std::string& msg, const bool fail_all = false);
73 
83 class BaseTimer {
84 
85 public:
86 
87  using Clock = std::chrono::high_resolution_clock;
88 
90 
92  void start(){
93  if (running_)
94  error_out("Base_Timer:start Failed timer already running");
95  start_time_ = Clock::now();
96 
98  running_ = true;
99  }
100 
102  void stop(){
103  if (!running_)
104  error_out("Base_Timer:stop Failed timer not running");
105  accumulation_ += std::chrono::duration_cast<std::chrono::duration<double>>(Clock::now() - start_time_).count();
106  running_ = false;
107  }
108 
110  unsigned long long incrementUpdates(unsigned long long count=1) {count_updates_ += count; return count_updates_;}
111 
113  double accumulatedTime() const {return accumulation_;}
114 
116  void setAccumulatedTime(double accum=0) {accumulation_=accum;}
117  double accumulatedTimePerUpdate() const {
127  if (count_updates_ > 0) {
129  } else {
130  return 0;
131  }
132  }
133 
134 
143  if (count_started_> 0) {
145  } else {
146  return 0;
147  }
148  }
149 
156  double difference(const BaseTimer &from) const {
157  return accumulation_ - from.accumulation_;
158  }
159 
161  void reset() {
162  if (running_)
163  error_out("BaseTimer, cannot reset a running timer");
164  accumulation_ = 0.0;
166  }
167 
169  bool running() const { return running_;}
170 
172  unsigned long numCalls() const { return count_started_; }
173 
175  unsigned long long numUpdates() const { return count_updates_; }
176 
178  void overrideNumCallsForUnitTesting(const unsigned long num_calls)
179  { count_started_ = num_calls; }
180 
182  void overrideNumUpdatesForUnitTesting(const unsigned long long num_updates)
183  { count_updates_ = num_updates; }
184 
185  struct TimeInfo {
186  TimeInfo():time(0.0), count(0), updates(0), running(false){}
188  double time;
189  unsigned long count;
190  unsigned long long updates;
191  bool running;
192  };
193 
194 protected:
195  double accumulation_; // total time
196  unsigned long count_started_; // Number of times this timer has been started
197  unsigned long long count_updates_; // Total count of items updated during this timer
198  Clock::time_point start_time_;
199  bool running_;
200 
201  friend struct TimeInfo;
202 };
203 
222 {
223 protected:
224 
233  class LevelTimer : public BaseTimer {
234  protected:
235 
236  // TODO: implement operator=
237 
238  unsigned level_;
239  std::string name_;
241  std::vector<LevelTimer> sub_timers_;
242  public:
244  LevelTimer();
245 
254  const char* name = "RootTimer",
255  LevelTimer *parent=nullptr,
256  bool start_timer=true) :
257  BaseTimer(),
258  level_(level),
259  name_(name),
260  parent_(parent)
261  {
262  if ( start_timer )
264 
265  }
266 
268  LevelTimer(const LevelTimer &src) :
270  {
271  for (unsigned i=0;i<sub_timers_.size();++i)
272  sub_timers_[i].parent_ = this;
273  }
274 
280  LevelTimer* start(const char* sub_name) {
281  for (unsigned i=0;i<sub_timers_.size();i++ )
282  if (sub_name == sub_timers_[i].name_ ) {
283  sub_timers_[i].BaseTimer::start();
284  return &sub_timers_[i];
285  }
286  sub_timers_.push_back(LevelTimer(level_+1,sub_name,this,true));
287  return &sub_timers_[sub_timers_.size()-1];
288  }
289 
297  LevelTimer* stop(const std::string &name = "RootTimer") {
298  if (name != name_)
299  error_out("Stopping timer "+name+" But top level running timer is "+name_);
300  BaseTimer::stop();
301  return parent_;
302  }
303 
304 
309  std::string get_full_name() const {
310  std::string parent_name("");
311  if ((parent_ != nullptr))
312  parent_name = parent_->get_full_name() + "@";
313 
314  std::string my_name(name_);
315 
316  std::string full_name = parent_name + my_name;
317  return full_name;
318  }
319 
325  int countTimers() {
326  int count=1;
327  for (unsigned i=0;i<sub_timers_.size(); ++i)
328  count += sub_timers_[i].countTimers();
329  return count;
330  }
331 
332  void addTimerNames(Array<std::string> &names, unsigned &pos) {
333  names[pos++] = get_full_name();
334  for (unsigned i=0;i<sub_timers_.size(); ++i)
335  sub_timers_[i].addTimerNames(names, pos);
336  }
337 
343  double accumulatedTime(const std::string &locate_name="") {
344 
345  if (locate_name == "")
347 
348  std::string first_name,second_name;
349 
350  size_t i = locate_name.find_first_of('@');
351  if ( i >= locate_name.size() ) {
352  first_name = locate_name;
353  second_name = "";
354  } else {
355  first_name.assign(locate_name,0,i);
356  second_name.assign(locate_name,i+1,locate_name.size()-i-1);
357  }
358  for (unsigned j=0;j<sub_timers_.size();++j)
359  if ( first_name == sub_timers_[j].name_)
360  return sub_timers_[j].accumulatedTime(second_name);
361  return 0;
362  }
363 
365  unsigned level() const
366  {return level_;}
367 
368  protected:
375  void splitString(const std::string &locate_name, std::string &first_name, std::string &second_name) {
376  size_t i = locate_name.find_first_of('@');
377  if ( i >= locate_name.size() ) {
378  first_name = locate_name;
379  second_name = "";
380  } else {
381  first_name.assign(locate_name,0,i);
382  second_name.assign(locate_name,i+1,locate_name.size()-i-1);
383  }
384  }
385 
386  public:
392  double accumulatedTimePerUpdate(const std::string &locate_name="") {
393 
394  if (locate_name == "")
396 
397  std::string first_name,second_name;
398  splitString(locate_name, first_name, second_name);
399 
400  for (unsigned j=0;j<sub_timers_.size();j++)
401  if ( first_name == sub_timers_[j].name_)
402  return sub_timers_[j].accumulatedTimePerUpdate(second_name);
403  return 0;
404  }
405 
411  double accumulatedTimePerTimerCall(const std::string &locate_name="") {
412 
413  if (locate_name == "")
415 
416  std::string first_name,second_name;
417  splitString(locate_name, first_name, second_name);
418 
419  for (unsigned j=0;j<sub_timers_.size();j++)
420  if ( first_name == sub_timers_[j].name_)
421  return sub_timers_[j].accumulatedTimePerTimerCall(second_name);
422  return 0;
423  }
424 
428  void pack();
429 
435  LevelTimer* unpack(unsigned from);
436 
441  void report(std::ostream &os);
442 
448  const BaseTimer* findBaseTimer(const std::string &name) const;
449 
456  BaseTimer::TimeInfo findTimer(const std::string &name,bool& found);
457 
458  protected:
459 
460 
461  }; // LevelTimer
462 
463 
464 
465 
466 public:
472  explicit StackedTimer(const char *name, const bool start_base_timer = true)
473  : timer_(0,name,nullptr,false),
474  enable_verbose_(false),
475  verbose_timestamp_levels_(0), // 0 disables
476  verbose_ostream_(Teuchos::rcpFromRef(std::cout))
477  {
478  top_ = &timer_;
479  if (start_base_timer)
480  this->startBaseTimer();
481 
482  auto check_verbose = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMERS");
483  if (check_verbose != nullptr)
484  enable_verbose_ = true;
485 
486  auto check_timestamp = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
487  if (check_timestamp != nullptr) {
488  verbose_timestamp_levels_ = std::atoi(check_timestamp);
489  }
490  }
491 
495  void startBaseTimer() {
496  timer_.BaseTimer::start();
497 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
498  ::Kokkos::Profiling::pushRegion(timer_.get_full_name());
499 #endif
500  }
501 
505  void stopBaseTimer() {
506  timer_.BaseTimer::stop();
507 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
508  ::Kokkos::Profiling::popRegion();
509 #endif
510  }
511 
517  void start(const std::string name,
518  const bool push_kokkos_profiling_region = true) {
519  if (top_ == nullptr)
520  top_ = timer_.start(name.c_str());
521  else
522  top_ = top_->start(name.c_str());
523 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
524  if (push_kokkos_profiling_region) {
525  ::Kokkos::Profiling::pushRegion(name);
526  }
527 #endif
528  if (enable_verbose_) {
530  *verbose_ostream_ << "STARTING: " << name << std::endl;
531  }
532  // gcc 4.X is incomplete in c++11 standard - missing
533  // std::put_time. We'll disable this feature for gcc 4.
534 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
535  else if (top_ != nullptr) {
536  if ( top_->level() <= verbose_timestamp_levels_) {
537  auto now = std::chrono::system_clock::now();
538  auto now_time = std::chrono::system_clock::to_time_t(now);
539  auto gmt = gmtime(&now_time);
540  auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
541  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
542  *verbose_ostream_ << "STARTING: " << name << " LEVEL: " << top_->level() << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
543  }
544  }
545 #endif
546  }
547  }
548 
554  void stop(const std::string &name,
555  const bool pop_kokkos_profiling_region = true) {
556  if (top_)
557  top_ = top_->stop(name);
558  else
559  timer_.BaseTimer::stop();
560 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
561  if (pop_kokkos_profiling_region) {
562  ::Kokkos::Profiling::popRegion();
563  }
564 #endif
565  if (enable_verbose_) {
567  *verbose_ostream_ << "STOPPING: " << name << std::endl;
568  }
569  // gcc 4.X is incomplete in c++11 standard - missing
570  // std::put_time. We'll disable this feature for gcc 4.
571 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
572  // The stop adjusts the top level, need to adjust by +1 for printing
573  else if (top_ != nullptr) {
574  if ( (top_->level()+1) <= verbose_timestamp_levels_) {
575  auto now = std::chrono::system_clock::now();
576  auto now_time = std::chrono::system_clock::to_time_t(now);
577  auto gmt = gmtime(&now_time);
578  auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
579  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
580  *verbose_ostream_ << "STOPPING: " << name << " LEVEL: " << top_->level()+1 << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
581  }
582  }
583 #endif
584  }
585  }
586 
591  void incrementUpdates(const long long i = 1) {
593  }
594 
600  double accumulatedTime(const std::string &name="") {
601  if (top_) // Top is null for the head node when nothing is running
602  return top_->accumulatedTime(name);
603  else
604  return timer_.accumulatedTime(name);
605  }
606 
612  double accumulatedTimePerUpdate(const std::string &name="") {
613  if (top_) // Top is null for the head node when nothing is running
614  return top_->accumulatedTimePerUpdate(name);
615  else
616  return timer_.accumulatedTimePerUpdate(name);
617  }
623  double accumulatedTimePerTimerCall(const std::string &name="") {
624  if (top_) // Top is null for the head node when nothing is running
625  return top_->accumulatedTimePerTimerCall(name);
626  else
627  return timer_.accumulatedTimePerTimerCall(name);
628  }
629 
635  const BaseTimer* findBaseTimer(const std::string &name) const {
636  const BaseTimer* baseTimer = timer_.findBaseTimer(name);
637  TEUCHOS_TEST_FOR_EXCEPTION(baseTimer == nullptr, std::runtime_error,
638  "StackedTimer::findBaseTimer() failed to find a timer named \"" << name << "\"!\n");
639  return baseTimer;
640  }
641 
647  BaseTimer::TimeInfo findTimer(const std::string &name) {
648  bool foundTimer = false;
649  const auto timeInfo = timer_.findTimer(name,foundTimer);
650  TEUCHOS_TEST_FOR_EXCEPTION(!foundTimer, std::runtime_error,
651  "StackedTimer::findTimer() failed to find a timer named \"" << name << "\"!\n");
652  return timeInfo;
653  }
654 
655  void report(std::ostream &os) {
656  timer_.report(os);
657  }
658 
672  struct OutputOptions {
674  output_minmax(false), output_proc_minmax(false), num_histogram(10), max_levels(INT_MAX),
676  drop_time(-1.0) {}
687  double drop_time;
688  };
689 
695  void report(std::ostream &os, Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());
696 
706  void reportXML(std::ostream &os, const std::string& datestamp, const std::string& timestamp, Teuchos::RCP<const Teuchos::Comm<int> > comm);
707 
734  std::string reportWatchrXML(const std::string& name, Teuchos::RCP<const Teuchos::Comm<int> > comm);
735 
736  // If set to true, print timer start/stop to verbose ostream.
737  void enableVerbose(const bool enable_verbose);
738 
739  // Enable timestamps in verbose mode for the number of levels specified.
740  void enableVerboseTimestamps(const unsigned levels);
741 
742  // Set the ostream for verbose mode(defaults to std::cout).
744 
745 protected:
750 
762 
765  std::string::size_type timer_names_;
766  std::string::size_type average_time_;
767  std::string::size_type fraction_;
768  std::string::size_type count_;
769  std::string::size_type total_updates_;
770  std::string::size_type min_;
771  std::string::size_type max_;
772  std::string::size_type procmin_;
773  std::string::size_type procmax_;
774  std::string::size_type stddev_;
775  std::string::size_type histogram_;
777  timer_names_(0),
778  average_time_(0),
779  fraction_(0),
780  count_(0),
781  total_updates_(0),
782  min_(0),
783  max_(0),
784  procmax_(0),
785  stddev_(0),
786  histogram_(0){}
787  } alignments_;
788 
791 
794 
797 
801  void flatten();
802 
807  void merge(Teuchos::RCP<const Teuchos::Comm<int> > comm);
808 
812  void collectRemoteData(Teuchos::RCP<const Teuchos::Comm<int> > comm, const OutputOptions &options );
813 
820  double computeColumnWidthsForAligment(std::string prefix, int print_level,
821  std::vector<bool> &printed, double parent_time,
822  const OutputOptions &options);
823 
827  double printLevel(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed,
828  double parent_time, const OutputOptions &options);
829 
834  double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed, double parent_time, const std::string& rootName = "");
835 
836 }; //StackedTimer
837 
838 
839 } //namespace Teuchos
840 
841 #endif /* TEUCHOS_STACKED_TIMER_HPP */
void setAccumulatedTime(double accum=0)
Setter for accumulated time.
double accumulatedTimePerTimerCall(const std::string &name="")
Clock::time_point start_time_
double difference(const BaseTimer &from) const
Return the difference between two timers in seconds,.
void setVerboseOstream(const Teuchos::RCP< std::ostream > &os)
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
void addTimerNames(Array< std::string > &names, unsigned &pos)
void enableVerboseTimestamps(const unsigned levels)
void enableVerbose(const bool enable_verbose)
void merge(Teuchos::RCP< const Teuchos::Comm< int > > comm)
#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)
double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const std::string &rootName="")
void start()
Start a currently stopped timer.
LevelTimer * top_
Current level running.
double accumulatedTimePerUpdate(const std::string &name="")
std::string reportWatchrXML(const std::string &name, Teuchos::RCP< const Teuchos::Comm< int > > comm)
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().
BaseTimer::TimeInfo findTimer(const std::string &name, bool &found)
double printLevel(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
LevelTimer * unpack(unsigned from)
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.
the basic timer used elsewhere, uses MPI_Wtime for time
double computeColumnWidthsForAligment(std::string prefix, int print_level, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
void reportXML(std::ostream &os, const std::string &datestamp, const std::string &timestamp, Teuchos::RCP< const Teuchos::Comm< int > > comm)
Stores the column widths for output alignment.
Array< Array< int > > hist_
void collectRemoteData(Teuchos::RCP< const Teuchos::Comm< int > > comm, const OutputOptions &options)
std::chrono::high_resolution_clock Clock
LevelTimer(const LevelTimer &src)
Copy constructor.
Array< unsigned long long > updates_
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.
void error_out(const std::string &msg, const bool)
Error reporting function for stacked timer.
LevelTimer * stop(const std::string &name="RootTimer")
void reset()
Reset all the timer stats, throws if it is already running.
Array< std::string > flat_names_
void stop()
Stop a current running timer and accumulate time difference.
unsigned level() const
Returns the level of the timer in the stack.
void report(std::ostream &os)
LevelTimer()
Default constructor, shouldn&#39;t be used but needed for std::vector.
const BaseTimer * findBaseTimer(const std::string &name) const
unsigned long long count_updates_
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.
Array< unsigned long > count_
Reference-counted pointer class and non-member templated function implementations.
LevelTimer * start(const char *sub_name)
struct Teuchos::StackedTimer::AlignmentWidths alignments_