40 #ifndef TEUCHOS_STACKED_TIMER_HPP
41 #define TEUCHOS_STACKED_TIMER_HPP
44 #include "Teuchos_Comm.hpp"
45 #include "Teuchos_DefaultComm.hpp"
46 #include "Teuchos_CommHelpers.hpp"
59 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
62 extern void pushRegion (
const std::string&);
63 extern void popRegion ();
72 TEUCHOSCOMM_LIB_DLL_EXPORT
void error_out(
const std::string& msg,
const bool fail_all =
false);
87 using Clock = std::chrono::high_resolution_clock;
89 BaseTimer() : accumulation_(0.0), count_started_(0), count_updates_(0), running_(
false) {}
94 error_out(
"Base_Timer:start Failed timer already running");
95 start_time_ = Clock::now();
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();
110 unsigned long long incrementUpdates(
unsigned long long count=1) {count_updates_ += count;
return count_updates_;}
127 if (count_updates_ > 0) {
128 return accumulation_/count_updates_;
143 if (count_started_> 0) {
144 return accumulation_/count_started_;
157 return accumulation_ - from.accumulation_;
163 error_out(
"BaseTimer, cannot reset a running timer");
165 count_started_ = count_updates_ = 0;
172 unsigned long numCalls()
const {
return count_started_; }
175 unsigned long long numUpdates()
const {
return count_updates_; }
179 { count_started_ = num_calls; }
183 { count_updates_ = num_updates; }
186 TimeInfo():time(0.0), count(0), updates(0),
running(false){}
187 TimeInfo(BaseTimer* t): time(t->accumulation_), count(t->count_started_), updates(t->count_updates_),
running(t->
running()) {}
190 unsigned long long updates;
195 double accumulation_;
196 unsigned long count_started_;
197 unsigned long long count_updates_;
198 Clock::time_point start_time_;
201 friend struct TimeInfo;
241 std::vector<LevelTimer> sub_timers_;
254 const char* name =
"RootTimer",
256 bool start_timer=
true) :
269 BaseTimer(src), level_(src.level_), name_(src.name_),parent_(src.parent_), sub_timers_(src.sub_timers_)
271 for (
unsigned i=0;i<sub_timers_.size();++i)
272 sub_timers_[i].parent_ =
this;
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];
286 sub_timers_.push_back(
LevelTimer(level_+1,sub_name,
this,
true));
287 return &sub_timers_[sub_timers_.size()-1];
299 error_out(
"Stopping timer "+name+
" But top level running timer is "+name_);
310 std::string parent_name(
"");
311 if ((parent_ !=
nullptr))
312 parent_name = parent_->get_full_name() +
"@";
314 std::string my_name(name_);
316 std::string full_name = parent_name + my_name;
327 for (
unsigned i=0;i<sub_timers_.size(); ++i)
328 count += sub_timers_[i].countTimers();
333 names[pos++] = get_full_name();
334 for (
unsigned i=0;i<sub_timers_.size(); ++i)
335 sub_timers_[i].addTimerNames(names, pos);
345 if (locate_name ==
"")
348 std::string first_name,second_name;
350 size_t i = locate_name.find_first_of(
'@');
351 if ( i >= locate_name.size() ) {
352 first_name = locate_name;
355 first_name.assign(locate_name,0,i);
356 second_name.assign(locate_name,i+1,locate_name.size()-i-1);
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);
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;
381 first_name.assign(locate_name,0,i);
382 second_name.assign(locate_name,i+1,locate_name.size()-i-1);
394 if (locate_name ==
"")
397 std::string first_name,second_name;
398 splitString(locate_name, first_name, second_name);
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);
413 if (locate_name ==
"")
416 std::string first_name,second_name;
417 splitString(locate_name, first_name, second_name);
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);
441 void report(std::ostream &os);
448 const BaseTimer* findBaseTimer(
const std::string &name)
const;
456 BaseTimer::TimeInfo findTimer(
const std::string &name,
bool& found);
467 explicit StackedTimer(
const char *name,
const bool start_base_timer =
true)
468 : timer_(0,name,nullptr,false),
469 global_mpi_aggregation_called_(false),
470 enable_verbose_(false),
471 verbose_timestamp_levels_(0),
472 verbose_ostream_(Teuchos::rcpFromRef(std::cout)),
476 if (start_base_timer)
477 this->startBaseTimer();
479 auto check_verbose = std::getenv(
"TEUCHOS_ENABLE_VERBOSE_TIMERS");
480 if (check_verbose !=
nullptr)
481 enable_verbose_ =
true;
483 auto check_timestamp = std::getenv(
"TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
484 if (check_timestamp !=
nullptr) {
485 verbose_timestamp_levels_ = std::atoi(check_timestamp);
493 timer_.BaseTimer::start();
494 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
495 ::Kokkos::Profiling::pushRegion(timer_.get_full_name());
503 timer_.BaseTimer::stop();
504 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
505 ::Kokkos::Profiling::popRegion();
515 const bool push_kokkos_profiling_region =
true) {
516 if (enable_timers_) {
518 top_ = timer_.start(name.c_str());
520 top_ = top_->start(name.c_str());
521 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
522 if (push_kokkos_profiling_region) {
523 ::Kokkos::Profiling::pushRegion(name);
527 if (enable_verbose_) {
528 if (!verbose_timestamp_levels_) {
529 *verbose_ostream_ <<
"STARTING: " << name << std::endl;
533 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
534 else if (top_ !=
nullptr) {
535 if ( top_->level() <= verbose_timestamp_levels_) {
536 auto now = std::chrono::system_clock::now();
537 auto now_time = std::chrono::system_clock::to_time_t(now);
538 auto gmt = gmtime(&now_time);
539 auto timestamp = std::put_time(gmt,
"%Y-%m-%d %H:%M:%S");
540 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
541 *verbose_ostream_ <<
"STARTING: " << name <<
" LEVEL: " << top_->level() <<
" COUNT: " << timer_.numCalls() <<
" TIMESTAMP: " << timestamp <<
"." << ms.count() << std::endl;
553 void stop(
const std::string &name,
554 const bool pop_kokkos_profiling_region =
true) {
555 if (enable_timers_) {
557 top_ = top_->stop(name);
559 timer_.BaseTimer::stop();
560 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
561 if (pop_kokkos_profiling_region) {
562 ::Kokkos::Profiling::popRegion();
566 if (enable_verbose_) {
567 if (!verbose_timestamp_levels_) {
568 *verbose_ostream_ <<
"STOPPING: " << name << std::endl;
572 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
574 else if (top_ !=
nullptr) {
575 if ( (top_->level()+1) <= verbose_timestamp_levels_) {
576 auto now = std::chrono::system_clock::now();
577 auto now_time = std::chrono::system_clock::to_time_t(now);
578 auto gmt = gmtime(&now_time);
579 auto timestamp = std::put_time(gmt,
"%Y-%m-%d %H:%M:%S");
580 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
581 *verbose_ostream_ <<
"STOPPING: " << name <<
" LEVEL: " << top_->level()+1 <<
" COUNT: " << timer_.numCalls() <<
" TIMESTAMP: " << timestamp <<
"." << ms.count() << std::endl;
593 top_->incrementUpdates(i);
603 return top_->accumulatedTime(name);
605 return timer_.accumulatedTime(name);
615 return top_->accumulatedTimePerUpdate(name);
617 return timer_.accumulatedTimePerUpdate(name);
626 return top_->accumulatedTimePerTimerCall(name);
628 return timer_.accumulatedTimePerTimerCall(name);
637 const BaseTimer* baseTimer = timer_.findBaseTimer(name);
639 "StackedTimer::findBaseTimer() failed to find a timer named \"" << name <<
"\"!\n");
648 BaseTimer::TimeInfo
findTimer(
const std::string &name) {
649 bool foundTimer =
false;
650 const auto timeInfo = timer_.findTimer(name,foundTimer);
652 "StackedTimer::findTimer() failed to find a timer named \"" << name <<
"\"!\n");
656 void report(std::ostream &os) {
674 OutputOptions() : output_fraction(
false), output_total_updates(
false), output_histogram(
false),
675 output_minmax(
false), output_proc_minmax(
false), num_histogram(10), max_levels(INT_MAX),
676 print_warnings(
true), align_columns(
false), print_names_before_values(
true),
678 bool output_fraction;
679 bool output_total_updates;
680 bool output_histogram;
682 bool output_proc_minmax;
687 bool print_names_before_values;
744 void enableVerbose(
const bool enable_verbose);
747 void enableVerboseTimestamps(
const unsigned levels);
754 void disableTimers();
775 double getMpiAverageTime(
const std::string& flat_timer_name);
785 double getMpiAverageCount(
const std::string& flat_timer_name);
795 bool isTimer(
const std::string& flat_timer_name);
815 bool global_mpi_aggregation_called_;
819 std::string::size_type timer_names_;
820 std::string::size_type average_time_;
821 std::string::size_type fraction_;
822 std::string::size_type count_;
823 std::string::size_type total_updates_;
824 std::string::size_type min_;
825 std::string::size_type max_;
826 std::string::size_type procmin_;
827 std::string::size_type procmax_;
828 std::string::size_type stddev_;
829 std::string::size_type histogram_;
874 int getFlatNameIndex(
const std::string& flat_timer_name);
882 double computeColumnWidthsForAligment(std::string prefix,
int print_level,
883 std::vector<bool> &printed,
double parent_time,
889 double printLevel(std::string prefix,
int level, std::ostream &os, std::vector<bool> &printed,
896 double printLevelXML(std::string prefix,
int level, std::ostream &os, std::vector<bool> &printed,
double parent_time,
const std::string& rootName =
"");
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 '@' if no '@' 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.
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)
std::string get_full_name() const