10 #ifndef TEUCHOS_STACKED_TIMER_HPP
11 #define TEUCHOS_STACKED_TIMER_HPP
14 #include "Teuchos_Comm.hpp"
15 #include "Teuchos_DefaultComm.hpp"
16 #include "Teuchos_CommHelpers.hpp"
20 #include "Teuchos_Behavior.hpp"
21 #ifdef HAVE_TEUCHOSCORE_KOKKOS
22 #include "Kokkos_Core.hpp"
33 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
36 extern void pushRegion (
const std::string&);
37 extern void popRegion ();
46 TEUCHOSCOMM_LIB_DLL_EXPORT
void error_out(
const std::string& msg,
const bool fail_all =
false);
61 using Clock = std::chrono::high_resolution_clock;
63 BaseTimer() : accumulation_(0.0), accumulationSquared_(0.0), count_started_(0), count_updates_(0), running_(
false) {}
68 error_out(
"Base_Timer:start Failed timer already running");
69 start_time_ = Clock::now();
78 error_out(
"Base_Timer:stop Failed timer not running");
79 auto elapsed = std::chrono::duration_cast<std::chrono::duration<double>>(Clock::now() - start_time_).count();
80 accumulation_ += elapsed;
81 accumulationSquared_ += elapsed*elapsed;
86 unsigned long long incrementUpdates(
unsigned long long count=1) {count_updates_ += count;
return count_updates_;}
106 if (count_updates_ > 0) {
107 return accumulation_/count_updates_;
122 if (count_started_> 0) {
123 return accumulation_/count_started_;
137 if (count_started_ > 0) {
139 return sqrt(std::max<double>(accumulationSquared_ / count_started_ - mean*mean, 0.0));
152 return accumulation_ - from.accumulation_;
158 error_out(
"BaseTimer, cannot reset a running timer");
160 count_started_ = count_updates_ = 0;
167 unsigned long numCalls()
const {
return count_started_; }
170 unsigned long long numUpdates()
const {
return count_updates_; }
174 { count_started_ = num_calls; }
178 { count_updates_ = num_updates; }
181 TimeInfo():time(0.0), stdDev(0.0), count(0), updates(0),
running(false){}
182 TimeInfo(BaseTimer* t): time(t->accumulation_), stdDev(t->
timePerCallStdDev()), count(t->count_started_), updates(t->count_updates_),
running(t->
running()) {}
186 unsigned long long updates;
191 double accumulation_;
192 double accumulationSquared_;
193 unsigned long count_started_;
194 unsigned long long count_updates_;
195 Clock::time_point start_time_;
198 friend struct TimeInfo;
238 std::vector<LevelTimer> sub_timers_;
251 const char* name =
"RootTimer",
253 bool start_timer=
true) :
266 BaseTimer(src), level_(src.level_), name_(src.name_),parent_(src.parent_), sub_timers_(src.sub_timers_)
268 for (
unsigned i=0;i<sub_timers_.size();++i)
269 sub_timers_[i].parent_ =
this;
278 for (
unsigned i=0;i<sub_timers_.size();i++ )
279 if (sub_name == sub_timers_[i].name_ ) {
280 sub_timers_[i].BaseTimer::start();
281 return &sub_timers_[i];
283 sub_timers_.push_back(
LevelTimer(level_+1,sub_name,
this,
true));
284 return &sub_timers_[sub_timers_.size()-1];
296 error_out(
"Stopping timer "+name+
" But top level running timer is "+name_);
307 std::string parent_name(
"");
308 if ((parent_ !=
nullptr))
309 parent_name = parent_->get_full_name() +
"@";
311 std::string my_name(name_);
313 std::string full_name = parent_name + my_name;
317 std::string get_name()
const {
318 std::string my_name(name_);
329 for (
unsigned i=0;i<sub_timers_.size(); ++i)
330 count += sub_timers_[i].countTimers();
335 names[pos++] = get_full_name();
336 for (
unsigned i=0;i<sub_timers_.size(); ++i)
337 sub_timers_[i].addTimerNames(names, pos);
347 if (locate_name ==
"")
350 std::string first_name,second_name;
352 size_t i = locate_name.find_first_of(
'@');
353 if ( i >= locate_name.size() ) {
354 first_name = locate_name;
357 first_name.assign(locate_name,0,i);
358 second_name.assign(locate_name,i+1,locate_name.size()-i-1);
360 for (
unsigned j=0;j<sub_timers_.size();++j)
361 if ( first_name == sub_timers_[j].name_)
362 return sub_timers_[j].accumulatedTime(second_name);
377 void splitString(
const std::string &locate_name, std::string &first_name, std::string &second_name) {
378 size_t i = locate_name.find_first_of(
'@');
379 if ( i >= locate_name.size() ) {
380 first_name = locate_name;
383 first_name.assign(locate_name,0,i);
384 second_name.assign(locate_name,i+1,locate_name.size()-i-1);
396 if (locate_name ==
"")
399 std::string first_name,second_name;
400 splitString(locate_name, first_name, second_name);
402 for (
unsigned j=0;j<sub_timers_.size();j++)
403 if ( first_name == sub_timers_[j].name_)
404 return sub_timers_[j].accumulatedTimePerUpdate(second_name);
415 if (locate_name ==
"")
418 std::string first_name,second_name;
419 splitString(locate_name, first_name, second_name);
421 for (
unsigned j=0;j<sub_timers_.size();j++)
422 if ( first_name == sub_timers_[j].name_)
423 return sub_timers_[j].accumulatedTimePerTimerCall(second_name);
443 void report(std::ostream &os);
450 const BaseTimer* findBaseTimer(
const std::string &name)
const;
458 BaseTimer::TimeInfo findTimer(
const std::string &name,
bool& found);
469 explicit StackedTimer(
const char *name,
const bool start_base_timer =
true)
470 : timer_(0,name,nullptr,false),
471 global_mpi_aggregation_called_(false),
472 enable_verbose_(false),
473 verbose_timestamp_levels_(0),
474 verbose_ostream_(Teuchos::rcpFromRef(std::cout)),
478 if (start_base_timer)
479 this->startBaseTimer();
481 auto check_verbose = std::getenv(
"TEUCHOS_ENABLE_VERBOSE_TIMERS");
482 if (check_verbose !=
nullptr)
483 enable_verbose_ =
true;
485 auto check_timestamp = std::getenv(
"TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
486 if (check_timestamp !=
nullptr) {
487 verbose_timestamp_levels_ = std::atoi(check_timestamp);
492 return timer_.get_full_name();
499 timer_.BaseTimer::start();
500 #ifdef HAVE_TEUCHOSCORE_KOKKOS
501 if (Behavior::fenceTimers()) {
502 Kokkos::fence(
"timer_fence_begin_"+timer_.get_name());
505 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
506 if (push_kokkos_profiling_region) {
507 ::Kokkos::Tools::pushRegion(timer_.get_name());
516 timer_.BaseTimer::stop();
517 #ifdef HAVE_TEUCHOSCORE_KOKKOS
518 if (Behavior::fenceTimers()) {
519 Kokkos::fence(
"timer_fence_end_"+timer_.get_name());
522 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
523 if (pop_kokkos_profiling_region) {
524 ::Kokkos::Tools::popRegion();
535 const bool push_kokkos_profiling_region =
true) {
536 if (enable_timers_) {
537 if (top_ ==
nullptr) {
538 top_ = timer_.start(name.c_str());
540 top_ = top_->start(name.c_str());
541 #ifdef HAVE_TEUCHOSCORE_KOKKOS
542 if (Behavior::fenceTimers()) {
543 Kokkos::fence(
"timer_fence_begin_"+name);
546 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
547 if (push_kokkos_profiling_region) {
548 ::Kokkos::Tools::pushRegion(name);
553 if (enable_verbose_) {
554 if (!verbose_timestamp_levels_) {
555 *verbose_ostream_ <<
"STARTING: " << name << std::endl;
559 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
560 else if (top_ !=
nullptr) {
561 if ( top_->level() <= verbose_timestamp_levels_) {
562 auto now = std::chrono::system_clock::now();
563 auto now_time = std::chrono::system_clock::to_time_t(now);
564 auto gmt = gmtime(&now_time);
565 auto timestamp = std::put_time(gmt,
"%Y-%m-%d %H:%M:%S");
566 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
567 *verbose_ostream_ <<
"STARTING: " << name <<
" LEVEL: " << top_->level() <<
" COUNT: " << timer_.numCalls() <<
" TIMESTAMP: " << timestamp <<
"." << ms.count() << std::endl;
579 void stop(
const std::string &name,
580 const bool pop_kokkos_profiling_region =
true) {
581 if (enable_timers_) {
583 top_ = top_->stop(name);
584 #ifdef HAVE_TEUCHOSCORE_KOKKOS
585 if (Behavior::fenceTimers()) {
586 Kokkos::fence(
"timer_fence_end_"+name);
589 #if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
590 if (pop_kokkos_profiling_region) {
591 ::Kokkos::Tools::popRegion();
595 timer_.BaseTimer::stop();
598 if (enable_verbose_) {
599 if (!verbose_timestamp_levels_) {
600 *verbose_ostream_ <<
"STOPPING: " << name << std::endl;
604 #if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
606 else if (top_ !=
nullptr) {
607 if ( (top_->level()+1) <= verbose_timestamp_levels_) {
608 auto now = std::chrono::system_clock::now();
609 auto now_time = std::chrono::system_clock::to_time_t(now);
610 auto gmt = gmtime(&now_time);
611 auto timestamp = std::put_time(gmt,
"%Y-%m-%d %H:%M:%S");
612 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
613 *verbose_ostream_ <<
"STOPPING: " << name <<
" LEVEL: " << top_->level()+1 <<
" COUNT: " << timer_.numCalls() <<
" TIMESTAMP: " << timestamp <<
"." << ms.count() << std::endl;
625 top_->incrementUpdates(i);
635 return top_->accumulatedTime(name);
637 return timer_.accumulatedTime(name);
647 return top_->accumulatedTimePerUpdate(name);
649 return timer_.accumulatedTimePerUpdate(name);
658 return top_->accumulatedTimePerTimerCall(name);
660 return timer_.accumulatedTimePerTimerCall(name);
669 const BaseTimer* baseTimer = timer_.findBaseTimer(name);
671 "StackedTimer::findBaseTimer() failed to find a timer named \"" << name <<
"\"!\n");
680 BaseTimer::TimeInfo
findTimer(
const std::string &name) {
681 bool foundTimer =
false;
682 const auto timeInfo = timer_.findTimer(name,foundTimer);
684 "StackedTimer::findTimer() failed to find a timer named \"" << name <<
"\"!\n");
688 void report(std::ostream &os) {
707 OutputOptions() : output_fraction(
false), output_total_updates(
false), output_histogram(
false),
708 output_minmax(
false), output_proc_minmax(
false), num_histogram(10), max_levels(INT_MAX),
709 print_warnings(
true), align_columns(
false), print_names_before_values(
true),
710 drop_time(-1.0), output_per_proc_stddev(
false) {}
711 bool output_fraction;
712 bool output_total_updates;
713 bool output_histogram;
715 bool output_proc_minmax;
720 bool print_names_before_values;
722 bool output_per_proc_stddev;
778 void enableVerbose(
const bool enable_verbose);
781 void enableVerboseTimestamps(
const unsigned levels);
788 void disableTimers();
809 double getMpiAverageTime(
const std::string& flat_timer_name);
819 double getMpiAverageCount(
const std::string& flat_timer_name);
829 bool isTimer(
const std::string& flat_timer_name);
851 bool global_mpi_aggregation_called_;
855 std::string::size_type timer_names_;
856 std::string::size_type average_time_;
857 std::string::size_type fraction_;
858 std::string::size_type count_;
859 std::string::size_type total_updates_;
860 std::string::size_type min_;
861 std::string::size_type max_;
862 std::string::size_type procmin_;
863 std::string::size_type procmax_;
864 std::string::size_type stddev_;
865 std::string::size_type histogram_;
910 int getFlatNameIndex(
const std::string& flat_timer_name);
918 double computeColumnWidthsForAligment(std::string prefix,
int print_level,
919 std::vector<bool> &printed,
double parent_time,
925 double printLevel(std::string prefix,
int level, std::ostream &os, std::vector<bool> &printed,
932 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
void stopBaseTimer(const bool pop_kokkos_profiling_region=true)
#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().
void startBaseTimer(const bool push_kokkos_profiling_region=true)
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.
double timePerCallStdDev() const
return the std dev in time per timer start/stop
void setAccumulatedTimeSquared(double accumSq=0)
Setter for squared accumulated time.
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