10#include "Teuchos_StackedTimer.hpp"
20#include "Trilinos_git_sha.h"
27 level_(std::numeric_limits<unsigned>::max()),name_(
"INVALID"),parent_(nullptr)
38 for (
unsigned i=0; i<level_; ++i)
40 os << name_<<
":"<<
accumulatedTime()<<
" [" << count_started_<<
"] ("<< count_updates_ <<
")"<<std::endl;
42 for (
size_t i=0; i<sub_timers_.size(); ++i) {
43 t_total += sub_timers_[i].accumulatedTime();
44 sub_timers_[i].report(os);
46 if ( sub_timers_.size() == 0 )
48 for (
unsigned i=0; i<=level_; ++i)
56 const BaseTimer* t =
nullptr;
61 for (
unsigned i=0;i<sub_timers_.size(); ++i){
62 t = sub_timers_[i].findBaseTimer(name);
72 BaseTimer::TimeInfo t;
74 if (full_name.size() > name.size())
76 if ( strncmp(full_name.c_str(), name.c_str(), full_name.size()))
79 t = BaseTimer::TimeInfo(
this);
83 for (
unsigned i=0;i<sub_timers_.size(); ++i){
84 t = sub_timers_[i].findTimer(name,found);
94 int num_timers =
timer_.countTimers();
95 flat_names_.resize(num_timers);
97 timer_.addTimerNames(flat_names_, pos);
104 flat_names_ = all_names;
110 int num_names = flat_names_.
size();
111 sum_.resize(num_names);
112 count_.resize(num_names);
113 updates_.resize(num_names);
114 active_.resize(num_names);
116 if (options.output_minmax || options.output_histogram || options.output_proc_minmax) {
117 min_.resize(num_names);
118 max_.resize(num_names);
119 if ( options.output_minmax )
120 sum_sq_.resize(num_names);
129 if (options.output_proc_minmax) {
130 procmin_.resize(num_names);
131 procmax_.resize(num_names);
135 if (options.output_histogram ) {
136 hist_.resize(options.num_histogram);
137 for (
int i=0;i<options.num_histogram ; ++i)
138 hist_[i].resize(num_names);
141 if (options.output_per_proc_stddev) {
142 per_proc_stddev_min_.resize(num_names);
143 per_proc_stddev_max_.resize(num_names);
150 if (options.output_total_updates)
151 updates.
resize(num_names);
155 if (options.output_per_proc_stddev)
156 per_proc_stddev.
resize(num_names);
158 if (options.output_histogram)
162 for (
int i=0;i<num_names; ++i) {
164 auto t =
timer_.findTimer(flat_names_[i],found);
167 used[i] = t.count==0? 0:1;
168 if (options.output_total_updates)
169 updates[i] = t.updates;
170 if (options.output_per_proc_stddev)
171 per_proc_stddev[i] = t.stdDev;
181 for (
int i=0;i<num_names;++i)
185 for (
int i=0;i<num_names;++i)
188 if (procmin_.size()) {
191 int commRank = comm->getRank();
192 for (
int i=0;i<num_names; ++i) {
193 if (used[i] && (min_[i]==time[i]))
194 procmin[i] = commRank;
197 if (used[i] && (max_[i]==time[i]))
198 procmax[i] = commRank;
207 if (options.output_histogram) {
208 for (
int i=0;i<num_names; ++i) {
210 double dh = (max_[i]-min_[i])/options.num_histogram;
214 int bin=(time[i]- min_[i])/dh;
215 bins[i] = std::max(std::min(bin,options.num_histogram-1) , 0);
220 for (
int j=0; j<options.num_histogram; ++j){
221 for (
int i=0;i<num_names; ++i) {
231 if (sum_sq_.size()) {
232 for (
int i=0;i<num_names; ++i)
237 if (options.output_per_proc_stddev) {
244std::pair<std::string, std::string> getPrefix(
const std::string &name) {
245 for (std::size_t i=name.size()-1; i>0; --i)
246 if (name[i] ==
'@') {
247 return std::pair<std::string, std::string>(name.substr(0,i), name.substr(i+1));
249 return std::pair<std::string, std::string>(std::string(
""), name);
255 std::vector<bool> &printed,
261 double total_time = 0.0;
263 for (
int i=0; i<flat_names_.size(); ++i ) {
264 if (sum_[i]/active_[i] <= options.drop_time)
268 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
269 if ( (level != print_level) || (level >= options.max_levels) )
271 auto split_names = getPrefix(flat_names_[i]);
272 if ( prefix != split_names.first)
277 std::ostringstream os;
278 for (
int l=0; l<level; ++l)
281 os << split_names.second <<
": ";
282 alignments_.timer_names_= std::max(alignments_.timer_names_,os.str().size());
287 std::ostringstream os;
288 os << sum_[i]/active_[i];
289 alignments_.average_time_ = std::max(alignments_.average_time_,os.str().size());
293 if ( options.output_fraction && parent_time>0) {
294 std::ostringstream os;
295 os <<
" - "<<sum_[i]/active_[i]/parent_time*100<<
"%";
296 alignments_.fraction_ = std::max(alignments_.fraction_,os.str().size());
301 std::ostringstream os;
302 os <<
" ["<<count_[i]/active_[i]<<
"]";
303 alignments_.count_ = std::max(alignments_.count_,os.str().size());
307 if ( options.output_total_updates) {
308 std::ostringstream os;
309 os <<
" ("<<updates_[i]/active_[i]<<
")";
310 alignments_.total_updates_ = std::max(alignments_.total_updates_,os.str().size());
314 if ( options.output_minmax && active_[i]>1) {
316 std::ostringstream os;
317 os <<
" {min=" << min_[i];
318 alignments_.min_ = std::max(alignments_.min_,os.str().size());
321 std::ostringstream os;
322 os <<
", max=" << max_[i];
325 alignments_.max_ = std::max(alignments_.max_,os.str().size());
327 if (procmin_.size()) {
328 std::ostringstream os;
329 os <<
", proc min=" << procmin_[i];
332 alignments_.procmin_ = std::min(alignments_.procmin_,os.str().size());
334 if (procmax_.size()) {
335 std::ostringstream os;
336 os <<
", proc max=" << procmax_[i];
339 alignments_.procmax_ = std::max(alignments_.procmax_,os.str().size());
342 std::ostringstream os;
343 os <<
", std dev=" << sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
345 alignments_.stddev_ = std::max(alignments_.stddev_,os.str().size());
349 if ( options.output_histogram && active_[i] >1 ) {
350 std::ostringstream os;
352 for (
int h=0;h<options.num_histogram; ++h) {
354 os <<
", "<<hist_[h][i];
359 alignments_.histogram_ = std::max(alignments_.histogram_,os.str().size());
367 if (options.print_names_before_values) {
368 std::ostringstream tmp;
369 for (
int l=0; l<=level; ++l)
371 tmp <<
"Remainder: ";
372 alignments_.timer_names_ = std::max(alignments_.timer_names_,tmp.str().size());
375 std::ostringstream tmp;
376 tmp << sum_[i]/active_[i]- sub_time;
377 alignments_.average_time_ = std::max(alignments_.average_time_,tmp.str().size());
379 if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
380 std::ostringstream tmp;
381 tmp <<
" - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 <<
"%";
382 alignments_.fraction_ = std::max(alignments_.fraction_,tmp.str().size());
386 total_time += sum_[i]/active_[i];
399 double total_time = 0.0;
401 for (
int i=0; i<flat_names_.size(); ++i ) {
402 if (sum_[i]/active_[i] <= options.drop_time) {
407 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
408 if ( (level != print_level) || (level >= options.max_levels) )
410 auto split_names = getPrefix(flat_names_[i]);
411 if ( prefix != split_names.first)
415 if (options.print_names_before_values) {
416 std::ostringstream tmp;
417 for (
int l=0; l<level; ++l) {
421 tmp << split_names.second <<
": ";
422 if (options.align_columns)
423 os << std::left << std::setw(alignments_.timer_names_);
428 std::ostringstream tmp;
429 tmp << sum_[i]/active_[i];
430 if (options.align_columns)
431 os << std::left << std::setw(alignments_.average_time_);
435 if ( options.output_fraction && parent_time>0) {
436 std::ostringstream tmp;
437 tmp <<
" - "<<sum_[i]/active_[i]/parent_time*100<<
"%";
438 if (options.align_columns)
439 os << std::left << std::setw(alignments_.fraction_);
443 else if (options.output_fraction) {
444 if (options.align_columns)
445 os << std::setw(alignments_.fraction_) <<
" ";
449 std::ostringstream tmp;
450 tmp <<
" ["<<count_[i]/active_[i]<<
"]";
451 if (options.align_columns)
452 os << std::left << std::setw(alignments_.count_);
456 if ( options.output_total_updates ) {
457 std::ostringstream tmp;
458 tmp <<
" ("<<updates_[i]/active_[i]<<
")";
459 if (options.align_columns)
460 os << std::left << std::setw(alignments_.total_updates_);
464 if ( options.output_minmax && active_[i]>1) {
466 std::ostringstream tmp;
467 tmp <<
" {min="<<min_[i];
468 if (options.align_columns)
469 os << std::left << std::setw(alignments_.min_);
473 std::ostringstream tmp;
474 tmp <<
", max="<<max_[i];
477 if (options.align_columns)
478 os << std::left << std::setw(alignments_.max_);
481 if (procmin_.size()) {
482 std::ostringstream tmp;
483 tmp <<
", proc min="<<procmin_[i];
486 if (options.align_columns)
487 os << std::left << std::setw(alignments_.procmin_);
490 if (procmax_.size()) {
491 std::ostringstream tmp;
492 tmp <<
", proc max="<<procmax_[i];
495 if (options.align_columns)
496 os << std::left << std::setw(alignments_.procmax_);
500 std::ostringstream tmp;
501 tmp <<
", std dev="<<sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
503 if (options.align_columns)
504 os << std::left << std::setw(alignments_.stddev_);
508 else if ( options.output_minmax) {
510 size_t offset = alignments_.min_ + alignments_.max_ + alignments_.stddev_;
511 for (
size_t j=0; j < offset; ++j)
516 if ( options.output_histogram && active_[i] >1 ) {
517 std::ostringstream tmp;
519 for (
int h=0;h<options.num_histogram; ++h) {
521 tmp <<
", "<<hist_[h][i];
526 if (options.align_columns)
527 os << std::left << std::setw(alignments_.histogram_);
530 else if ( options.output_histogram) {
532 for (
size_t j=0; j < alignments_.histogram_; ++j)
536 if (options.output_per_proc_stddev) {
537 std::ostringstream tmp;
538 tmp <<
", std dev per proc min/max=";
539 tmp << per_proc_stddev_min_[i];
541 tmp << per_proc_stddev_max_[i];
545 if (! options.print_names_before_values) {
546 std::ostringstream tmp;
548 for (
int l=0; l<level; ++l) {
552 tmp << split_names.second <<
": ";
558 double sub_time =
printLevel(flat_names_[i], level+1, os, printed, sum_[i]/active_[i], options);
562 if (options.print_names_before_values) {
563 std::ostringstream tmp;
564 for (
int l=0; l<=level; ++l)
566 tmp <<
"Remainder: ";
567 if (options.align_columns)
568 os << std::left << std::setw(alignments_.timer_names_);
572 std::ostringstream tmp;
573 tmp << sum_[i]/active_[i]- sub_time;
574 if (options.align_columns)
575 os << std::left << std::setw(alignments_.average_time_);
578 if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
579 if (options.align_columns)
580 os << std::left << std::setw(alignments_.fraction_);
581 std::ostringstream tmp;
582 tmp <<
" - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 <<
"%";
585 if (! options.print_names_before_values) {
588 offset += alignments_.count_;
589 if (options.output_total_updates)
590 offset += alignments_.total_updates_;
591 if (options.output_minmax)
592 offset += alignments_.min_ + alignments_.max_ + alignments_.stddev_;
593 if (options.output_histogram)
594 offset += alignments_.histogram_;
595 for (
size_t j=0; j < offset; ++j)
598 std::ostringstream tmp;
600 for (
int l=0; l<=level; ++l)
602 tmp <<
"Remainder: ";
603 if (options.align_columns)
604 os << std::left << std::setw(alignments_.timer_names_);
609 total_time += sum_[i]/active_[i];
614static void printXMLEscapedString(std::ostream& os,
const std::string& str)
650StackedTimer::printLevelXML (std::string prefix,
int print_level, std::ostream& os, std::vector<bool> &printed,
double parent_time,
const std::string& rootName)
652 constexpr int indSpaces = 2;
653 int indent = indSpaces * print_level;
655 double total_time = 0.0;
657 for (
int i=0; i<flat_names_.size(); ++i) {
660 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
661 if ( level != print_level)
663 auto split_names = getPrefix(flat_names_[i]);
664 if ( prefix != split_names.first)
667 for (
int j = 0; j < indent; j++)
669 os <<
"<timing name=\"";
670 if(level == 0 && rootName.length())
671 printXMLEscapedString(os, rootName);
673 printXMLEscapedString(os, split_names.second);
674 os <<
"\" value=\"" << sum_[i]/active_[i] <<
"\"";
678 std::ostringstream osInner;
679 double sub_time =
printLevelXML(flat_names_[i], print_level+1, osInner, printed, sum_[i]/active_[i]);
680 std::string innerContents = osInner.str();
681 if(innerContents.length())
687 for (
int j = 0; j < indent + indSpaces; j++)
689 os <<
"<timing name=\"Remainder\" value=\"" << (sum_[i]/active_[i] - sub_time) <<
"\"/>\n";
692 for (
int j = 0; j < indent; j++)
701 total_time += sum_[i]/active_[i];
709 if (
rank(*comm) == 0 ) {
710 if (options.print_warnings) {
711 os <<
"*** Teuchos::StackedTimer::report() - Remainder for a level will be ***"
712 <<
"\n*** incorrect if a timer in the level does not exist on every rank ***"
713 <<
"\n*** of the MPI Communicator. ***"
716 if ( (options.max_levels != INT_MAX) && options.print_warnings) {
717 os <<
"Teuchos::StackedTimer::report() - max_levels manually set to " << options.max_levels
718 <<
". \nTo print more levels, increase value of OutputOptions::max_levels." << std::endl;
720 if ( (! options.print_names_before_values) && (! options.align_columns)) {
721 options.align_columns =
true;
722 if (options.print_warnings)
723 os <<
"Teuchos::StackedTimer::report() - option print_names_before_values=false "
724 <<
"\nrequires that the option align_columns=true too. Setting the value for "
725 <<
"\nalign_column to true."
728 if (options.align_columns) {
729 std::vector<bool> printed(flat_names_.size(),
false);
733 std::vector<bool> printed(flat_names_.size(),
false);
743 if (
rank(*comm) == 0 ) {
744 std::vector<bool> printed(flat_names_.size(),
false);
745 os <<
"<?xml version=\"1.0\"?>\n";
746 os <<
"<performance-report date=\"" << timestamp <<
"\" name=\"nightly_run_" << datestamp <<
"\" time-units=\"seconds\">\n";
748 os <<
"</performance-report>\n";
756 std::string gitSHA(Trilinos::TRILINOS_GIT_SHA);
761 std::string watchrDir = rawWatchrDir;
762 if(!watchrDir.length())
768 std::string buildName = rawBuildName ? rawBuildName :
"";
769 std::string datestamp;
770 std::string timestamp;
776 tstruct = gmtime(&t);
777 if(rawBuildDateOverride)
780 int year = 0, month = 0, day = 0;
781 sscanf(rawBuildDateOverride,
"%d_%d_%d", &year, &month, &day);
783 if(year <= 2000 || year > 2100)
784 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid year or is not in YYYY_MM_DD format.");
785 if(month < 1 || month > 12)
786 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid month or is not in YYYY_MM_DD format.");
787 if(day < 1 || day > 31)
788 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid day or is not in YYYY_MM_DD format.");
789 snprintf(buf, 256,
"%04d_%02d_%02d", year, month, day);
791 strftime(buf, 256,
"T%H:%M:%S", tstruct);
792 std::string justTime = buf;
793 snprintf(buf, 256,
"%04d-%02d-%02d", year, month, day);
794 timestamp = std::string(buf) + justTime;
798 strftime(buf, 256,
"%Y_%m_%d", tstruct);
800 strftime(buf, 256,
"%FT%H:%M:%S", tstruct);
806 std::string fullFile;
808 if(
rank(*comm) == 0) {
809 std::string nameNoSpaces = name;
810 for(
char& c : nameNoSpaces)
815 if(buildName.length())
818 std::string buildNameNoSpaces = buildName;
819 for(
char& c : buildNameNoSpaces)
824 fullFile = watchrDir +
'/' + buildNameNoSpaces +
"-" + nameNoSpaces +
'_' + datestamp +
".xml";
827 fullFile = watchrDir +
'/' + nameNoSpaces +
'_' + datestamp +
".xml";
828 std::ofstream os(fullFile);
829 std::vector<bool> printed(flat_names_.size(),
false);
830 os <<
"<?xml version=\"1.0\"?>\n";
831 os <<
"<performance-report date=\"" << timestamp <<
"\" name=\"nightly_run_" << datestamp <<
"\" time-units=\"seconds\">\n";
832 if(gitSHA !=
"UNDEFINED")
834 os <<
" <metadata key=\"Trilinos Version\" value=\"" << gitSHA <<
"\"/>\n";
836 auto systemInfo = SystemInformation::collectSystemInformation();
837 for (
const auto &e : systemInfo) {
838 os <<
" <metadata key=\"" << e.first <<
"\" value=\"";
839 printXMLEscapedString(os, e.second);
842 printLevelXML(
"", 0, os, printed, 0.0, buildName +
": " + name);
843 os <<
"</performance-report>\n";
868 global_mpi_aggregation_called_ =
true;
874 return sum_[i] / active_[i];
880 return static_cast<double>(count_[i]) /
static_cast<double>(active_[i]);
886 "ERROR: StackedTimer::getAverageMpiTime() - must call aggregateMpiData() first!");
888 auto search = std::find(flat_names_.begin(),flat_names_.end(),flat_timer_name);
891 "ERROR: StackedTimer::getAverageMpiTime() - the timer named \""
892 << flat_timer_name <<
"\" does not exist!");
894 auto i = std::distance(flat_names_.begin(),search);
895 return static_cast<int>(i);
901 "ERROR: StackedTimer::isTimer() - must call aggregateMpiData() before using this query!");
903 auto search = std::find(flat_names_.begin(),flat_names_.end(),flat_timer_name);
904 return (search == flat_names_.end()) ? false :
true;
909 std::stack<std::string> timer_names;
911 while (
top_->level() > 0) {
912 const std::string name =
top_->get_name();
913 timer_names.push(name);
919 timer_names.push(
timer_.get_name());
928 bool first_timer =
true;
929 while (timers_to_start.size() > 0) {
937 this->
start(timers_to_start.top());
940 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.
const char * getEnvironmentVariableValue(const char name[])
Read a process environment variable by name.
void error_out(const std::string &msg, const bool)
Error reporting function for stacked timer.