40 #include "Teuchos_StackedTimer.hpp"
53 level_(std::numeric_limits<unsigned>::max()),name_(
"INVALID"),parent_(nullptr)
64 for (
unsigned i=0; i<level_; ++i)
66 os << name_<<
":"<<
accumulatedTime()<<
" [" << count_started_<<
"] ("<< count_updates_ <<
")"<<std::endl;
68 for (
size_t i=0; i<sub_timers_.size(); ++i) {
69 t_total += sub_timers_[i].accumulatedTime();
70 sub_timers_[i].report(os);
72 if ( sub_timers_.size() == 0 )
74 for (
unsigned i=0; i<=level_; ++i)
83 if (get_full_name() == name) {
87 for (
unsigned i=0;i<sub_timers_.size(); ++i){
88 t = sub_timers_[i].findBaseTimer(name);
98 BaseTimer::TimeInfo t;
99 auto full_name = get_full_name();
100 if (full_name.size() > name.size())
102 if ( strncmp(full_name.c_str(), name.c_str(), full_name.size()))
104 if (get_full_name() == name) {
105 t = BaseTimer::TimeInfo(
this);
109 for (
unsigned i=0;i<sub_timers_.size(); ++i){
110 t = sub_timers_[i].findTimer(name,found);
121 flat_names_.
resize(num_timers);
123 timer_.addTimerNames(flat_names_, pos);
130 flat_names_ = all_names;
136 int num_names = flat_names_.
size();
139 updates_.
resize(num_names);
140 active_.
resize(num_names);
142 if (options.output_minmax || options.output_histogram || options.output_proc_minmax) {
145 if ( options.output_minmax )
146 sum_sq_.
resize(num_names);
155 if (options.output_proc_minmax) {
156 procmin_.
resize(num_names);
157 procmax_.
resize(num_names);
161 if (options.output_histogram ) {
162 hist_.resize(options.num_histogram);
163 for (
int i=0;i<options.num_histogram ; ++i)
164 hist_[i].resize(num_names);
171 if (options.output_total_updates)
172 updates.
resize(num_names);
176 if (options.output_histogram)
180 for (
int i=0;i<num_names; ++i) {
185 used[i] = t.count==0? 0:1;
186 if (options.output_total_updates)
187 updates[i] = t.updates;
197 for (
int i=0;i<num_names;++i)
201 for (
int i=0;i<num_names;++i)
204 if (procmin_.
size()) {
207 int commRank = comm->getRank();
208 for (
int i=0;i<num_names; ++i) {
209 if (used[i] && (min_[i]==time[i]))
210 procmin[i] = commRank;
213 if (used[i] && (max_[i]==time[i]))
214 procmax[i] = commRank;
223 if (options.output_histogram) {
224 for (
int i=0;i<num_names; ++i) {
226 double dh = (max_[i]-min_[i])/options.num_histogram;
230 int bin=(time[i]- min_[i])/dh;
231 bins[i] = std::max(std::min(bin,options.num_histogram-1) , 0);
236 for (
int j=0; j<options.num_histogram; ++j){
237 for (
int i=0;i<num_names; ++i) {
247 if (sum_sq_.
size()) {
248 for (
int i=0;i<num_names; ++i)
255 std::pair<std::string, std::string> getPrefix(
const std::string &name) {
256 for (std::size_t i=name.size()-1; i>0; --i)
257 if (name[i] ==
'@') {
258 return std::pair<std::string, std::string>(name.substr(0,i), name.substr(i+1));
260 return std::pair<std::string, std::string>(std::string(
""), name);
266 std::vector<bool> &printed,
272 double total_time = 0.0;
274 for (
int i=0; i<flat_names_.
size(); ++i ) {
275 if (sum_[i]/active_[i] <= options.drop_time)
279 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
280 if ( (level != print_level) || (level >= options.max_levels) )
282 auto split_names = getPrefix(flat_names_[i]);
283 if ( prefix != split_names.first)
288 std::ostringstream os;
289 for (
int l=0; l<level; ++l)
292 os << split_names.second <<
": ";
293 alignments_.timer_names_= std::max(alignments_.timer_names_,os.str().size());
298 std::ostringstream os;
299 os << sum_[i]/active_[i];
300 alignments_.average_time_ = std::max(alignments_.average_time_,os.str().size());
304 if ( options.output_fraction && parent_time>0) {
305 std::ostringstream os;
306 os <<
" - "<<sum_[i]/active_[i]/parent_time*100<<
"%";
307 alignments_.fraction_ = std::max(alignments_.fraction_,os.str().size());
312 std::ostringstream os;
313 os <<
" ["<<count_[i]/active_[i]<<
"]";
314 alignments_.count_ = std::max(alignments_.count_,os.str().size());
318 if ( options.output_total_updates) {
319 std::ostringstream os;
320 os <<
" ("<<updates_[i]/active_[i]<<
")";
321 alignments_.total_updates_ = std::max(alignments_.total_updates_,os.str().size());
325 if ( options.output_minmax && active_[i]>1) {
327 std::ostringstream os;
328 os <<
" {min=" << min_[i];
329 alignments_.min_ = std::max(alignments_.min_,os.str().size());
332 std::ostringstream os;
333 os <<
", max=" << max_[i];
336 alignments_.max_ = std::max(alignments_.max_,os.str().size());
338 if (procmin_.
size()) {
339 std::ostringstream os;
340 os <<
", proc min=" << procmin_[i];
343 alignments_.procmin_ = std::min(alignments_.procmin_,os.str().size());
345 if (procmax_.
size()) {
346 std::ostringstream os;
347 os <<
", proc max=" << procmax_[i];
350 alignments_.procmax_ = std::max(alignments_.procmax_,os.str().size());
353 std::ostringstream os;
354 os <<
", std dev=" << sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
356 alignments_.stddev_ = std::max(alignments_.stddev_,os.str().size());
360 if ( options.output_histogram && active_[i] >1 ) {
361 std::ostringstream os;
363 for (
int h=0;h<options.num_histogram; ++h) {
365 os <<
", "<<hist_[h][i];
370 alignments_.histogram_ = std::max(alignments_.histogram_,os.str().size());
378 if (options.print_names_before_values) {
379 std::ostringstream tmp;
380 for (
int l=0; l<=level; ++l)
382 tmp <<
"Remainder: ";
383 alignments_.timer_names_ = std::max(alignments_.timer_names_,tmp.str().size());
386 std::ostringstream tmp;
387 tmp << sum_[i]/active_[i]- sub_time;
388 alignments_.average_time_ = std::max(alignments_.average_time_,tmp.str().size());
390 if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
391 std::ostringstream tmp;
392 tmp <<
" - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 <<
"%";
393 alignments_.fraction_ = std::max(alignments_.fraction_,tmp.str().size());
397 total_time += sum_[i]/active_[i];
410 double total_time = 0.0;
412 for (
int i=0; i<flat_names_.
size(); ++i ) {
413 if (sum_[i]/active_[i] <= options.drop_time) {
418 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
419 if ( (level != print_level) || (level >= options.max_levels) )
421 auto split_names = getPrefix(flat_names_[i]);
422 if ( prefix != split_names.first)
426 if (options.print_names_before_values) {
427 std::ostringstream tmp;
428 for (
int l=0; l<level; ++l) {
432 tmp << split_names.second <<
": ";
433 if (options.align_columns)
434 os << std::left << std::setw(alignments_.timer_names_);
439 std::ostringstream tmp;
440 tmp << sum_[i]/active_[i];
441 if (options.align_columns)
442 os << std::left << std::setw(alignments_.average_time_);
446 if ( options.output_fraction && parent_time>0) {
447 std::ostringstream tmp;
448 tmp <<
" - "<<sum_[i]/active_[i]/parent_time*100<<
"%";
449 if (options.align_columns)
450 os << std::left << std::setw(alignments_.fraction_);
454 else if (options.output_fraction) {
455 if (options.align_columns)
456 os << std::setw(alignments_.fraction_) <<
" ";
460 std::ostringstream tmp;
461 tmp <<
" ["<<count_[i]/active_[i]<<
"]";
462 if (options.align_columns)
463 os << std::left << std::setw(alignments_.count_);
467 if ( options.output_total_updates ) {
468 std::ostringstream tmp;
469 tmp <<
" ("<<updates_[i]/active_[i]<<
")";
470 if (options.align_columns)
471 os << std::left << std::setw(alignments_.total_updates_);
475 if ( options.output_minmax && active_[i]>1) {
477 std::ostringstream tmp;
478 tmp <<
" {min="<<min_[i];
479 if (options.align_columns)
480 os << std::left << std::setw(alignments_.min_);
484 std::ostringstream tmp;
485 tmp <<
", max="<<max_[i];
488 if (options.align_columns)
489 os << std::left << std::setw(alignments_.max_);
492 if (procmin_.
size()) {
493 std::ostringstream tmp;
494 tmp <<
", proc min="<<procmin_[i];
497 if (options.align_columns)
498 os << std::left << std::setw(alignments_.procmin_);
501 if (procmax_.
size()) {
502 std::ostringstream tmp;
503 tmp <<
", proc max="<<procmax_[i];
506 if (options.align_columns)
507 os << std::left << std::setw(alignments_.procmax_);
511 std::ostringstream tmp;
512 tmp <<
", std dev="<<sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
514 if (options.align_columns)
515 os << std::left << std::setw(alignments_.stddev_);
519 else if ( options.output_minmax) {
521 size_t offset = alignments_.min_ + alignments_.max_ + alignments_.stddev_;
522 for (
size_t j=0; j < offset; ++j)
527 if ( options.output_histogram && active_[i] >1 ) {
528 std::ostringstream tmp;
530 for (
int h=0;h<options.num_histogram; ++h) {
532 tmp <<
", "<<hist_[h][i];
537 if (options.align_columns)
538 os << std::left << std::setw(alignments_.histogram_);
541 else if ( options.output_histogram) {
543 for (
size_t j=0; j < alignments_.histogram_; ++j)
547 if (! options.print_names_before_values) {
548 std::ostringstream tmp;
550 for (
int l=0; l<level; ++l) {
554 tmp << split_names.second <<
": ";
560 double sub_time =
printLevel(flat_names_[i], level+1, os, printed, sum_[i]/active_[i], options);
564 if (options.print_names_before_values) {
565 std::ostringstream tmp;
566 for (
int l=0; l<=level; ++l)
568 tmp <<
"Remainder: ";
569 if (options.align_columns)
570 os << std::left << std::setw(alignments_.timer_names_);
574 std::ostringstream tmp;
575 tmp << sum_[i]/active_[i]- sub_time;
576 if (options.align_columns)
577 os << std::left << std::setw(alignments_.average_time_);
580 if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
581 if (options.align_columns)
582 os << std::left << std::setw(alignments_.fraction_);
583 std::ostringstream tmp;
584 tmp <<
" - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 <<
"%";
587 if (! options.print_names_before_values) {
590 offset += alignments_.count_;
591 if (options.output_total_updates)
592 offset += alignments_.total_updates_;
593 if (options.output_minmax)
594 offset += alignments_.min_ + alignments_.max_ + alignments_.stddev_;
595 if (options.output_histogram)
596 offset += alignments_.histogram_;
597 for (
size_t j=0; j < offset; ++j)
600 std::ostringstream tmp;
602 for (
int l=0; l<=level; ++l)
604 tmp <<
"Remainder: ";
605 if (options.align_columns)
606 os << std::left << std::setw(alignments_.timer_names_);
611 total_time += sum_[i]/active_[i];
616 static void printXMLEscapedString(std::ostream& os,
const std::string& str)
652 StackedTimer::printLevelXML (std::string prefix,
int print_level, std::ostream& os, std::vector<bool> &printed,
double parent_time,
const std::string& rootName)
654 constexpr
int indSpaces = 2;
655 int indent = indSpaces * print_level;
657 double total_time = 0.0;
659 for (
int i=0; i<flat_names_.
size(); ++i) {
662 int level = std::count(flat_names_[i].begin(), flat_names_[i].end(),
'@');
663 if ( level != print_level)
665 auto split_names = getPrefix(flat_names_[i]);
666 if ( prefix != split_names.first)
669 for (
int j = 0; j < indent; j++)
671 os <<
"<timing name=\"";
672 if(level == 0 && rootName.length())
673 printXMLEscapedString(os, rootName);
675 printXMLEscapedString(os, split_names.second);
676 os <<
"\" value=\"" << sum_[i]/active_[i] <<
"\"";
680 std::ostringstream osInner;
681 double sub_time =
printLevelXML(flat_names_[i], print_level+1, osInner, printed, sum_[i]/active_[i]);
682 std::string innerContents = osInner.str();
683 if(innerContents.length())
689 for (
int j = 0; j < indent + indSpaces; j++)
691 os <<
"<timing name=\"Remainder\" value=\"" << (sum_[i]/active_[i] - sub_time) <<
"\"/>\n";
694 for (
int j = 0; j < indent; j++)
703 total_time += sum_[i]/active_[i];
711 if (rank(*comm) == 0 ) {
712 if (options.print_warnings) {
713 os <<
"*** Teuchos::StackedTimer::report() - Remainder for a level will be ***"
714 <<
"\n*** incorrect if a timer in the level does not exist on every rank ***"
715 <<
"\n*** of the MPI Communicator. ***"
718 if ( (options.max_levels != INT_MAX) && options.print_warnings) {
719 os <<
"Teuchos::StackedTimer::report() - max_levels manually set to " << options.max_levels
720 <<
". \nTo print more levels, increase value of OutputOptions::max_levels." << std::endl;
722 if ( (! options.print_names_before_values) && (! options.align_columns)) {
723 options.align_columns =
true;
724 if (options.print_warnings)
725 os <<
"Teuchos::StackedTimer::report() - option print_names_before_values=false "
726 <<
"\nrequires that the option align_columns=true too. Setting the value for "
727 <<
"\nalign_column to true."
730 if (options.align_columns) {
731 std::vector<bool> printed(flat_names_.
size(),
false);
735 std::vector<bool> printed(flat_names_.
size(),
false);
745 if (rank(*comm) == 0 ) {
746 std::vector<bool> printed(flat_names_.
size(),
false);
747 os <<
"<?xml version=\"1.0\"?>\n";
748 os <<
"<performance-report date=\"" << timestamp <<
"\" name=\"nightly_run_" << datestamp <<
"\" time-units=\"seconds\">\n";
750 os <<
"</performance-report>\n";
756 const char* rawWatchrDir = getenv(
"WATCHR_PERF_DIR");
757 const char* rawBuildName = getenv(
"WATCHR_BUILD_NAME");
758 const char* rawGitSHA = getenv(
"TRILINOS_GIT_SHA");
759 const char* rawBuildDateOverride = getenv(
"WATCHR_BUILD_DATE");
763 std::string watchrDir = rawWatchrDir;
764 if(!watchrDir.length())
770 std::string buildName = rawBuildName ? rawBuildName :
"";
771 std::string datestamp;
772 std::string timestamp;
778 tstruct = gmtime(&t);
779 if(rawBuildDateOverride)
782 int year = 0, month = 0, day = 0;
783 sscanf(rawBuildDateOverride,
"%d_%d_%d", &year, &month, &day);
785 if(year <= 2000 || year > 2100)
786 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid year or is not in YYYY_MM_DD format.");
787 if(month < 1 || month > 12)
788 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid month or is not in YYYY_MM_DD format.");
789 if(day < 1 || day > 31)
790 throw std::invalid_argument(
"$WATCHR_BUILD_DATE has invalid day or is not in YYYY_MM_DD format.");
791 snprintf(buf, 256,
"%04d_%02d_%02d", year, month, day);
793 strftime(buf, 256,
"T%H:%M:%S", tstruct);
794 std::string justTime = buf;
795 snprintf(buf, 256,
"%04d-%02d-%02d", year, month, day);
796 timestamp = std::string(buf) + justTime;
800 strftime(buf, 256,
"%Y_%m_%d", tstruct);
802 strftime(buf, 256,
"%FT%H:%M:%S", tstruct);
808 std::string fullFile;
810 if(rank(*comm) == 0) {
811 std::string nameNoSpaces = name;
812 for(
char& c : nameNoSpaces)
817 if(buildName.length())
820 std::string buildNameNoSpaces = buildName;
821 for(
char& c : buildNameNoSpaces)
826 fullFile = watchrDir +
'/' + buildNameNoSpaces +
"-" + nameNoSpaces +
'_' + datestamp +
".xml";
829 fullFile = watchrDir +
'/' + nameNoSpaces +
'_' + datestamp +
".xml";
830 std::ofstream os(fullFile);
831 std::vector<bool> printed(flat_names_.
size(),
false);
832 os <<
"<?xml version=\"1.0\"?>\n";
833 os <<
"<performance-report date=\"" << timestamp <<
"\" name=\"nightly_run_" << datestamp <<
"\" time-units=\"seconds\">\n";
836 std::string gitSHA(rawGitSHA);
838 if(gitSHA.length() > 10)
839 gitSHA = gitSHA.substr(0, 10);
840 os <<
" <metadata key=\"Trilinos Version\" value=\"" << gitSHA <<
"\"/>\n";
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;
bool isTimer(const std::string &flat_timer_name)
void setVerboseOstream(const Teuchos::RCP< std::ostream > &os)
Set the ostream for verbose mode(defaults to std::cout).
void enableVerboseTimestamps(const unsigned levels)
Enable timestamps in verbose mode for the number of levels specified.
void enableVerbose(const bool enable_verbose)
If set to true, print timer start/stop to verbose ostream.
void merge(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.
bool enable_verbose_
If set to true, prints to the debug ostream. At construction, default value is set from environment v...
T * getRawPtr()
Return a raw pointer to beginning of array or NULL if unsized.
double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const std::string &rootName="")
double getMpiAverageCount(const std::string &flat_timer_name)
bool enable_timers_
Used to disable timers for asynchronous work.
std::string reportWatchrXML(const std::string &name, Teuchos::RCP< const Teuchos::Comm< int > > comm)
unsigned verbose_timestamp_levels_
If set to a value greater than 0, verbose mode will print that many levels of timers with timestamps...
BaseTimer::TimeInfo findTimer(const std::string &name, bool &found)
double printLevel(std::string prefix, int level, std::ostream &os, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
double accumulatedTime(const std::string &name="")
void report(std::ostream &os)
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.
double computeColumnWidthsForAligment(std::string prefix, int print_level, std::vector< bool > &printed, double parent_time, const OutputOptions &options)
void reportXML(std::ostream &os, const std::string &datestamp, const std::string ×tamp, Teuchos::RCP< const Teuchos::Comm< int > > comm)
void collectRemoteData(Teuchos::RCP< const Teuchos::Comm< int > > comm, const OutputOptions &options)
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 resize(size_type new_size, const value_type &x=value_type())
Teuchos::RCP< std::ostream > verbose_ostream_
For debugging, this is the ostream used for printing.
LevelTimer timer_
Base timer.
double getMpiAverageTime(const std::string &flat_timer_name)
int getFlatNameIndex(const std::string &flat_timer_name)
LevelTimer()
Default constructor, shouldn't be used but needed for std::vector.
const BaseTimer * findBaseTimer(const std::string &name) const
void aggregateMpiData(Teuchos::RCP< const Teuchos::Comm< int > > comm, OutputOptions options=OutputOptions())
Smart reference counting pointer class for automatic garbage collection.