Teuchos - Trilinos Tools Package  Version of the Day
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
Teuchos_StackedTimer.cpp
1 // @HEADER BEGIN
2 // @HEADER END
3 
4 #include "Teuchos_StackedTimer.hpp"
5 #include <limits>
6 #include <algorithm>
7 #include <sstream>
8 
9 namespace Teuchos {
10 
11 
13  level_(std::numeric_limits<unsigned>::max()),name_("INVALID"),parent_(nullptr)
14 {}
15 
16 void error_out(const std::string& msg, const bool)
17 {
18  TEUCHOS_TEST_FOR_EXCEPTION(true,std::runtime_error,msg);
19 }
20 
21 
22 void
24  for (unsigned i=0; i<level_; ++i)
25  os << " ";
26  os << name_<<":"<<accumulatedTime()<< " [" << count_started_<<"] ("<< count_updates_ <<")"<<std::endl;
27  double t_total = 0;
28  for (size_t i=0; i<sub_timers_.size(); ++i) {
29  t_total += sub_timers_[i].accumulatedTime();
30  sub_timers_[i].report(os);
31  }
32  if ( sub_timers_.size() == 0 )
33  return;
34  for (unsigned i=0; i<=level_; ++i)
35  os << " ";
36  os << "Remainder: " << accumulatedTime() - t_total<<std::endl;
37 
38 }
39 
40 const BaseTimer*
41 StackedTimer::LevelTimer::findBaseTimer(const std::string &name) const {
42  const BaseTimer* t = nullptr;
43  if (get_full_name() == name) {
44  return this;
45  }
46  else {
47  for (unsigned i=0;i<sub_timers_.size(); ++i){
48  t = sub_timers_[i].findBaseTimer(name);
49  if (t != nullptr)
50  return t;
51  }
52  }
53  return t;
54 }
55 
56 BaseTimer::TimeInfo
57 StackedTimer::LevelTimer::findTimer(const std::string &name, bool& found) {
58  BaseTimer::TimeInfo t;
59  if (get_full_name() == name) {
60  t = BaseTimer::TimeInfo(this);
61  found = true;
62  }
63  else {
64  for (unsigned i=0;i<sub_timers_.size(); ++i){
65  t = sub_timers_[i].findTimer(name,found);
66  if (found)
67  return t;
68  }
69  }
70  return t;
71 }
72 
73 void
75  int num_timers = timer_.countTimers();
76  flat_names_.resize(num_timers);
77  unsigned pos=0;
78  timer_.addTimerNames(flat_names_, pos);
79 }
80 
81 void
83  Array<std::string> all_names;
84  mergeCounterNames(*comm, flat_names_, all_names, Union);
85  flat_names_ = all_names;
86 }
87 
88 void
90  // allocate everything
91  int num_names = flat_names_.size();
92  sum_.resize(num_names);
93  count_.resize(num_names);
94  updates_.resize(num_names);
95  active_.resize(num_names);
96 
97  if (options.output_minmax || options.output_histogram) {
98  min_.resize(num_names);
99  max_.resize(num_names);
100  if ( options.output_minmax )
101  sum_sq_.resize(num_names);
102  }
103 
104 
105  if (options.output_histogram ) {
106  hist_.resize(options.num_histogram);
107  for (int i=0;i<options.num_histogram ; ++i)
108  hist_[i].resize(num_names);
109  }
110 
111  // Temp data
112  Array<double> time(num_names);
113  Array<unsigned long> count(num_names);
115  if (options.output_total_updates)
116  updates.resize(num_names);
117  Array<int> used(num_names);
118  Array<int> bins;
119 
120  if (options.output_histogram)
121  bins.resize(num_names);
122 
123  // set initial values
124  for (int i=0;i<num_names; ++i) {
125  bool found = false; // ignore result here
126  auto t = timer_.findTimer(flat_names_[i],found);
127  time[i] = t.time;
128  count[i] = t.count;
129  used[i] = t.count==0? 0:1;
130  if (options.output_total_updates)
131  updates[i] = t.updates;
132  }
133 
134  // Now reduce the data
135  reduce<int, double>(time.getRawPtr(), sum_.getRawPtr(), num_names, REDUCE_SUM, 0, *comm);
136  reduce(count.getRawPtr(), count_.getRawPtr(), num_names, REDUCE_SUM, 0, *comm);
137  reduce(used.getRawPtr(), active_.getRawPtr(), num_names, REDUCE_SUM, 0, *comm);
138 
139  if (min_.size()) {
140  reduceAll(*comm, REDUCE_MIN, num_names, time.getRawPtr(), min_.getRawPtr());
141  reduceAll(*comm, REDUCE_MAX, num_names, time.getRawPtr(), max_.getRawPtr());
142  }
143 
144  if (options.output_histogram) {
145  for (int i=0;i<num_names; ++i) {
146 
147  double dh = (max_[i]-min_[i])/options.num_histogram;
148  if (dh==0) // Put everything into bin 1
149  dh=1;
150  if (used[i]) {
151  int bin=(time[i]- min_[i])/dh;
152  bins[i] = std::max(std::min(bin,options.num_histogram-1) , 0);
153  }
154  }
155  // Recycle the used array for the temp bin array
156  for (int j=0; j<options.num_histogram; ++j){
157  for (int i=0;i<num_names; ++i) {
158  if (bins[i] == j )
159  used[i]=1;
160  else
161  used[i]=0;
162  }
163  reduce(used.getRawPtr(), hist_[j].getRawPtr(), num_names, REDUCE_SUM, 0, *comm);
164  }
165  }
166 
167  if (sum_sq_.size()) {
168  for (int i=0;i<num_names; ++i)
169  time[i] *= time[i];
170  reduce(time.getRawPtr(), sum_sq_.getRawPtr(), num_names, REDUCE_SUM, 0, *comm);
171  }
172 
173 }
174 
175 std::pair<std::string, std::string> getPrefix(const std::string &name) {
176  for (std::size_t i=name.size()-1; i>0; --i)
177  if (name[i] == '@') {
178  return std::pair<std::string, std::string>(name.substr(0,i), name.substr(i+1, name.size()));
179  }
180  return std::pair<std::string, std::string>(std::string(""), name);
181 }
182 
183 double
185  int print_level,
186  std::vector<bool> &printed,
187  double parent_time,
188  const OutputOptions &options)
189 {
190  // This replicates printLevel but counts column width instead of
191  // printing to ostream. This must be kept in sync with printLevel()
192  double total_time = 0.0;
193 
194  for (int i=0; i<flat_names_.size(); ++i ) {
195  if (printed[i])
196  continue;
197  int level = std::count(flat_names_[i].begin(), flat_names_[i].end(), '@');
198  if ( (level != print_level) || (level >= options.max_levels) )
199  continue;
200  auto split_names = getPrefix(flat_names_[i]);
201  if ( prefix != split_names.first)
202  continue;
203 
204  // Output the indentation level and timer name
205  {
206  std::ostringstream os;
207  for (int l=0; l<level; ++l)
208  os << "| ";
209  // Output the timer name
210  os << split_names.second << ": ";
211  alignments_.timer_names_= std::max(alignments_.timer_names_,os.str().size());
212  }
213 
214  // output averge time
215  {
216  std::ostringstream os;
217  os << sum_[i]/active_[i];
218  alignments_.average_time_ = std::max(alignments_.average_time_,os.str().size());
219  }
220 
221  // output percentage
222  if ( options.output_fraction && parent_time>0) {
223  std::ostringstream os;
224  os << " - "<<sum_[i]/active_[i]/parent_time*100<<"%";
225  alignments_.fraction_ = std::max(alignments_.fraction_,os.str().size());
226  }
227 
228  // output count
229  {
230  std::ostringstream os;
231  os << " ["<<count_[i]/active_[i]<<"]";
232  alignments_.count_ = std::max(alignments_.count_,os.str().size());
233  }
234 
235  // output total counts
236  if ( options.output_total_updates) {
237  std::ostringstream os;
238  os << " ("<<updates_[i]/active_[i]<<")";
239  alignments_.total_updates_ = std::max(alignments_.total_updates_,os.str().size());
240  }
241 
242  // Output min and maxs
243  if ( options.output_minmax && active_[i]>1) {
244  {
245  std::ostringstream os;
246  os << " {min=" << min_[i];
247  alignments_.min_ = std::max(alignments_.min_,os.str().size());
248  }
249  {
250  std::ostringstream os;
251  os << ", max=" << max_[i];
252  if (active_[i] <= 1)
253  os << "}";
254  alignments_.max_ = std::max(alignments_.max_,os.str().size());
255  }
256  if (active_[i]>1) {
257  std::ostringstream os;
258  os << ", std dev=" << sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
259  os << "}";
260  alignments_.stddev_ = std::max(alignments_.stddev_,os.str().size());
261  }
262  }
263  // Output histogram
264  if ( options.output_histogram && active_[i] >1 ) {
265  std::ostringstream os;
266  os << " <";
267  for (int h=0;h<options.num_histogram; ++h) {
268  if (h)
269  os <<", "<<hist_[h][i];
270  else
271  os << hist_[h][i];
272  }
273  os << ">";
274  alignments_.histogram_ = std::max(alignments_.histogram_,os.str().size());
275  }
276 
277  printed[i] = true;
278  double sub_time = computeColumnWidthsForAligment(flat_names_[i], level+1, printed, sum_[i]/active_[i], options);
279 
280  // Print Remainder
281  if (sub_time > 0 ) {
282  if (options.print_names_before_values) {
283  std::ostringstream tmp;
284  for (int l=0; l<=level; ++l)
285  tmp << "| ";
286  tmp << "Remainder: ";
287  alignments_.timer_names_ = std::max(alignments_.timer_names_,tmp.str().size());
288  }
289  {
290  std::ostringstream tmp;
291  tmp << sum_[i]/active_[i]- sub_time;
292  alignments_.average_time_ = std::max(alignments_.average_time_,tmp.str().size());
293  }
294  if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
295  std::ostringstream tmp;
296  tmp << " - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 << "%";
297  alignments_.fraction_ = std::max(alignments_.fraction_,tmp.str().size());
298  }
299  }
300 
301  total_time += sum_[i]/active_[i];
302  }
303  return total_time;
304 }
305 
306 double
307 StackedTimer::printLevel (std::string prefix, int print_level, std::ostream &os, std::vector<bool> &printed, double parent_time, const OutputOptions &options)
308 {
309  // NOTE: If you change the outputting format or logic in this
310  // function, you must make a corresponding change to the function
311  // computeColumnWidthsForAlignment() or the alignments will be
312  // incorrect if the user requests aligned output!
313 
314  double total_time = 0.0;
315 
316  for (int i=0; i<flat_names_.size(); ++i ) {
317  if (printed[i])
318  continue;
319  int level = std::count(flat_names_[i].begin(), flat_names_[i].end(), '@');
320  if ( (level != print_level) || (level >= options.max_levels) )
321  continue;
322  auto split_names = getPrefix(flat_names_[i]);
323  if ( prefix != split_names.first)
324  continue;
325 
326  // Output the indentation level
327  if (options.print_names_before_values) {
328  std::ostringstream tmp;
329  for (int l=0; l<level; ++l) {
330  tmp << "| ";
331  }
332  // Output the timer name
333  tmp << split_names.second << ": ";
334  if (options.align_columns)
335  os << std::left << std::setw(alignments_.timer_names_);
336  os << tmp.str();
337  }
338  // output averge time
339  {
340  std::ostringstream tmp;
341  tmp << sum_[i]/active_[i];
342  if (options.align_columns)
343  os << std::left << std::setw(alignments_.average_time_);
344  os << tmp.str();
345  }
346  // output percentage
347  if ( options.output_fraction && parent_time>0) {
348  std::ostringstream tmp;
349  tmp << " - "<<sum_[i]/active_[i]/parent_time*100<<"%";
350  if (options.align_columns)
351  os << std::left << std::setw(alignments_.fraction_);
352  os << tmp.str();
353  }
354  // to keep alignment for later columns if requested
355  else if (options.output_fraction) {
356  if (options.align_columns)
357  os << std::setw(alignments_.fraction_) << " ";
358  }
359  // output count
360  {
361  std::ostringstream tmp;
362  tmp << " ["<<count_[i]/active_[i]<<"]";
363  if (options.align_columns)
364  os << std::left << std::setw(alignments_.count_);
365  os << tmp.str();
366  }
367  // output total counts
368  if ( options.output_total_updates ) {
369  std::ostringstream tmp;
370  tmp << " ("<<updates_[i]/active_[i]<<")";
371  if (options.align_columns)
372  os << std::left << std::setw(alignments_.total_updates_);
373  os << tmp.str();
374  }
375  // Output min and maxs
376  if ( options.output_minmax && active_[i]>1) {
377  {
378  std::ostringstream tmp;
379  tmp << " {min="<<min_[i];
380  if (options.align_columns)
381  os << std::left << std::setw(alignments_.min_);
382  os << tmp.str();
383  }
384  {
385  std::ostringstream tmp;
386  tmp <<", max="<<max_[i];
387  if (active_[i] <= 1)
388  tmp << "}";
389  if (options.align_columns)
390  os << std::left << std::setw(alignments_.max_);
391  os << tmp.str();
392  }
393  if (active_[i]>1) {
394  std::ostringstream tmp;
395  tmp << ", std dev="<<sqrt(std::max<double>(sum_sq_[i]-sum_[i]*sum_[i]/active_[i],0.0)/(active_[i]-1));
396  tmp << "}";
397  if (options.align_columns)
398  os << std::left << std::setw(alignments_.stddev_);
399  os << tmp.str();
400  }
401  }
402  else if ( options.output_minmax) {
403  // this block keeps alignment for single rank timers
404  size_t offset = alignments_.min_ + alignments_.max_ + alignments_.stddev_;
405  for (size_t j=0; j < offset; ++j)
406  os << " ";
407  }
408 
409  // Output histogram
410  if ( options.output_histogram && active_[i] >1 ) {
411  std::ostringstream tmp;
412  tmp << " <";
413  for (int h=0;h<options.num_histogram; ++h) {
414  if (h)
415  tmp <<", "<<hist_[h][i];
416  else
417  tmp << hist_[h][i];
418  }
419  tmp << ">";
420  if (options.align_columns)
421  os << std::left << std::setw(alignments_.histogram_);
422  os << tmp.str();
423  }
424  else if ( options.output_histogram) {
425  // this block keeps alignment for single rank timers
426  for (size_t j=0; j < alignments_.histogram_; ++j)
427  os << " ";
428  }
429 
430  if (not options.print_names_before_values) {
431  std::ostringstream tmp;
432  tmp << " ";
433  for (int l=0; l<level; ++l) {
434  tmp << "| ";
435  }
436  // Output the timer name
437  tmp << split_names.second << ": ";
438  os << tmp.str();
439  }
440 
441  os << std::endl;
442  printed[i] = true;
443  double sub_time = printLevel(flat_names_[i], level+1, os, printed, sum_[i]/active_[i], options);
444 
445  // Print Remainder
446  if (sub_time > 0 ) {
447  if (options.print_names_before_values) {
448  std::ostringstream tmp;
449  for (int l=0; l<=level; ++l)
450  tmp << "| ";
451  tmp << "Remainder: ";
452  if (options.align_columns)
453  os << std::left << std::setw(alignments_.timer_names_);
454  os << tmp.str();
455  }
456  {
457  std::ostringstream tmp;
458  tmp << sum_[i]/active_[i]- sub_time;
459  if (options.align_columns)
460  os << std::left << std::setw(alignments_.average_time_);
461  os << tmp.str();
462  }
463  if ( options.output_fraction && (sum_[i]/active_[i] > 0.) ) {
464  if (options.align_columns)
465  os << std::left << std::setw(alignments_.fraction_);
466  std::ostringstream tmp;
467  tmp << " - "<< (sum_[i]/active_[i]- sub_time)/(sum_[i]/active_[i])*100 << "%";
468  os << tmp.str();
469  }
470  if (not options.print_names_before_values) {
471  {
472  size_t offset = 0;
473  offset += alignments_.count_;
474  if (options.output_total_updates)
475  offset += alignments_.total_updates_;
476  if (options.output_minmax)
477  offset += alignments_.min_ + alignments_.max_ + alignments_.stddev_;
478  if (options.output_histogram)
479  offset += alignments_.histogram_;
480  for (size_t j=0; j < offset; ++j)
481  os << " ";
482  }
483  std::ostringstream tmp;
484  tmp << " ";
485  for (int l=0; l<=level; ++l)
486  tmp << "| ";
487  tmp << "Remainder: ";
488  if (options.align_columns)
489  os << std::left << std::setw(alignments_.timer_names_);
490  os << tmp.str();
491  }
492  os << std::endl;
493  }
494  total_time += sum_[i]/active_[i];
495  }
496  return total_time;
497 }
498 
499 void
500 StackedTimer::report(std::ostream &os, Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options) {
501  flatten();
502  merge(comm);
503  collectRemoteData(comm, options);
504  if (rank(*comm) == 0 ) {
505  if (options.print_warnings) {
506  os << "*** Teuchos::StackedTimer::report() - Remainder for a level will be ***"
507  << "\n*** incorrect if a timer in the level does not exist on every rank ***"
508  << "\n*** of the MPI Communicator. ***"
509  << std::endl;
510  }
511  if ( (options.max_levels != INT_MAX) && options.print_warnings) {
512  os << "Teuchos::StackedTimer::report() - max_levels manually set to " << options.max_levels
513  << ". \nTo print more levels, increase value of OutputOptions::max_levels." << std::endl;
514  }
515  if (not options.print_names_before_values and not options.align_columns) {
516  options.align_columns = true;
517  if (options.print_warnings)
518  os << "Teuchos::StackedTimer::report() - option print_names_before_values=false "
519  << "\nrequires that the option align_columns=true too. Setting the value for "
520  << "\nalign_column to true."
521  << std::endl;
522  }
523  if (options.align_columns) {
524  std::vector<bool> printed(flat_names_.size(), false);
525  computeColumnWidthsForAligment("", 0, printed, 0., options);
526  }
527 
528  std::vector<bool> printed(flat_names_.size(), false);
529  printLevel("", 0, os, printed, 0., options);
530  }
531 }
532 
533 } //namespace Teuchos
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.
T * getRawPtr()
Return a raw pointer to beginning of array or NULL if unsized.
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="")
the basic timer used elsewhere, uses MPI_Wtime for time
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)
TEUCHOS_DEPRECATED void reduceAll(const Comm< Ordinal > &comm, const EReductionType reductType, const Packet &send, Packet *globalReduct)
Deprecated .
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())
LevelTimer timer_
Base timer.
void error_out(const std::string &msg, const bool)
Error reporting function for stacked timer.
Abstract interface for distributed-memory communication.
size_type size() const
LevelTimer()
Default constructor, shouldn&#39;t be used but needed for std::vector.
const BaseTimer * findBaseTimer(const std::string &name) const
Smart reference counting pointer class for automatic garbage collection.
Struct for controlling output options like histograms.