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  enable_timers_(true)
478  {
479  top_ = &timer_;
480  if (start_base_timer)
481  this->startBaseTimer();
482 
483  auto check_verbose = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMERS");
484  if (check_verbose != nullptr)
485  enable_verbose_ = true;
486 
487  auto check_timestamp = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
488  if (check_timestamp != nullptr) {
489  verbose_timestamp_levels_ = std::atoi(check_timestamp);
490  }
491  }
492 
496  void startBaseTimer() {
497  timer_.BaseTimer::start();
498 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
499  ::Kokkos::Profiling::pushRegion(timer_.get_full_name());
500 #endif
501  }
502 
506  void stopBaseTimer() {
507  timer_.BaseTimer::stop();
508 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
509  ::Kokkos::Profiling::popRegion();
510 #endif
511  }
512 
518  void start(const std::string name,
519  const bool push_kokkos_profiling_region = true) {
520  if (enable_timers_) {
521  if (top_ == nullptr)
522  top_ = timer_.start(name.c_str());
523  else
524  top_ = top_->start(name.c_str());
525 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
526  if (push_kokkos_profiling_region) {
527  ::Kokkos::Profiling::pushRegion(name);
528  }
529 #endif
530  }
531  if (enable_verbose_) {
533  *verbose_ostream_ << "STARTING: " << name << std::endl;
534  }
535  // gcc 4.X is incomplete in c++11 standard - missing
536  // std::put_time. We'll disable this feature for gcc 4.
537 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
538  else if (top_ != nullptr) {
539  if ( top_->level() <= verbose_timestamp_levels_) {
540  auto now = std::chrono::system_clock::now();
541  auto now_time = std::chrono::system_clock::to_time_t(now);
542  auto gmt = gmtime(&now_time);
543  auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
544  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
545  *verbose_ostream_ << "STARTING: " << name << " LEVEL: " << top_->level() << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
546  }
547  }
548 #endif
549  }
550  }
551 
557  void stop(const std::string &name,
558  const bool pop_kokkos_profiling_region = true) {
559  if (enable_timers_) {
560  if (top_)
561  top_ = top_->stop(name);
562  else
563  timer_.BaseTimer::stop();
564 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
565  if (pop_kokkos_profiling_region) {
566  ::Kokkos::Profiling::popRegion();
567  }
568 #endif
569  }
570  if (enable_verbose_) {
572  *verbose_ostream_ << "STOPPING: " << name << std::endl;
573  }
574  // gcc 4.X is incomplete in c++11 standard - missing
575  // std::put_time. We'll disable this feature for gcc 4.
576 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
577  // The stop adjusts the top level, need to adjust by +1 for printing
578  else if (top_ != nullptr) {
579  if ( (top_->level()+1) <= verbose_timestamp_levels_) {
580  auto now = std::chrono::system_clock::now();
581  auto now_time = std::chrono::system_clock::to_time_t(now);
582  auto gmt = gmtime(&now_time);
583  auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
584  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
585  *verbose_ostream_ << "STOPPING: " << name << " LEVEL: " << top_->level()+1 << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
586  }
587  }
588 #endif
589  }
590  }
591 
596  void incrementUpdates(const long long i = 1) {
598  }
599 
605  double accumulatedTime(const std::string &name="") {
606  if (top_) // Top is null for the head node when nothing is running
607  return top_->accumulatedTime(name);
608  else
609  return timer_.accumulatedTime(name);
610  }
611 
617  double accumulatedTimePerUpdate(const std::string &name="") {
618  if (top_) // Top is null for the head node when nothing is running
619  return top_->accumulatedTimePerUpdate(name);
620  else
621  return timer_.accumulatedTimePerUpdate(name);
622  }
628  double accumulatedTimePerTimerCall(const std::string &name="") {
629  if (top_) // Top is null for the head node when nothing is running
630  return top_->accumulatedTimePerTimerCall(name);
631  else
632  return timer_.accumulatedTimePerTimerCall(name);
633  }
634 
640  const BaseTimer* findBaseTimer(const std::string &name) const {
641  const BaseTimer* baseTimer = timer_.findBaseTimer(name);
642  TEUCHOS_TEST_FOR_EXCEPTION(baseTimer == nullptr, std::runtime_error,
643  "StackedTimer::findBaseTimer() failed to find a timer named \"" << name << "\"!\n");
644  return baseTimer;
645  }
646 
652  BaseTimer::TimeInfo findTimer(const std::string &name) {
653  bool foundTimer = false;
654  const auto timeInfo = timer_.findTimer(name,foundTimer);
655  TEUCHOS_TEST_FOR_EXCEPTION(!foundTimer, std::runtime_error,
656  "StackedTimer::findTimer() failed to find a timer named \"" << name << "\"!\n");
657  return timeInfo;
658  }
659 
660  void report(std::ostream &os) {
661  timer_.report(os);
662  }
663 
677  struct OutputOptions {
679  output_minmax(false), output_proc_minmax(false), num_histogram(10), max_levels(INT_MAX),
681  drop_time(-1.0) {}
692  double drop_time;
693  };
694 
700  void report(std::ostream &os, Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());
701 
711  void reportXML(std::ostream &os, const std::string& datestamp, const std::string& timestamp, Teuchos::RCP<const Teuchos::Comm<int> > comm);
712 
739  std::string reportWatchrXML(const std::string& name, Teuchos::RCP<const Teuchos::Comm<int> > comm);
740 
742  void enableVerbose(const bool enable_verbose);
743 
745  void enableVerboseTimestamps(const unsigned levels);
746 
749 
752  void disableTimers();
753 
756  void enableTimers();
757 
758 protected:
763 
775 
778  std::string::size_type timer_names_;
779  std::string::size_type average_time_;
780  std::string::size_type fraction_;
781  std::string::size_type count_;
782  std::string::size_type total_updates_;
783  std::string::size_type min_;
784  std::string::size_type max_;
785  std::string::size_type procmin_;
786  std::string::size_type procmax_;
787  std::string::size_type stddev_;
788  std::string::size_type histogram_;
790  timer_names_(0),
791  average_time_(0),
792  fraction_(0),
793  count_(0),
794  total_updates_(0),
795  min_(0),
796  max_(0),
797  procmax_(0),
798  stddev_(0),
799  histogram_(0){}
800  } alignments_;
801 
804 
807 
810 
813 
817  void flatten();
818 
823  void merge(Teuchos::RCP<const Teuchos::Comm<int> > comm);
824 
828  void collectRemoteData(Teuchos::RCP<const Teuchos::Comm<int> > comm, const OutputOptions &options );
829 
836  double computeColumnWidthsForAligment(std::string prefix, int print_level,
837  std::vector<bool> &printed, double parent_time,
838  const OutputOptions &options);
839 
843  double printLevel(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed,
844  double parent_time, const OutputOptions &options);
845 
850  double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed, double parent_time, const std::string& rootName = "");
851 
852 }; //StackedTimer
853 
854 
855 } //namespace Teuchos
856 
857 #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)
Set the ostream for verbose mode(defaults to std::cout).
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)
Enable timestamps in verbose mode for the number of levels specified.
void enableVerbose(const bool enable_verbose)
If set to true, print timer start/stop to verbose ostream.
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.
bool enable_timers_
Used to disable timers for asynchronous work.
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_