10#include "Teuchos_StackedTimer.hpp"
24 level_(std::numeric_limits<unsigned>::max()),name_(
"INVALID"),parent_(nullptr)
35 for (
unsigned i=0; i<level_; ++i)
37 os << name_<<
":"<<
accumulatedTime()<<
" [" << count_started_<<
"] ("<< count_updates_ <<
")"<<std::endl;
39 for (
size_t i=0; i<sub_timers_.size(); ++i) {
40 t_total += sub_timers_[i].accumulatedTime();
41 sub_timers_[i].report(os);
43 if ( sub_timers_.size() == 0 )
45 for (
unsigned i=0; i<=level_; ++i)
53 const BaseTimer* t =
nullptr;
58 for (
unsigned i=0;i<sub_timers_.size(); ++i){
59 t = sub_timers_[i].findBaseTimer(name);
69 BaseTimer::TimeInfo t;
71 if (full_name.size() > name.size())
73 if ( strncmp(full_name.c_str(), name.c_str(), full_name.size()))
76 t = BaseTimer::TimeInfo(
this);
80 for (
unsigned i=0;i<sub_timers_.size(); ++i){
81 t = sub_timers_[i].findTimer(name,found);
91 int num_timers =
timer_.countTimers();
92 flat_names_.resize(num_timers);
94 timer_.addTimerNames(flat_names_, pos);
101 flat_names_ = all_names;
107 int num_names = flat_names_.
size();
108 sum_.resize(num_names);
109 count_.resize(num_names);
110 updates_.resize(num_names);
111 active_.resize(num_names);
113 if (options.output_minmax || options.output_histogram || options.output_proc_minmax) {
114 min_.resize(num_names);
115 max_.resize(num_names);
116 if ( options.output_minmax )
117 sum_sq_.resize(num_names);
126 if (options.output_proc_minmax) {
127 procmin_.resize(num_names);
128 procmax_.resize(num_names);
132 if (options.output_histogram ) {
133 hist_.resize(options.num_histogram);
134 for (
int i=0;i<options.num_histogram ; ++i)
135 hist_[i].resize(num_names);
138 if (options.output_per_proc_stddev) {
139 per_proc_stddev_min_.resize(num_names);
140 per_proc_stddev_max_.resize(num_names);
147 if (options.output_total_updates)
148 updates.
resize(num_names);
152 if (options.output_per_proc_stddev)
153 per_proc_stddev.
resize(num_names);
155 if (options.output_histogram)
159 for (
int i=0;i<num_names; ++i) {
161 auto t =
timer_.findTimer(flat_names_[i],found);
164 used[i] = t.count==0? 0:1;
165 if (options.output_total_updates)
166 updates[i] = t.updates;
167 if (options.output_per_proc_stddev)
168 per_proc_stddev[i] = t.stdDev;
178 for (
int i=0;i<num_names;++i)
182 for (
int i=0;i<num_names;++i)
185 if (procmin_.size()) {
188 int commRank = comm->getRank();
189 for (
int i=0;i<num_names; ++i) {
190 if (used[i] && (min_[i]==time[i]))
191 procmin[i] = commRank;
194 if (used[i] && (max_[i]==time[i]))
195 procmax[i] = commRank;
204 if (options.output_histogram) {
205 for (
int i=0;i<num_names; ++i) {
207 double dh = (max_[i]-min_[i])/options.num_histogram;
211 int bin=(time[i]- min_[i])/dh;
212 bins[i] = std::max(std::min(bin,options.num_histogram-1) , 0);
217 for (
int j=0; j<options.num_histogram; ++j){
218 for (
int i=0;i<num_names; ++i) {
228 if (sum_sq_.size()) {
229 for (
int i=0;i<num_names; ++i)
234 if (options.output_per_proc_stddev) {
241std::pair<std::string, std::string> getPrefix(
const std::string &name) {
242 for (std::size_t i=name.size()-1; i>0; --i)
243 if (name[i] ==
'@') {
244 return std::pair<std::string, std::string>(name.substr(0,i), name.substr(i+1));
246 return std::pair<std::string, std::string>(std::string(
""), name);
252 std::vector<bool> &printed,
258 double total_time = 0.0;
260 for (
int i=0; i<flat_names_.size(); ++i ) {
261 if (sum_[i]/active_[i] <= options.drop_time)
265 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
266 if ( (level != print_level) || (level >= options.max_levels) )
268 auto split_names = getPrefix(flat_names_[i]);
269 if ( prefix != split_names.first)
274 std::ostringstream os;
275 for (
int l=0; l<level; ++l)
278 os << split_names.second <<
": ";
279 alignments_.timer_names_= std::max(alignments_.timer_names_,os.str().size());
284 std::ostringstream os;
285 os << sum_[i]/active_[i];
286 alignments_.average_time_ = std::max(alignments_.average_time_,os.str().size());
290 if ( options.output_fraction && parent_time>0) {
291 std::ostringstream os;
292 os <<
" - "<<sum_[i]/active_[i]/parent_time*100<<
"%";
293 alignments_.fraction_ = std::max(alignments_.fraction_,os.str().size());
298 std::ostringstream os;
299 os <<
" ["<<count_[i]/active_[i]<<
"]";
300 alignments_.count_ = std::max(alignments_.count_,os.str().size());
304 if ( options.output_total_updates) {
305 std::ostringstream os;
306 os <<
" ("<<updates_[i]/active_[i]<<
")";
307 alignments_.total_updates_ = std::max(alignments_.total_updates_,os.str().size());
311 if ( options.output_minmax && active_[i]>1) {
313 std::ostringstream os;
314 os <<
" {min=" << min_[i];
315 alignments_.min_ = std::max(alignments_.min_,os.str().size());
318 std::ostringstream os;
319 os <<
", max=" << max_[i];
322 alignments_.max_ = std::max(alignments_.max_,os.str().size());
324 if (procmin_.size()) {
325 std::ostringstream os;
326 os <<
", proc min=" << procmin_[i];
329 alignments_.procmin_ = std::min(alignments_.procmin_,os.str().size());
331 if (procmax_.size()) {
332 std::ostringstream os;
333 os <<
", proc max=" << procmax_[i];
336 alignments_.procmax_ = std::max(alignments_.procmax_,os.str().size());
339 std::ostringstream os;
340 os <<
", std dev=" << sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
342 alignments_.stddev_ = std::max(alignments_.stddev_,os.str().size());
346 if ( options.output_histogram && active_[i] >1 ) {
347 std::ostringstream os;
349 for (
int h=0;h<options.num_histogram; ++h) {
351 os <<
", "<<hist_[h][i];
356 alignments_.histogram_ = std::max(alignments_.histogram_,os.str().size());
364 if (options.print_names_before_values) {
365 std::ostringstream tmp;
366 for (
int l=0; l<=level; ++l)
368 tmp <<
"Remainder: ";
369 alignments_.timer_names_ = std::max(alignments_.timer_names_,tmp.str().size());
372 std::ostringstream tmp;
373 tmp << sum_[i]/active_[i]- sub_time;
374 alignments_.average_time_ = std::max(alignments_.average_time_,tmp.str().size());
376 if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
377 std::ostringstream tmp;
378 tmp <<
" - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 <<
"%";
379 alignments_.fraction_ = std::max(alignments_.fraction_,tmp.str().size());
383 total_time += sum_[i]/active_[i];
396 double total_time = 0.0;
398 for (
int i=0; i<flat_names_.size(); ++i ) {
399 if (sum_[i]/active_[i] <= options.drop_time) {
404 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
405 if ( (level != print_level) || (level >= options.max_levels) )
407 auto split_names = getPrefix(flat_names_[i]);
408 if ( prefix != split_names.first)
412 if (options.print_names_before_values) {
413 std::ostringstream tmp;
414 for (
int l=0; l<level; ++l) {
418 tmp << split_names.second <<
": ";
419 if (options.align_columns)
420 os << std::left << std::setw(alignments_.timer_names_);
425 std::ostringstream tmp;
426 tmp << sum_[i]/active_[i];
427 if (options.align_columns)
428 os << std::left << std::setw(alignments_.average_time_);
432 if ( options.output_fraction && parent_time>0) {
433 std::ostringstream tmp;
434 tmp <<
" - "<<sum_[i]/active_[i]/parent_time*100<<
"%";
435 if (options.align_columns)
436 os << std::left << std::setw(alignments_.fraction_);
440 else if (options.output_fraction) {
441 if (options.align_columns)
442 os << std::setw(alignments_.fraction_) <<
" ";
446 std::ostringstream tmp;
447 tmp <<
" ["<<count_[i]/active_[i]<<
"]";
448 if (options.align_columns)
449 os << std::left << std::setw(alignments_.count_);
453 if ( options.output_total_updates ) {
454 std::ostringstream tmp;
455 tmp <<
" ("<<updates_[i]/active_[i]<<
")";
456 if (options.align_columns)
457 os << std::left << std::setw(alignments_.total_updates_);
461 if ( options.output_minmax && active_[i]>1) {
463 std::ostringstream tmp;
464 tmp <<
" {min="<<min_[i];
465 if (options.align_columns)
466 os << std::left << std::setw(alignments_.min_);
470 std::ostringstream tmp;
471 tmp <<
", max="<<max_[i];
474 if (options.align_columns)
475 os << std::left << std::setw(alignments_.max_);
478 if (procmin_.size()) {
479 std::ostringstream tmp;
480 tmp <<
", proc min="<<procmin_[i];
483 if (options.align_columns)
484 os << std::left << std::setw(alignments_.procmin_);
487 if (procmax_.size()) {
488 std::ostringstream tmp;
489 tmp <<
", proc max="<<procmax_[i];
492 if (options.align_columns)
493 os << std::left << std::setw(alignments_.procmax_);
497 std::ostringstream tmp;
498 tmp <<
", std dev="<<sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
500 if (options.align_columns)
501 os << std::left << std::setw(alignments_.stddev_);
505 else if ( options.output_minmax) {
507 size_t offset = alignments_.min_ + alignments_.max_ + alignments_.stddev_;
508 for (
size_t j=0; j < offset; ++j)
513 if ( options.output_histogram && active_[i] >1 ) {
514 std::ostringstream tmp;
516 for (
int h=0;h<options.num_histogram; ++h) {
518 tmp <<
", "<<hist_[h][i];
523 if (options.align_columns)
524 os << std::left << std::setw(alignments_.histogram_);
527 else if ( options.output_histogram) {
529 for (
size_t j=0; j < alignments_.histogram_; ++j)
533 if (options.output_per_proc_stddev) {
534 std::ostringstream tmp;
535 tmp <<
", std dev per proc min/max=";
536 tmp << per_proc_stddev_min_[i];
538 tmp << per_proc_stddev_max_[i];
542 if (! options.print_names_before_values) {
543 std::ostringstream tmp;
545 for (
int l=0; l<level; ++l) {
549 tmp << split_names.second <<
": ";
555 double sub_time =
printLevel(flat_names_[i], level+1, os, printed, sum_[i]/active_[i], options);
559 if (options.print_names_before_values) {
560 std::ostringstream tmp;
561 for (
int l=0; l<=level; ++l)
563 tmp <<
"Remainder: ";
564 if (options.align_columns)
565 os << std::left << std::setw(alignments_.timer_names_);
569 std::ostringstream tmp;
570 tmp << sum_[i]/active_[i]- sub_time;
571 if (options.align_columns)
572 os << std::left << std::setw(alignments_.average_time_);
575 if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
576 if (options.align_columns)
577 os << std::left << std::setw(alignments_.fraction_);
578 std::ostringstream tmp;
579 tmp <<
" - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 <<
"%";
582 if (! options.print_names_before_values) {
585 offset += alignments_.count_;
586 if (options.output_total_updates)
587 offset += alignments_.total_updates_;
588 if (options.output_minmax)
589 offset += alignments_.min_ + alignments_.max_ + alignments_.stddev_;
590 if (options.output_histogram)
591 offset += alignments_.histogram_;
592 for (
size_t j=0; j < offset; ++j)
595 std::ostringstream tmp;
597 for (
int l=0; l<=level; ++l)
599 tmp <<
"Remainder: ";
600 if (options.align_columns)
601 os << std::left << std::setw(alignments_.timer_names_);
606 total_time += sum_[i]/active_[i];
611static void printXMLEscapedString(std::ostream& os,
const std::string& str)
647StackedTimer::printLevelXML (std::string prefix,
int print_level, std::ostream& os, std::vector<bool> &printed,
double parent_time,
const std::string& rootName)
649 constexpr int indSpaces = 2;
650 int indent = indSpaces * print_level;
652 double total_time = 0.0;
654 for (
int i=0; i<flat_names_.size(); ++i) {
657 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
658 if ( level != print_level)
660 auto split_names = getPrefix(flat_names_[i]);
661 if ( prefix != split_names.first)
664 for (
int j = 0; j < indent; j++)
666 os <<
"<timing name=\"";
667 if(level == 0 && rootName.length())
668 printXMLEscapedString(os, rootName);
670 printXMLEscapedString(os, split_names.second);
671 os <<
"\" value=\"" << sum_[i]/active_[i] <<
"\"";
675 std::ostringstream osInner;
676 double sub_time =
printLevelXML(flat_names_[i], print_level+1, osInner, printed, sum_[i]/active_[i]);
677 std::string innerContents = osInner.str();
678 if(innerContents.length())
684 for (
int j = 0; j < indent + indSpaces; j++)
686 os <<
"<timing name=\"Remainder\" value=\"" << (sum_[i]/active_[i] - sub_time) <<
"\"/>\n";
689 for (
int j = 0; j < indent; j++)
698 total_time += sum_[i]/active_[i];
706 if (
rank(*comm) == 0 ) {
707 if (options.print_warnings) {
708 os <<
"*** Teuchos::StackedTimer::report() - Remainder for a level will be ***"
709 <<
"\n*** incorrect if a timer in the level does not exist on every rank ***"
710 <<
"\n*** of the MPI Communicator. ***"
713 if ( (options.max_levels != INT_MAX) && options.print_warnings) {
714 os <<
"Teuchos::StackedTimer::report() - max_levels manually set to " << options.max_levels
715 <<
". \nTo print more levels, increase value of OutputOptions::max_levels." << std::endl;
717 if ( (! options.print_names_before_values) && (! options.align_columns)) {
718 options.align_columns =
true;
719 if (options.print_warnings)
720 os <<
"Teuchos::StackedTimer::report() - option print_names_before_values=false "
721 <<
"\nrequires that the option align_columns=true too. Setting the value for "
722 <<
"\nalign_column to true."
725 if (options.align_columns) {
726 std::vector<bool> printed(flat_names_.size(),
false);
730 std::vector<bool> printed(flat_names_.size(),
false);
740 if (
rank(*comm) == 0 ) {
741 std::vector<bool> printed(flat_names_.size(),
false);
742 os <<
"<?xml version=\"1.0\"?>\n";
743 os <<
"<performance-report date=\"" << timestamp <<
"\" name=\"nightly_run_" << datestamp <<
"\" time-units=\"seconds\">\n";
745 os <<
"</performance-report>\n";
751 const char* rawWatchrDir = getenv(
"WATCHR_PERF_DIR");
752 const char* rawBuildName = getenv(
"WATCHR_BUILD_NAME");
753 const char* rawGitSHA = getenv(
"TRILINOS_GIT_SHA");
754 const char* rawBuildDateOverride = getenv(
"WATCHR_BUILD_DATE");
758 std::string watchrDir = rawWatchrDir;
759 if(!watchrDir.length())
765 std::string buildName = rawBuildName ? rawBuildName :
"";
766 std::string datestamp;
767 std::string timestamp;
773 tstruct = gmtime(&t);
774 if(rawBuildDateOverride)
777 int year = 0, month = 0, day = 0;
778 sscanf(rawBuildDateOverride,
"%d_%d_%d", &year, &month, &day);
780 if(year <= 2000 || year > 2100)
781 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid year or is not in YYYY_MM_DD format.");
782 if(month < 1 || month > 12)
783 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid month or is not in YYYY_MM_DD format.");
784 if(day < 1 || day > 31)
785 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid day or is not in YYYY_MM_DD format.");
786 snprintf(buf, 256,
"%04d_%02d_%02d", year, month, day);
788 strftime(buf, 256,
"T%H:%M:%S", tstruct);
789 std::string justTime = buf;
790 snprintf(buf, 256,
"%04d-%02d-%02d", year, month, day);
791 timestamp = std::string(buf) + justTime;
795 strftime(buf, 256,
"%Y_%m_%d", tstruct);
797 strftime(buf, 256,
"%FT%H:%M:%S", tstruct);
803 std::string fullFile;
805 if(
rank(*comm) == 0) {
806 std::string nameNoSpaces = name;
807 for(
char& c : nameNoSpaces)
812 if(buildName.length())
815 std::string buildNameNoSpaces = buildName;
816 for(
char& c : buildNameNoSpaces)
821 fullFile = watchrDir +
'/' + buildNameNoSpaces +
"-" + nameNoSpaces +
'_' + datestamp +
".xml";
824 fullFile = watchrDir +
'/' + nameNoSpaces +
'_' + datestamp +
".xml";
825 std::ofstream os(fullFile);
826 std::vector<bool> printed(flat_names_.size(),
false);
827 os <<
"<?xml version=\"1.0\"?>\n";
828 os <<
"<performance-report date=\"" << timestamp <<
"\" name=\"nightly_run_" << datestamp <<
"\" time-units=\"seconds\">\n";
831 std::string gitSHA(rawGitSHA);
833 if(gitSHA.length() > 10)
834 gitSHA = gitSHA.substr(0, 10);
835 os <<
" <metadata key=\"Trilinos Version\" value=\"" << gitSHA <<
"\"/>\n";
837 auto systemInfo = SystemInformation::collectSystemInformation();
838 for (
const auto &e : systemInfo) {
839 os <<
" <metadata key=\"" << e.first <<
"\" value=\"";
840 printXMLEscapedString(os, e.second);
843 printLevelXML(
"", 0, os, printed, 0.0, buildName +
": " + name);
844 os <<
"</performance-report>\n";
869 global_mpi_aggregation_called_ =
true;
875 return sum_[i] / active_[i];
881 return static_cast<double>(count_[i]) /
static_cast<double>(active_[i]);
887 "ERROR: StackedTimer::getAverageMpiTime() - must call aggregateMpiData() first!");
889 auto search = std::find(flat_names_.begin(),flat_names_.end(),flat_timer_name);
892 "ERROR: StackedTimer::getAverageMpiTime() - the timer named \""
893 << flat_timer_name <<
"\" does not exist!");
895 auto i = std::distance(flat_names_.begin(),search);
896 return static_cast<int>(i);
902 "ERROR: StackedTimer::isTimer() - must call aggregateMpiData() before using this query!");
904 auto search = std::find(flat_names_.begin(),flat_names_.end(),flat_timer_name);
905 return (search == flat_names_.end()) ? false :
true;
910 std::stack<std::string> timer_names;
912 while (
top_->level() > 0) {
913 const std::string name =
top_->get_name();
914 timer_names.push(name);
920 timer_names.push(
timer_.get_name());
929 bool first_timer =
true;
930 while (timers_to_start.size() > 0) {
938 this->
start(timers_to_start.top());
941 timers_to_start.pop();
Replacement for std::vector that is compatible with the Teuchos Memory Management classes.
T * getRawPtr()
Return a raw pointer to beginning of array or NULL if unsized.
void resize(size_type new_size, const value_type &x=value_type())
The basic timer used internally, uses std::chrono::high_resolution_clock.
Abstract interface for distributed-memory communication.
void reduce(const Packet sendBuf[], Packet recvBuf[], const Ordinal count, const EReductionType reductType, const Ordinal root, const Comm< Ordinal > &comm)
Wrapper for MPI_Reduce; reduction to one process, using a built-in reduction operator selected by enu...
int rank(const Comm< Ordinal > &comm)
Get the process rank.
void reduceAll(const Comm< Ordinal > &comm, const ValueTypeReductionOp< Ordinal, Packet > &reductOp, const Ordinal count, const Packet sendBuffer[], Packet globalReducts[])
Wrapper for MPI_Allreduce that takes a custom reduction operator.
Smart reference counting pointer class for automatic garbage collection.
void report(std::ostream &os)
BaseTimer::TimeInfo findTimer(const std::string &name, bool &found)
const BaseTimer * findBaseTimer(const std::string &name) const
LevelTimer()
Default constructor, shouldn't be used but needed for std::vector.
std::string get_full_name() const
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)
double getMpiAverageTime(const std::string &flat_timer_name)
void start(const std::string name, const bool push_kokkos_profiling_region=true)
void stop(const std::string &name, const bool pop_kokkos_profiling_region=true)
void startBaseTimer(const bool push_kokkos_profiling_region=true)
void stopBaseTimer(const bool pop_kokkos_profiling_region=true)
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.
void startTimers(std::stack< std::string > timers_to_start)
int getFlatNameIndex(const std::string &flat_timer_name)
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...
void aggregateMpiData(Teuchos::RCP< const Teuchos::Comm< int > > comm, OutputOptions options=OutputOptions())
std::stack< std::string > stopAllTimers()
void merge(Teuchos::RCP< const Teuchos::Comm< int > > comm)
bool isTimer(const std::string &flat_timer_name)
double printLevel(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
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)
double getMpiAverageCount(const std::string &flat_timer_name)
void reportXML(std::ostream &os, const std::string &datestamp, const std::string ×tamp, Teuchos::RCP< const Teuchos::Comm< int > > comm)
#define TEUCHOS_ASSERT(assertion_test)
This macro is throws when an assert fails.
#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 mergeCounterNames(const Comm< int > &comm, const Array< std::string > &localNames, Array< std::string > &globalNames, const ECounterSetOp setOp)
Merge counter names over all processors.
void error_out(const std::string &msg, const bool)
Error reporting function for stacked timer.