Teuchos - Trilinos Tools Package Version of the Day
Loading...
Searching...
No Matches
Teuchos_StackedTimer.hpp
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
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)
60namespace Kokkos {
61namespace Profiling {
62extern void pushRegion (const std::string&);
63extern void popRegion ();
64} // namespace Profiling
65} // namespace Kokkos
66#endif
67
68
69namespace Teuchos {
70
72void error_out(const std::string& msg, const bool fail_all = false);
73
83class BaseTimer {
84
85public:
86
87 using Clock = std::chrono::high_resolution_clock;
88
89 BaseTimer() : accumulation_(0.0), count_started_(0), count_updates_(0), running_(false) {}
90
92 void start(){
93 if (running_)
94 error_out("Base_Timer:start Failed timer already running");
95 start_time_ = Clock::now();
96
97 count_started_++;
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) {
128 return accumulation_/count_updates_;
129 } else {
130 return 0;
131 }
132 }
133
134
143 if (count_started_> 0) {
144 return accumulation_/count_started_;
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;
165 count_started_ = count_updates_ = 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){}
187 TimeInfo(BaseTimer* t): time(t->accumulation_), count(t->count_started_), updates(t->count_updates_), running(t->running()) {}
188 double time;
189 unsigned long count;
190 unsigned long long updates;
191 bool running;
192 };
193
194protected:
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{
223protected:
224
233 class LevelTimer : public BaseTimer {
234 protected:
235
236 // TODO: implement operator=
237
238 unsigned level_;
239 std::string name_;
240 LevelTimer *parent_;
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) :
269 BaseTimer(src), level_(src.level_), name_(src.name_),parent_(src.parent_), sub_timers_(src.sub_timers_)
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_);
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
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
466public:
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
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
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) {
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
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
678 OutputOptions() : output_fraction(false), output_total_updates(false), output_histogram(false),
679 output_minmax(false), output_proc_minmax(false), num_histogram(10), max_levels(INT_MAX),
680 print_warnings(true), align_columns(false), print_names_before_values(true),
681 drop_time(-1.0) {}
682 bool output_fraction;
683 bool output_total_updates;
684 bool output_histogram;
685 bool output_minmax;
686 bool output_proc_minmax;
687 int num_histogram;
688 int max_levels;
689 bool print_warnings;
690 bool align_columns;
691 bool print_names_before_values;
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
744 std::string reportWatchrXML(const std::string& name, Teuchos::RCP<const Teuchos::Comm<int> > comm);
745
747 void enableVerbose(const bool enable_verbose);
748
750 void enableVerboseTimestamps(const unsigned levels);
751
754
757 void disableTimers();
758
761 void enableTimers();
762
763protected:
768
769 Array<std::string> flat_names_;
770 Array<double> min_;
771 Array<double> max_;
772 Array<int> procmin_;
773 Array<int> procmax_;
774 Array<double> sum_;
775 Array<double> sum_sq_;
776 Array<Array<int>> hist_;
779 Array<int> active_;
780
783 std::string::size_type timer_names_;
784 std::string::size_type average_time_;
785 std::string::size_type fraction_;
786 std::string::size_type count_;
787 std::string::size_type total_updates_;
788 std::string::size_type min_;
789 std::string::size_type max_;
790 std::string::size_type procmin_;
791 std::string::size_type procmax_;
792 std::string::size_type stddev_;
793 std::string::size_type histogram_;
795 timer_names_(0),
796 average_time_(0),
797 fraction_(0),
798 count_(0),
799 total_updates_(0),
800 min_(0),
801 max_(0),
802 procmax_(0),
803 stddev_(0),
804 histogram_(0){}
805 } alignments_;
806
809
812
815
818
822 void flatten();
823
828 void merge(Teuchos::RCP<const Teuchos::Comm<int> > comm);
829
833 void collectRemoteData(Teuchos::RCP<const Teuchos::Comm<int> > comm, const OutputOptions &options );
834
841 double computeColumnWidthsForAligment(std::string prefix, int print_level,
842 std::vector<bool> &printed, double parent_time,
843 const OutputOptions &options);
844
848 double printLevel(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed,
849 double parent_time, const OutputOptions &options);
850
855 double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed, double parent_time, const std::string& rootName = "");
856
857}; //StackedTimer
858
859
860} //namespace Teuchos
861
862#endif /* TEUCHOS_STACKED_TIMER_HPP */
Templated array class derived from the STL std::vector.
Teuchos header file which uses auto-configuration information to include necessary C++ headers.
Common capabilities for collecting and reporting performance data collectively across MPI processes.
Reference-counted pointer class and non-member templated function implementations.
Replacement for std::vector that is compatible with the Teuchos Memory Management classes.
the basic timer used elsewhere, uses MPI_Wtime for time
void setAccumulatedTime(double accum=0)
Setter for accumulated time.
double difference(const BaseTimer &from) const
Return the difference between two timers in seconds,.
void reset()
Reset all the timer stats, throws if it is already running.
void start()
Start a currently stopped timer.
double accumulatedTimePerTimerCall() const
return the average time per timer start/stop
double accumulatedTimePerUpdate() const
return the average time per item updated
void stop()
Stop a current running timer and accumulate time difference.
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 overrideNumCallsForUnitTesting(const unsigned long num_calls)
Sets the number of calls to start() for this timer. This is only used for unit testing.
unsigned long long numUpdates() const
Returns the number of updates added to this timer.
unsigned long numCalls() const
Returns the number of calls to start().
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.
Abstract interface for distributed-memory communication.
Smart reference counting pointer class for automatic garbage collection.
Timer info at a given level and all the children.
double accumulatedTime(const std::string &locate_name="")
LevelTimer * start(const char *sub_name)
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
double accumulatedTimePerTimerCall(const std::string &locate_name="")
LevelTimer(const LevelTimer &src)
Copy constructor.
BaseTimer::TimeInfo findTimer(const std::string &name, bool &found)
const BaseTimer * findBaseTimer(const std::string &name) const
LevelTimer * stop(const std::string &name="RootTimer")
unsigned level() const
Returns the level of the timer in the stack.
LevelTimer()
Default constructor, shouldn't be used but needed for std::vector.
double accumulatedTimePerUpdate(const std::string &locate_name="")
LevelTimer * unpack(unsigned from)
LevelTimer(int level, const char *name="RootTimer", LevelTimer *parent=nullptr, bool start_timer=true)
This class allows one to push and pop timers on and off a stack.
LevelTimer * top_
Current level running.
double computeColumnWidthsForAligment(std::string prefix, int print_level, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
void collectRemoteData(Teuchos::RCP< const Teuchos::Comm< int > > comm, const OutputOptions &options)
void start(const std::string name, const bool push_kokkos_profiling_region=true)
BaseTimer::TimeInfo findTimer(const std::string &name)
void stop(const std::string &name, const bool pop_kokkos_profiling_region=true)
const BaseTimer * findBaseTimer(const std::string &name) const
Teuchos::RCP< std::ostream > verbose_ostream_
For debugging, this is the ostream used for printing.
double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const std::string &rootName="")
void enableVerboseTimestamps(const unsigned levels)
Enable timestamps in verbose mode for the number of levels specified.
double accumulatedTimePerUpdate(const std::string &name="")
void incrementUpdates(const long long i=1)
void setVerboseOstream(const Teuchos::RCP< std::ostream > &os)
Set the ostream for verbose mode(defaults to std::cout).
bool enable_timers_
Used to disable timers for asynchronous work.
unsigned verbose_timestamp_levels_
If set to a value greater than 0, verbose mode will print that many levels of timers with timestamps....
double accumulatedTime(const std::string &name="")
LevelTimer timer_
Base timer.
bool enable_verbose_
If set to true, prints to the debug ostream. At construction, default value is set from environment v...
double accumulatedTimePerTimerCall(const std::string &name="")
void merge(Teuchos::RCP< const Teuchos::Comm< int > > comm)
double printLevel(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
StackedTimer(const char *name, const bool start_base_timer=true)
void enableVerbose(const bool enable_verbose)
If set to true, print timer start/stop to verbose ostream.
std::string reportWatchrXML(const std::string &name, Teuchos::RCP< const Teuchos::Comm< int > > comm)
void reportXML(std::ostream &os, const std::string &datestamp, const std::string &timestamp, 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.
The Teuchos namespace contains all of the classes, structs and enums used by Teuchos,...
void error_out(const std::string &msg, const bool)
Error reporting function for stacked timer.
Stores the column widths for output alignment.