Teuchos Package Browser (Single Doxygen Collection)  Version of the Day
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
TimeMonitor_UnitTests.cpp
Go to the documentation of this file.
1 // @HEADER
2 // *****************************************************************************
3 // Teuchos: Common Tools Package
4 //
5 // Copyright 2004 NTESS and the Teuchos contributors.
6 // SPDX-License-Identifier: BSD-3-Clause
7 // *****************************************************************************
8 // @HEADER
9 
10 #include "Teuchos_TimeMonitor.hpp"
11 #include "Teuchos_DefaultComm.hpp"
14 #include "Teuchos_Behavior.hpp"
15 
16 // slowLoop does not reliably make a timer nonzero (RHEL6, gcc 4.4.7, OpenMPI 1.5.4).
17 // Thus, I'm introducing headers to make sleep() available.
18 #ifndef ICL
19 #include <unistd.h>
20 #else
21 void sleep(int sec)
22 {
23  Sleep(sec);
24 }
25 #endif
26 
27 #ifdef _MSC_VER
28 #pragma comment(lib, "Ws2_32.lib")
29 # include <Winsock2.h>
30 # include <process.h>
31 void sleep(int sec)
32 {
33  Sleep(sec * 1000);
34 }
35 #endif
36 
37 #ifdef HAVE_TEUCHOSCORE_KOKKOS
38 #include "Kokkos_Core.hpp"
39 #endif
40 
41 namespace {
42 
43  void func_time_monitor1()
44  {
45  TEUCHOS_FUNC_TIME_MONITOR("FUNC_TIME_MONITOR1");
46  }
47 
48 
49  void func_time_monitor2()
50  {
51  TEUCHOS_FUNC_TIME_MONITOR("FUNC_TIME_MONITOR2");
52  {
53  TEUCHOS_FUNC_TIME_MONITOR_DIFF("FUNC_TIME_MONITOR2_inner", inner);
54  }
55  }
56 
57  // This function is commented out because no code in this file
58  // actually uses it. Commenting it out avoids compiler warnings
59  // ("unused function").
60 #if 0
61  // Slowly compute the n-th Fibonacci number. This gives timers
62  // something to time. Be careful not to make n too large, or you'll
63  // run out of stack space.
64  int
65  fib (const int n)
66  {
67  if (n <= 0) {
68  return 0;
69  } else if (n == 1) {
70  return 1;
71  }
72  else {
73  // You should never compute the n-th Fibonacci number like this.
74  // This is exponentially slow in n. The point of using a slow
75  // algorithm like this is to exercise timers.
76  return fib (n-1) + fib (n-2);
77  }
78  }
79 #endif // 0
80 
81  // Do a number of arithmetic operations proportional to n^3, in
82  // order to have something to time. Unlike the recursive function
83  // fib() commented out above, this function shouldn't take up a lot
84  // of stack space.
85  double
86  slowLoop (const size_t n)
87  {
88  const double inc = 1 / static_cast<double> (n);
89  double x = 1.0;
90 
91  for (size_t i = 0; i < n; ++i) {
92  for (size_t j = 0; j < n; ++j) {
93  for (size_t k = 0; k < n; ++k) {
94  x = x + inc;
95  }
96  }
97  }
98  return x;
99  }
100 
101 } // namespace (anonymous)
102 
103 
104 namespace Teuchos {
105  //
106  // Basic TimeMonitor test: create and exercise a timer on all (MPI)
107  // processes, and make sure that TimeMonitor::summarize() reports it.
108  //
109  TEUCHOS_UNIT_TEST( TimeMonitor, FUNC_TIME_MONITOR )
110  {
112  using Teuchos::parameterList;
113  using Teuchos::RCP;
114 
115  func_time_monitor1 (); // Function to time.
116 
117  { // Repeat test for default output format.
118  std::ostringstream oss;
120 
121  // Echo summarize() output to the FancyOStream out (which is a
122  // standard unit test argument). Output should only appear in
123  // show-all-test-details mode.
124  out << oss.str () << std::endl;
125 
126  // Make sure that the timer's name shows up in the output.
128  const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
129  TEST_INEQUALITY(substr_i, std::string::npos);
130  }
131  }
132 
133  { // Repeat test for YAML output, compact style.
134  std::ostringstream oss;
135  RCP<ParameterList> reportParams =
136  parameterList (* (TimeMonitor::getValidReportParameters ()));
137  reportParams->set ("Report format", "YAML");
138  reportParams->set ("YAML style", "compact");
139  TimeMonitor::report (oss, reportParams);
140 
141  // Echo output to the FancyOStream out (which is a standard unit
142  // test argument). Output should only appear in "show all test
143  // details" mode.
144  out << oss.str () << std::endl;
145 
146  // Make sure that the timer's name shows up in the output.
147  const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
148  TEST_INEQUALITY(substr_i, std::string::npos);
149  }
150 
151  { // Repeat test for YAML output, spacious style.
152  std::ostringstream oss;
153  RCP<ParameterList> reportParams =
154  parameterList (* (TimeMonitor::getValidReportParameters ()));
155  reportParams->set ("Report format", "YAML");
156  reportParams->set ("YAML style", "spacious");
157  TimeMonitor::report (oss, reportParams);
158 
159  // Echo output to the FancyOStream out (which is a standard unit
160  // test argument). Output should only appear in "show all test
161  // details" mode.
162  out << oss.str () << std::endl;
163 
164  // Make sure that the timer's name shows up in the output.
165  const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
166  TEST_INEQUALITY(substr_i, std::string::npos);
167  }
168 
169  // This sets up for the next unit test.
171  }
172 
173  //
174  // Test for TimeMonitor's enableTimer and disableTimer methods.
175  //
177  {
178  using Teuchos::Array;
179  using Teuchos::OSTab;
181  using Teuchos::parameterList;
182  using Teuchos::RCP;
183  using Teuchos::rcpFromRef;
184  using Teuchos::Time;
185  using Teuchos::TimeMonitor;
186  using std::endl;
187  typedef Teuchos::Array<RCP<Time> >::size_type size_type;
188 
189  out << "Testing TimeMonitor's disableTimer() and enableTimer() methods"
190  << endl;
191  OSTab (rcpFromRef (out));
192 
193  out << "Creating timers" << endl;
194  const int numTrials = 5;
195  const int numTimers = 3;
196  Array<RCP<Time> > timers (numTimers);
197  for (size_type i = 0; i < numTimers; ++i) {
198  std::ostringstream os; // construct timer name
199  os << "Timer " << i;
200  timers[i] = TimeMonitor::getNewTimer (os.str ());
201  }
202 
203  out << "Running all timers without disabling any" << endl;
204  // The actual number of operations in slowloop is proportional to
205  // the cube of the loop length. Adjust loopLength as necessary to
206  // ensure the timer reports a nonzero elapsed time for each of the
207  // invocations.
208  const size_t loopLength = 25;
209  for (int k = 0; k < numTrials; ++k) {
210  for (size_type i = 0; i < numTimers; ++i) {
211  TimeMonitor timeMon (* timers[i]);
212  slowLoop (loopLength);
213  }
214  }
215  for (size_type i = 0; i < numTimers; ++i) {
216  TEST_EQUALITY( timers[i]->numCalls(), numTrials );
217  }
218 
219  out << "Disabling one timer and trying again" << endl;
220  // Disable timers[0] only, and repeat the above loops.
222  for (int k = 0; k < numTrials; ++k) {
223  for (size_type i = 0; i < numTimers; ++i) {
224  TimeMonitor timeMon (* timers[i]);
225  slowLoop (loopLength);
226  }
227  }
228  TEST_EQUALITY( timers[0]->numCalls(), numTrials );
229  for (size_type i = 1; i < numTimers; ++i) {
230  TEST_EQUALITY( timers[i]->numCalls(), 2*numTrials );
231  }
232 
233  out << "Reenabling the timer and trying again" << endl;
234  // Enable timers[0] and repeat the above loops.
235  TEST_NOTHROW( TimeMonitor::enableTimer ("Timer 0") );
236  for (int k = 0; k < numTrials; ++k) {
237  for (size_type i = 0; i < numTimers; ++i) {
238  TimeMonitor timeMon (* timers[i]);
239  slowLoop (loopLength);
240  }
241  }
242  TEST_EQUALITY( timers[0]->numCalls(), 2*numTrials );
243  for (size_type i = 1; i < numTimers; ++i) {
244  TEST_EQUALITY( timers[i]->numCalls(), 3*numTrials );
245  }
246 
247  out << "Test that summarize() reports enabled and disabled timers" << endl;
248  // Make sure that summarize() reports all timers. Disabling a
249  // timer must _not_ exclude it from the list of timers printed by
250  // summarize(). Disable a different timer this time just for fun.
252  {
253  std::ostringstream oss;
255 
256  // Echo summarize() output to the FancyOStream out (which is a
257  // standard unit test argument). Output should only appear in
258  // show-all-test-details mode.
259  out << oss.str () << std::endl;
260 
261  // Make sure that each timer's name shows up in the output.
262  for (size_type i = 0; i < numTimers; ++i) {
263  const std::string name = timers[i]->name ();
265  const size_t substr_i = oss.str ().find (name);
266  TEST_INEQUALITY(substr_i, std::string::npos);
267  }
268  }
269  }
270 
271  // This sets up for the next unit test.
273  }
274 
275 
276  //
277  // Test correct quoting of labels for TimeMonitor's YAML output.
278  //
279  TEUCHOS_UNIT_TEST( TimeMonitor, YamlLabelQuoting )
280  {
281  using Teuchos::Array;
283  using Teuchos::parameterList;
284  using Teuchos::RCP;
285  using Teuchos::Time;
286  typedef Array<std::string>::size_type size_type;
287 
288  Array<std::string> inputLabels, outputLabels;
289 
290  // Make sure to exercise things that don't need quoting, like
291  // spaces and certain punctuation, as well as things that do need
292  // quoting, like colons, inner double quotes, and backslashes.
293  inputLabels.push_back ("NoQuotingNeeded");
294  inputLabels.push_back ("No quoting needed");
295  inputLabels.push_back ("\"AlreadyQuotedNoQuotingNeeded\"");
296  inputLabels.push_back ("\"Already quoted, no quoting needed\"");
297  inputLabels.push_back ("\"Already quoted: quoting needed\"");
298  inputLabels.push_back ("NotQuoted:QuotingNeeded");
299  inputLabels.push_back ("Not quoted: quoting needed");
300  // Test both individual double quotes, and pairs of double quotes.
301  inputLabels.push_back ("Not quoted \" quoting needed");
302  inputLabels.push_back ("Not quoted \" \" quoting needed");
303  inputLabels.push_back ("\"Already quoted \" quoting needed\"");
304  inputLabels.push_back ("\"Already quoted \" \" quoting needed\"");
305  // Remember that in C strings, a double backslash turns into a
306  // single backslash. Our YAML output routine should turn each
307  // single backslash back into a double backslash.
308  inputLabels.push_back ("Not quoted \\ quoting needed");
309  inputLabels.push_back ("Not quoted \\\\ quoting needed");
310  inputLabels.push_back ("Not quoted \\ \\ quoting needed");
311  inputLabels.push_back ("\"Already quoted \\ quoting needed\"");
312  inputLabels.push_back ("\"Already quoted \\\\ quoting needed\"");
313  inputLabels.push_back ("\"Already quoted \\ \\ quoting needed\"");
314 
315  outputLabels.push_back ("NoQuotingNeeded");
316  outputLabels.push_back ("No quoting needed");
317  outputLabels.push_back ("\"AlreadyQuotedNoQuotingNeeded\"");
318  outputLabels.push_back ("\"Already quoted, no quoting needed\"");
319  outputLabels.push_back ("\"Already quoted: quoting needed\"");
320  outputLabels.push_back ("\"NotQuoted:QuotingNeeded\"");
321  outputLabels.push_back ("\"Not quoted: quoting needed\"");
322  outputLabels.push_back ("\"Not quoted \\\" quoting needed\"");
323  outputLabels.push_back ("\"Not quoted \\\" \\\" quoting needed\"");
324  outputLabels.push_back ("\"Already quoted \\\" quoting needed\"");
325  outputLabels.push_back ("\"Already quoted \\\" \\\" quoting needed\"");
326  outputLabels.push_back ("\"Not quoted \\\\ quoting needed\"");
327  outputLabels.push_back ("\"Not quoted \\\\\\\\ quoting needed\"");
328  outputLabels.push_back ("\"Not quoted \\\\ \\\\ quoting needed\"");
329  outputLabels.push_back ("\"Already quoted \\\\ quoting needed\"");
330  outputLabels.push_back ("\"Already quoted \\\\\\\\ quoting needed\"");
331  outputLabels.push_back ("\"Already quoted \\\\ \\\\ quoting needed\"");
332 
333  // Sanity check.
335  inputLabels.size () != outputLabels.size (),
336  std::logic_error,
337  "The number of input labels is different than the number of output labels."
338  " Please ask a Teuchos developer to make sure that every test input "
339  "label has a corresponding output label.");
340 
341  Array<RCP<Time> > timers;
342  for (size_type i = 0; i < inputLabels.size (); ++i) {
343  timers.push_back (TimeMonitor::getNewCounter (inputLabels[i]));
344  }
345 
346  // The actual number of operations in the loop is proportional to
347  // the cube of the loop length. Adjust the quantities below as
348  // necessary to ensure the timer reports a nonzero elapsed time
349  // for each of the invocations.
350  const size_t loopLength = 25;
351  for (int k = 0; k < 3; ++k) {
352  for (size_type i = 0; i < timers.size (); ++i) {
353  TimeMonitor timeMon (* timers[i]);
354  slowLoop (loopLength);
355  }
356  }
357 
358  { // YAML output, compact style.
359  std::ostringstream oss;
360  RCP<ParameterList> reportParams =
361  parameterList (* (TimeMonitor::getValidReportParameters ()));
362  reportParams->set ("Report format", "YAML");
363  reportParams->set ("YAML style", "compact");
364  TimeMonitor::report (oss, reportParams);
365 
366  // Echo output to the FancyOStream out (which is a standard unit
367  // test argument). Output should only appear in "show all test
368  // details" mode.
369  out << oss.str () << std::endl;
370 
371  // Make sure that all timer labels appear correctly in the output.
372  for (size_type i = 0; i < inputLabels.size(); ++i) {
373  const size_t pos = oss.str ().find (outputLabels[i]);
374  TEST_INEQUALITY(pos, std::string::npos);
375  }
376  }
377 
378  { // YAML output, spacious style.
379  std::ostringstream oss;
380  RCP<ParameterList> reportParams =
381  parameterList (* (TimeMonitor::getValidReportParameters ()));
382  reportParams->set ("Report format", "YAML");
383  reportParams->set ("YAML style", "spacious");
384  TimeMonitor::report (oss, reportParams);
385 
386  // Echo output to the FancyOStream out (which is a standard unit
387  // test argument). Output should only appear in "show all test
388  // details" mode.
389  out << oss.str () << std::endl;
390 
391  // Make sure that all timer labels appear correctly in the output.
392  for (size_type i = 0; i < inputLabels.size(); ++i) {
393  const size_t pos = oss.str ().find (outputLabels[i]);
394  TEST_INEQUALITY(pos, std::string::npos);
395  }
396  }
397 
398  // This sets up for the next unit test.
400  }
401 
402 
403  //
404  // Test filtering of timer labels.
405  //
406  TEUCHOS_UNIT_TEST( TimeMonitor, TimerLabelFiltering )
407  {
408  using Teuchos::Array;
410  using Teuchos::parameterList;
411  using Teuchos::RCP;
412  using Teuchos::Time;
413  typedef Array<std::string>::size_type size_type;
414 
415  // Filters to use in the test.
416  Array<std::string> filters;
417  filters.push_back ("Foo:");
418  filters.push_back ("Bar:");
419  filters.push_back ("Baz:");
420 
421  // All the timer labels.
422  Array<std::string> labels;
423  labels.push_back ("Foo: timer 1");
424  labels.push_back ("Foo: timer 2");
425  labels.push_back ("Foo: timer 3");
426  labels.push_back ("Bar: timer 1");
427  labels.push_back ("Bar: timer 2");
428  labels.push_back ("Baz: timer 1");
429  labels.push_back ("Xyzzy");
430  labels.push_back ("This is not a pipe");
431  labels.push_back ("You should not see this");
432 
433  Array<Array<std::string> > outLabels (3);
434  // Label(s) that should be printed for filters[0]
435  outLabels[0].push_back ("Foo: timer 1");
436  outLabels[0].push_back ("Foo: timer 2");
437  outLabels[0].push_back ("Foo: timer 3");
438  // Label(s) that should be printed for filters[1]
439  outLabels[1].push_back ("Bar: timer 1");
440  outLabels[1].push_back ("Bar: timer 2");
441  // Label(s) that should be printed for filters[2]
442  outLabels[2].push_back ("Baz: timer 1");
443 
444  // Labels that should not be printed for any of the filters below.
445  Array<std::string> otherLabels;
446  otherLabels.push_back ("Xyzzy");
447  otherLabels.push_back ("This is not a pipe");
448  otherLabels.push_back ("You should not see this");
449 
450  Array<RCP<Time> > timers;
451  for (size_type i = 0; i < labels.size (); ++i) {
452  timers.push_back (TimeMonitor::getNewCounter (labels[i]));
453  }
454 
455  // The actual number of operations in the loop is proportional to
456  // the cube of the loop length. Adjust the quantities below as
457  // necessary to ensure the timer reports a nonzero elapsed time
458  // for each of the invocations.
459  const size_t loopLength = 25;
460  for (int k = 0; k < 3; ++k) {
461  for (size_type i = 0; i < timers.size (); ++i) {
462  TimeMonitor timeMon (* timers[i]);
463  slowLoop (loopLength);
464  }
465  }
466 
467  try {
468  // FIXME (mfh 21 Aug 2012) We don't yet have a test ensuring that
469  // the filter only selects at the beginning of the timer label.
470 
471  // Test for each filter.
472  for (size_type i = 0; i < filters.size (); ++i) {
473  { // Default (tabular) output format.
474  std::ostringstream oss;
475  RCP<ParameterList> reportParams =
476  parameterList (* (TimeMonitor::getValidReportParameters ()));
477  TimeMonitor::report (oss, filters[i], reportParams);
478 
479  // Echo output to the FancyOStream out (which is a standard unit
480  // test argument). Output should only appear in "show all test
481  // details" mode.
482  out << oss.str () << std::endl;
483 
484  // Check whether the labels that were supposed to be printed
485  // were actually printed.
487  for (size_type j = 0; j < outLabels[i].size(); ++j) {
488  const size_t pos = oss.str ().find (outLabels[i][j]);
489  TEST_INEQUALITY(pos, std::string::npos);
490  }
491  }
492 
493  // Check whether the labels that were _not_ supposed to be
494  // printed were actually printed.
495  //
496  // First, check the labels that should only be printed with
497  // the other filters.
498  for (size_type ii = 0; ii < outLabels.size(); ++ii) {
499  if (ii != i) {
500  for (size_type j = 0; j < outLabels[ii].size(); ++j) {
501  const size_t pos = oss.str ().find (outLabels[ii][j]);
502  TEST_EQUALITY(pos, std::string::npos);
503  }
504  }
505  }
506  // Next, check the labels that should not be printed for any
507  // filters.
508  for (size_type j = 0; j < otherLabels.size(); ++j) {
509  const size_t pos = oss.str ().find (otherLabels[j]);
510  TEST_EQUALITY(pos, std::string::npos);
511  }
512  }
513 
514  { // YAML output, compact style.
515  std::ostringstream oss;
516  RCP<ParameterList> reportParams =
517  parameterList (* (TimeMonitor::getValidReportParameters ()));
518  reportParams->set ("Report format", "YAML");
519  reportParams->set ("YAML style", "compact");
520  TimeMonitor::report (oss, filters[i], reportParams);
521 
522  // Echo output to the FancyOStream out (which is a standard unit
523  // test argument). Output should only appear in "show all test
524  // details" mode.
525  out << oss.str () << std::endl;
526 
527  // Check whether the labels that were supposed to be printed
528  // were actually printed.
529  for (size_type j = 0; j < outLabels[i].size(); ++j) {
530  const size_t pos = oss.str ().find (outLabels[i][j]);
531  TEST_INEQUALITY(pos, std::string::npos);
532  }
533 
534  // Check whether the labels that were _not_ supposed to be
535  // printed were actually printed.
536  //
537  // First, check the labels that should only be printed with
538  // the other filters.
539  for (size_type ii = 0; ii < outLabels.size(); ++ii) {
540  if (ii != i) {
541  for (size_type j = 0; j < outLabels[ii].size(); ++j) {
542  const size_t pos = oss.str ().find (outLabels[ii][j]);
543  TEST_EQUALITY(pos, std::string::npos);
544  }
545  }
546  }
547  // Next, check the labels that should not be printed for any
548  // filters.
549  for (size_type j = 0; j < otherLabels.size(); ++j) {
550  const size_t pos = oss.str ().find (otherLabels[j]);
551  TEST_EQUALITY(pos, std::string::npos);
552  }
553  }
554 
555  { // YAML output, spacious style.
556  std::ostringstream oss;
557  RCP<ParameterList> reportParams =
558  parameterList (* (TimeMonitor::getValidReportParameters ()));
559  reportParams->set ("Report format", "YAML");
560  reportParams->set ("YAML style", "spacious");
561  TimeMonitor::report (oss, filters[i], reportParams);
562 
563  // Echo output to the FancyOStream out (which is a standard unit
564  // test argument). Output should only appear in "show all test
565  // details" mode.
566  out << oss.str () << std::endl;
567 
568  // Check whether the labels that were supposed to be printed
569  // were actually printed.
570  for (size_type j = 0; j < outLabels[i].size(); ++j) {
571  const size_t pos = oss.str ().find (outLabels[i][j]);
572  TEST_INEQUALITY(pos, std::string::npos);
573  }
574 
575  // Check whether the labels that were _not_ supposed to be
576  // printed were actually printed.
577  //
578  // First, check the labels that should only be printed with
579  // the other filters.
580  for (size_type ii = 0; ii < outLabels.size(); ++ii) {
581  if (ii != i) {
582  for (size_type j = 0; j < outLabels[ii].size(); ++j) {
583  const size_t pos = oss.str ().find (outLabels[ii][j]);
584  TEST_EQUALITY(pos, std::string::npos);
585  }
586  }
587  }
588  // Next, check the labels that should not be printed for any
589  // filters.
590  for (size_type j = 0; j < otherLabels.size(); ++j) {
591  const size_t pos = oss.str ().find (otherLabels[j]);
592  TEST_EQUALITY(pos, std::string::npos);
593  }
594  }
595  }
596  }
597  catch (...) {
598  // Make sure to clear the counters, so that they don't pollute
599  // the remaining tests. (The Teuchos unit test framework may
600  // catch any exceptions that the above code throws, but allow
601  // the remaining tests to continue.)
603  throw;
604  }
605 
606  // This sets up for the next unit test.
608  }
609 
610 
611 
612  //
613  // TimeMonitor nested timers test: create two timers on all (MPI)
614  // processes, use the second inside the scope of the first, and make
615  // sure that TimeMonitor::summarize() reports both timers.
616  //
617  TEUCHOS_UNIT_TEST( TimeMonitor, FUNC_TIME_MONITOR_tested )
618  {
620  using Teuchos::parameterList;
621  using Teuchos::RCP;
622 
623  func_time_monitor2 ();
624 
625  {
626  std::ostringstream oss;
628 
629  // Echo summarize() output to the FancyOStream out (which is a
630  // standard unit test argument). Output should only appear in
631  // show-all-test-details mode.
632  out << oss.str() << std::endl;
633 
635  const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
636  TEST_INEQUALITY(substr_i, std::string::npos);
637  const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
638  TEST_INEQUALITY(substr_inner_i, std::string::npos);
639  }
640  }
641 
642  { // Repeat test for YAML output, compact style.
643  std::ostringstream oss;
644  RCP<ParameterList> reportParams =
645  parameterList (* (TimeMonitor::getValidReportParameters ()));
646  reportParams->set ("Report format", "YAML");
647  reportParams->set ("YAML style", "compact");
648  TimeMonitor::report (oss, reportParams);
649 
650  // Echo output to the FancyOStream out (which is a standard unit
651  // test argument). Output should only appear in "show all test
652  // details" mode.
653  out << oss.str () << std::endl;
654 
655  const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
656  TEST_INEQUALITY(substr_i, std::string::npos);
657  const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
658  TEST_INEQUALITY(substr_inner_i, std::string::npos);
659  }
660 
661  { // Repeat test for YAML output, spacious style.
662  std::ostringstream oss;
663  RCP<ParameterList> reportParams =
664  parameterList (* (TimeMonitor::getValidReportParameters ()));
665  reportParams->set ("Report format", "YAML");
666  reportParams->set ("YAML style", "spacious");
667  TimeMonitor::report (oss, reportParams);
668 
669  // Echo output to the FancyOStream out (which is a standard unit
670  // test argument). Output should only appear in "show all test
671  // details" mode.
672  out << oss.str () << std::endl;
673 
674  const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
675  TEST_INEQUALITY(substr_i, std::string::npos);
676  const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
677  TEST_INEQUALITY(substr_inner_i, std::string::npos);
678  }
679 
680  // This sets up for the next unit test.
682  }
683 
684  //
685  // Test whether TimeMonitor::summarize() does the right thing when
686  // different MPI processes create different sets of timers. This
687  // test is only meaningful if running with more than one MPI
688  // process, but it should also pass if running in a non-MPI build or
689  // with only one MPI process.
690  //
691  TEUCHOS_UNIT_TEST( TimeMonitor, SUMMARIZE_diffTimerSets )
692  {
694  const int numProcs = comm->getSize ();
695  const int myRank = comm->getRank ();
696 
697  // If MPI has not been initialized, turn the MPI communicator into
698  // a "serial" communicator. This may not be necessary when using
699  // the Teuchos Unit Test Framework.
700 #ifdef HAVE_MPI
701  {
702  int mpiHasBeenInitialized = 0;
703  MPI_Initialized (&mpiHasBeenInitialized);
704  if (! mpiHasBeenInitialized) {
706  }
707  }
708 #endif // HAVE_MPI
709 
710  // Store the output of TimeMonitor::summarize() here.
711  std::ostringstream oss;
712 
713  // Timer A gets created on all MPI processes.
714  // Timer B only gets created on Proc 0.
715  RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
716  RCP<Time> timerB;
717  if (myRank == 0) {
718  timerB = TimeMonitor::getNewCounter ("Timer B");
719  }
720  else {
721  timerB = null; // True anyway, but I want to make this explicit.
722  }
723 
724  // The actual number of operations in the loop is proportional to
725  // the cube of the loop length. Adjust the quantities below as
726  // necessary to ensure the timer reports a nonzero elapsed time
727  // for each of the invocations.
728  const size_t timerA_loopLength = 150;
729  const size_t timerB_loopLength = 200;
730 
731  // Timer A gets a call count of 3.
732  for (size_t k = 0; k < 3; ++k) {
733  TimeMonitor monitorA (*timerA);
734  slowLoop (timerA_loopLength);
735  }
736  if (myRank == 0) { // Timer B gets a call count of 1 on Proc 0.
737  TimeMonitor monitorB (*timerB);
738  slowLoop (timerB_loopLength);
739  }
740 
741  const bool alwaysWriteLocal = false; // the default
742  const bool writeGlobalStats = true; // the default
743  const bool writeZeroTimers = true; // the default
744  TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
745  writeZeroTimers, Intersection);
746 
747  // Echo summarize() output to the FancyOStream out (which is a
748  // standard unit test argument). Output should only appear in
749  // show-all-test-details mode.
750  out << std::endl << "Testing intersection of timers:" << std::endl
751  << oss.str() << std::endl;
752 
753  // Since setOp == Intersection, only Timer A should be reported,
754  // unless there is only one (MPI) process.
756  size_t substr_i = oss.str().find ("Timer A");
757  TEST_INEQUALITY(substr_i, std::string::npos);
758  if (numProcs > 1) {
759  substr_i = oss.str().find ("Timer B");
760  TEST_EQUALITY(substr_i, std::string::npos);
761  }
762  }
763 
764  // Now call summarize(), but ask for a union of timers.
765  std::ostringstream ossUnion;
766  TimeMonitor::summarize (ossUnion, alwaysWriteLocal, writeGlobalStats,
767  writeZeroTimers, Union);
768 
769  // Echo summarize() output to the FancyOStream out (which is a
770  // standard unit test argument). Output should only appear in
771  // show-all-test-details mode.
772  out << std::endl << "Testing union of timers:" << std::endl
773  << ossUnion.str() << std::endl;
774 
775  // Since setOp == Union, both Timer A and Timer B should be
776  // reported.
778  size_t substr_i = ossUnion.str().find ("Timer A");
779  TEST_INEQUALITY(substr_i, std::string::npos);
780  substr_i = ossUnion.str().find ("Timer B");
781  TEST_INEQUALITY(substr_i, std::string::npos);
782  }
783 
784  // This sets up for the next unit test.
786  }
787 
788  //
789  // Test whether the option to filter out zero timers works, for the
790  // case that all (MPI) processes have the same call counts.
791  //
792  TEUCHOS_UNIT_TEST( TimeMonitor, FILTER_ZERO_TIMERS_sameParallelCallCounts )
793  {
794  // Store the output of TimeMonitor::summarize() here.
795  std::ostringstream oss;
796 
797  RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
798  RCP<Time> timerB = TimeMonitor::getNewCounter ("Timer B");
799  RCP<Time> timerC = TimeMonitor::getNewCounter ("Timer C");
800 
801  // Timers A and B get nonzero elapsed times and call counts on all
802  // (MPI) processes. Timer C never gets started, so it should have
803  // a zero elapsed time and zero call count on all processes.
804 
805  // The actual number of operations in the loop is proportional to
806  // the cube of the loop length. Adjust the quantities below as
807  // necessary to ensure the timer reports a nonzero elapsed time
808  // for each of the invocations.
809  const size_t timerA_loopLength = 200;
810  const size_t timerB_loopLength = 250;
811 
812  // Timer A gets a call count of 3.
813  for (size_t k = 0; k < 3; ++k) {
814  TimeMonitor monitorA (*timerA);
815  slowLoop (size_t (timerA_loopLength));
816  }
817  // Timer B gets a call count of 1.
818  {
819  TimeMonitor monitorB (*timerB);
820  slowLoop (size_t (timerB_loopLength));
821  }
822 
823  const bool alwaysWriteLocal = false; // the default
824  const bool writeGlobalStats = true; // the default
825  const bool writeZeroTimers = false; // NOT the default
826  TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
827  writeZeroTimers);
828 
829  // Echo summarize() output to the FancyOStream out (which is a
830  // standard unit test argument). Output should only appear in
831  // show-all-test-details mode.
832  out << oss.str() << std::endl;
833 
834  // Timers A and B should be reported.
836  size_t substr_i = oss.str().find ("Timer A");
837  TEST_INEQUALITY(substr_i, std::string::npos);
838  substr_i = oss.str().find ("Timer B");
839  TEST_INEQUALITY(substr_i, std::string::npos);
840 
841  // Timer C should NOT be reported.
842  substr_i = oss.str().find ("Timer C");
843  TEST_EQUALITY(substr_i, std::string::npos);
844  }
845 
846  // This sets up for the next unit test.
848  }
849 
850 
851  //
852  // Test whether the option to filter out zero timers works, for the
853  // case that different (MPI) processes have different call counts.
854  //
855  TEUCHOS_UNIT_TEST( TimeMonitor, FILTER_ZERO_TIMERS_differentParallelCallCounts )
856  {
858  const int myRank = comm->getRank ();
859 
860  // If MPI has not been initialized, turn the MPI communicator into
861  // a "serial" communicator. This may not be necessary when using
862  // the Teuchos Unit Test Framework.
863 #ifdef HAVE_MPI
864  {
865  int mpiHasBeenInitialized = 0;
866  MPI_Initialized (&mpiHasBeenInitialized);
867  if (! mpiHasBeenInitialized) {
869  }
870  }
871 #endif // HAVE_MPI
872 
873  // Store the output of TimeMonitor::summarize() here.
874  std::ostringstream oss;
875 
876  RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
877  RCP<Time> timerB = TimeMonitor::getNewCounter ("Timer B");
878  RCP<Time> timerC = TimeMonitor::getNewCounter ("Timer C");
879 
880  // Timer A gets a nonzero elapsed time and call count on Proc 0,
881  // but a zero elapsed time and call count elsewhere.
882  //
883  // Timer B gets the same nonzero elapsed time and call count on
884  // all MPI procs.
885  //
886  // Timer C gets a zero elapsed time and call count on all procs.
887  //
888  // The actual number of operations in the loop is proportional to
889  // the cube of the loop length. Adjust the quantities below as
890  // necessary to ensure the timer reports a nonzero elapsed time
891  // for each of the invocations.
892  const size_t timerA_loopLength = 200;
893  const size_t timerB_loopLength = 500;
894 
895  if (myRank == 0) {
896  // Timer A gets a call count of 3 on Proc 0.
897  for (int k = 0; k < 3; ++k) {
898  TimeMonitor monitorA (*timerA);
899  slowLoop (size_t (timerA_loopLength));
900  }
901  }
902 
903  // Timer B gets a call count of 1 on all procs.
904  {
905  TimeMonitor monitorB (*timerB);
906  slowLoop (size_t (timerB_loopLength));
907  }
908 
909  const bool alwaysWriteLocal = false; // the default
910  const bool writeGlobalStats = true; // the default
911  const bool writeZeroTimers = false; // NOT the default
912  TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
913  writeZeroTimers, Union);
914 
915  // Echo summarize() output to the FancyOStream out (which is a
916  // standard unit test argument). Output should only appear in
917  // show-all-test-details mode.
918  out << oss.str() << std::endl;
919 
921  // Timers A and B should both be reported.
922  size_t substr_i = oss.str().find ("Timer A");
923  TEST_INEQUALITY(substr_i, std::string::npos);
924  substr_i = oss.str().find ("Timer B");
925  TEST_INEQUALITY(substr_i, std::string::npos);
926 
927  // Timer C should NOT be reported.
928  substr_i = oss.str().find ("Timer C");
929  TEST_EQUALITY(substr_i, std::string::npos);
930  }
931 
932  // This sets up for the next unit test (if there is one).
934  }
935 
936  //
937  // Test option to disregard missing timers from processes in TimeMonitor::summarize().
938  //
939  TEUCHOS_UNIT_TEST( TimeMonitor, IgnoreMissingTimers )
940  {
942  const int myRank = comm->getRank ();
943 
944 #ifdef HAVE_MPI
945  {
946  int mpiHasBeenInitialized = 0;
947  MPI_Initialized (&mpiHasBeenInitialized);
948  if (! mpiHasBeenInitialized) {
950  }
951  }
952 #endif // HAVE_MPI
953 
954  // Store the output of TimeMonitor::summarize() here.
955  std::ostringstream oss;
956 
957  std::string timerName="Timer Z";
958  // Timer Z appears on all PIDs except 0.
959  {
960  switch (myRank) {
961  case 1 :
962  break;
963  case 0 :
964  {
965  RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
966  TimeMonitor monitor (*timer);
967  sleep(1);
968  }
969  break;
970  case 2 :
971  {
972  RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
973  TimeMonitor monitor (*timer);
974  sleep(1);
975  }
976  break;
977  default :
978  {
979  RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
980  TimeMonitor monitor (*timer);
981  sleep(1);
982  }
983  }
984  }
985 
987  // test two versions of summarize with default behavior
989 
990  //version 1, comm provided
991  const bool alwaysWriteLocal = false;
992  const bool writeGlobalStats = true;
993  const bool writeZeroTimers = false;
994  bool ignoreMissingTimers = false; // the default
995  std::string filter = "";
996  TimeMonitor::summarize (comm.ptr(), oss, alwaysWriteLocal, writeGlobalStats,
997  writeZeroTimers, Union, filter, ignoreMissingTimers);
998 
999  // Echo summarize() output to the FancyOStream out (which is a
1000  // standard unit test argument). Output should only appear in
1001  // show-all-test-details mode.
1002  out << oss.str() << std::endl;
1003 
1004  if (comm->getSize() > 1) {
1005  // The min should be 0
1007  size_t substr_i = oss.str().find ("0 (0)");
1008  TEST_INEQUALITY(substr_i, std::string::npos);
1009  }
1010  }
1011 
1012  //version 2, no comm provided
1013  std::ostringstream oss2;
1014  TimeMonitor::summarize (oss2, alwaysWriteLocal, writeGlobalStats,
1015  writeZeroTimers, Union, filter, ignoreMissingTimers);
1016  out << oss2.str() << std::endl;
1017  if (comm->getSize() > 1) {
1018  // The min should be 0
1020  size_t substr_i = oss2.str().find ("0 (0)");
1021  TEST_INEQUALITY(substr_i, std::string::npos);
1022  }
1023  }
1024 
1026  // test two versions of summarize with *non* default behavior
1028  //version 1, comm provided
1029  ignoreMissingTimers = true; // NOT the default
1030  std::ostringstream oss3;
1031  TimeMonitor::summarize (comm.ptr(), oss3, alwaysWriteLocal, writeGlobalStats,
1032  writeZeroTimers, Union, filter, ignoreMissingTimers);
1033  out << oss3.str() << std::endl;
1034 
1035  // The min should be different from 0
1036  size_t substr_i = oss3.str().find ("0 (0)");
1037  TEST_EQUALITY(substr_i, std::string::npos);
1038 
1039  //version 2, no comm provided
1040  std::ostringstream oss4;
1041  TimeMonitor::summarize (oss4, alwaysWriteLocal, writeGlobalStats,
1042  writeZeroTimers, Union, filter, ignoreMissingTimers);
1043  out << oss4.str() << std::endl;
1044  // The min should be different from 0
1045  substr_i = oss4.str().find ("0 (0)");
1046  TEST_EQUALITY(substr_i, std::string::npos);
1047 
1048  // This sets up for the next unit test (if there is one).
1050  }
1051 
1052  //
1053  // Test that Time::start() and Time::stop() call Kokkos::fence(),
1054  // if the option to do that is enabled.
1055  //
1056  #ifdef HAVE_TEUCHOSCORE_KOKKOS
1057  namespace KokkosFenceCounter
1058  {
1059  static int numFences;
1060 
1061  void reset()
1062  {
1063  numFences = 0;
1064  }
1065 
1066  void begin_fence_callback(const char*, const uint32_t deviceId, uint64_t*) {
1067  using namespace Kokkos::Tools::Experimental;
1068  // Only count global device fences on the default space. Otherwise fences
1069  // could be counted multiple times, depending on how many backends are enabled.
1070  DeviceType fenceDevice = identifier_from_devid(deviceId).type;
1071  DeviceType defaultDevice = DeviceTypeTraits<Kokkos::DefaultExecutionSpace>::id;
1072  if(fenceDevice == defaultDevice)
1073  numFences++;
1074  }
1075  }
1076 
1077  TEUCHOS_UNIT_TEST( TimeMonitor, CheckTimerKokkosFences )
1078  {
1079  // This test doesn't care about the comm size or rank because Kokkos
1080  // fences and profiling is purely local to each rank.
1081  //
1082  // Set up the fence counter (reset count to 0 and set the callback)
1083  KokkosFenceCounter::reset();
1084  Kokkos::Tools::Experimental::set_begin_fence_callback(KokkosFenceCounter::begin_fence_callback);
1085  int fenceCountAfterStart = 0;
1086  int fenceCountAfterStop = 0;
1087 
1088  {
1089  RCP<Time> timer = TimeMonitor::getNewCounter ("Timer XYZ");
1090  TimeMonitor monitor (*timer);
1091  // Timer has started; record current fence count
1092  fenceCountAfterStart = KokkosFenceCounter::numFences;
1093  }
1094  // Timer has stopped; record again
1095  fenceCountAfterStop = KokkosFenceCounter::numFences;
1096  if (Behavior::fenceTimers()) {
1097  TEST_EQUALITY(fenceCountAfterStart, 1);
1098  TEST_EQUALITY(fenceCountAfterStop, 2);
1099  } else {
1100  TEST_EQUALITY(fenceCountAfterStart, 0);
1101  TEST_EQUALITY(fenceCountAfterStop, 0);
1102  }
1103 
1104  // This sets up for the next unit test (if there is one).
1106  }
1107  #endif
1108 
1109 } // namespace Teuchos
static int getRank()
The rank of the calling process in MPI_COMM_WORLD.
#define TEUCHOS_FUNC_TIME_MONITOR(FUNCNAME)
Defines a timer for a specific function.
#define TEST_INEQUALITY(v1, v2)
Assert the inequality of v1 and v2.
static Teuchos::RCP< const Comm< OrdinalType > > getDefaultSerialComm(const Teuchos::RCP< const Comm< OrdinalType > > &comm)
Return a serial Comm if the input Comm is null.
static void clearCounters()
&quot;Forget&quot; about all counters created with getNewCounter().
#define TEST_NOTHROW(code)
Asserr that the statement &#39;code&#39; does not thrown any excpetions.
static RCP< Time > getNewCounter(const std::string &name)
Create a new counter with the specified name and add it to a global set of counters of this type...
#define TEUCHOS_TEST_FOR_EXCEPTION(throw_exception_test, Exception, msg)
Macro for throwing an exception with breakpointing to ease debugging.
static void disableTimer(const std::string &name)
Disable the timer with the given name.
#define TEST_EQUALITY(v1, v2)
Assert the equality of v1 and v2.
ParameterList & set(std::string const &name, T &&value, std::string const &docString="", RCP< const ParameterEntryValidator > const &validator=null)
Templated set method.
static Teuchos::RCP< const Comm< OrdinalType > > getComm()
Return the default global communicator.
static RCP< const ParameterList > getValidReportParameters()
Default parameters (with validators) for report().
basic_OSTab< char > OSTab
static RCP< Time > getNewTimer(const std::string &name)
Return a new timer with the given name (class method).
TEUCHOS_UNIT_TEST(ConstNonconstObjectContainer, create)
static void summarize(Ptr< const Comm< int > > comm, std::ostream &out=std::cout, const bool alwaysWriteLocal=false, const bool writeGlobalStats=true, const bool writeZeroTimers=true, const ECounterSetOp setOp=Intersection, const std::string &filter="", const bool ignoreZeroTimers=false)
Print summary statistics for all timers on the given communicator.
Wall-clock timer.
Ptr< T > ptr() const
Get a safer wrapper raw C++ pointer to the underlying object.
Unit testing support.
static bool fenceTimers()
A list of parameters of arbitrary type.
void push_back(const value_type &x)
A MPI utilities class, providing methods for initializing, finalizing, and querying the global MPI se...
size_type size() const
Scope guard for Teuchos::Time, with MPI collective timer reporting.
Smart reference counting pointer class for automatic garbage collection.
static void enableTimer(const std::string &name)
Enable the timer with the given name.
Scope guard for Time, that can compute MPI collective timer statistics.
static void report(Ptr< const Comm< int > > comm, std::ostream &out, const std::string &filter, const RCP< ParameterList > &params=null)
Report timer statistics to the given output stream.
#define TEUCHOS_FUNC_TIME_MONITOR_DIFF(FUNCNAME, DIFF)
Defines a timer for a specific function (with differentiator).
Replacement for std::vector that is compatible with the Teuchos Memory Management classes...