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 /*
2 // @HEADER
3 // ***********************************************************************
4 //
5 // Teuchos: Common Tools Package
6 // Copyright (2004) Sandia Corporation
7 //
8 // Under terms of Contract DE-AC04-94AL85000, there is a non-exclusive
9 // license for use of this work by or on behalf of the U.S. Government.
10 //
11 // Redistribution and use in source and binary forms, with or without
12 // modification, are permitted provided that the following conditions are
13 // met:
14 //
15 // 1. Redistributions of source code must retain the above copyright
16 // notice, this list of conditions and the following disclaimer.
17 //
18 // 2. Redistributions in binary form must reproduce the above copyright
19 // notice, this list of conditions and the following disclaimer in the
20 // documentation and/or other materials provided with the distribution.
21 //
22 // 3. Neither the name of the Corporation nor the names of the
23 // contributors may be used to endorse or promote products derived from
24 // this software without specific prior written permission.
25 //
26 // THIS SOFTWARE IS PROVIDED BY SANDIA CORPORATION "AS IS" AND ANY
27 // EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
28 // IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
29 // PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL SANDIA CORPORATION OR THE
30 // CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL,
31 // EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
32 // PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
33 // PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
34 // LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
35 // NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
36 // SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
37 //
38 // Questions? Contact Michael A. Heroux (maherou@sandia.gov)
39 //
40 // ***********************************************************************
41 // @HEADER
42 */
43 
44 #include "Teuchos_TimeMonitor.hpp"
45 #include "Teuchos_DefaultComm.hpp"
48 
49 // slowLoop does not reliably make a timer nonzero (RHEL6, gcc 4.4.7, OpenMPI 1.5.4).
50 // Thus, I'm introducing headers to make sleep() available.
51 #ifndef ICL
52 #include <unistd.h>
53 #else
54 void sleep(int sec)
55 {
56  Sleep(sec);
57 }
58 #endif
59 
60 #ifdef _MSC_VER
61 #pragma comment(lib, "Ws2_32.lib")
62 # include <Winsock2.h>
63 # include <process.h>
64 void sleep(int sec)
65 {
66  Sleep(sec * 1000);
67 }
68 #endif
69 
70 namespace {
71 
72  void func_time_monitor1()
73  {
74  TEUCHOS_FUNC_TIME_MONITOR("FUNC_TIME_MONITOR1");
75  }
76 
77 
78  void func_time_monitor2()
79  {
80  TEUCHOS_FUNC_TIME_MONITOR("FUNC_TIME_MONITOR2");
81  {
82  TEUCHOS_FUNC_TIME_MONITOR_DIFF("FUNC_TIME_MONITOR2_inner", inner);
83  }
84  }
85 
86  // This function is commented out because no code in this file
87  // actually uses it. Commenting it out avoids compiler warnings
88  // ("unused function").
89 #if 0
90  // Slowly compute the n-th Fibonacci number. This gives timers
91  // something to time. Be careful not to make n too large, or you'll
92  // run out of stack space.
93  int
94  fib (const int n)
95  {
96  if (n <= 0) {
97  return 0;
98  } else if (n == 1) {
99  return 1;
100  }
101  else {
102  // You should never compute the n-th Fibonacci number like this.
103  // This is exponentially slow in n. The point of using a slow
104  // algorithm like this is to exercise timers.
105  return fib (n-1) + fib (n-2);
106  }
107  }
108 #endif // 0
109 
110  // Do a number of arithmetic operations proportional to n^3, in
111  // order to have something to time. Unlike the recursive function
112  // fib() commented out above, this function shouldn't take up a lot
113  // of stack space.
114  double
115  slowLoop (const size_t n)
116  {
117  const double inc = 1 / static_cast<double> (n);
118  double x = 1.0;
119 
120  for (size_t i = 0; i < n; ++i) {
121  for (size_t j = 0; j < n; ++j) {
122  for (size_t k = 0; k < n; ++k) {
123  x = x + inc;
124  }
125  }
126  }
127  return x;
128  }
129 
130 } // namespace (anonymous)
131 
132 
133 namespace Teuchos {
134  //
135  // Basic TimeMonitor test: create and exercise a timer on all (MPI)
136  // processes, and make sure that TimeMonitor::summarize() reports it.
137  //
138  TEUCHOS_UNIT_TEST( TimeMonitor, FUNC_TIME_MONITOR )
139  {
141  using Teuchos::parameterList;
142  using Teuchos::RCP;
143 
144  func_time_monitor1 (); // Function to time.
145 
146  { // Repeat test for default output format.
147  std::ostringstream oss;
149 
150  // Echo summarize() output to the FancyOStream out (which is a
151  // standard unit test argument). Output should only appear in
152  // show-all-test-details mode.
153  out << oss.str () << std::endl;
154 
155  // Make sure that the timer's name shows up in the output.
157  const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
158  TEST_INEQUALITY(substr_i, std::string::npos);
159  }
160  }
161 
162  { // Repeat test for YAML output, compact style.
163  std::ostringstream oss;
164  RCP<ParameterList> reportParams =
165  parameterList (* (TimeMonitor::getValidReportParameters ()));
166  reportParams->set ("Report format", "YAML");
167  reportParams->set ("YAML style", "compact");
168  TimeMonitor::report (oss, reportParams);
169 
170  // Echo output to the FancyOStream out (which is a standard unit
171  // test argument). Output should only appear in "show all test
172  // details" mode.
173  out << oss.str () << std::endl;
174 
175  // Make sure that the timer's name shows up in the output.
176  const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
177  TEST_INEQUALITY(substr_i, std::string::npos);
178  }
179 
180  { // Repeat test for YAML output, spacious style.
181  std::ostringstream oss;
182  RCP<ParameterList> reportParams =
183  parameterList (* (TimeMonitor::getValidReportParameters ()));
184  reportParams->set ("Report format", "YAML");
185  reportParams->set ("YAML style", "spacious");
186  TimeMonitor::report (oss, reportParams);
187 
188  // Echo output to the FancyOStream out (which is a standard unit
189  // test argument). Output should only appear in "show all test
190  // details" mode.
191  out << oss.str () << std::endl;
192 
193  // Make sure that the timer's name shows up in the output.
194  const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
195  TEST_INEQUALITY(substr_i, std::string::npos);
196  }
197 
198  // This sets up for the next unit test.
200  }
201 
202  //
203  // Test for TimeMonitor's enableTimer and disableTimer methods.
204  //
206  {
207  using Teuchos::Array;
208  using Teuchos::OSTab;
210  using Teuchos::parameterList;
211  using Teuchos::RCP;
212  using Teuchos::rcpFromRef;
213  using Teuchos::Time;
214  using Teuchos::TimeMonitor;
215  using std::endl;
216  typedef Teuchos::Array<RCP<Time> >::size_type size_type;
217 
218  out << "Testing TimeMonitor's disableTimer() and enableTimer() methods"
219  << endl;
220  OSTab (rcpFromRef (out));
221 
222  out << "Creating timers" << endl;
223  const int numTrials = 5;
224  const int numTimers = 3;
225  Array<RCP<Time> > timers (numTimers);
226  for (size_type i = 0; i < numTimers; ++i) {
227  std::ostringstream os; // construct timer name
228  os << "Timer " << i;
229  timers[i] = TimeMonitor::getNewTimer (os.str ());
230  }
231 
232  out << "Running all timers without disabling any" << endl;
233  // The actual number of operations in slowloop is proportional to
234  // the cube of the loop length. Adjust loopLength as necessary to
235  // ensure the timer reports a nonzero elapsed time for each of the
236  // invocations.
237  const size_t loopLength = 25;
238  for (int k = 0; k < numTrials; ++k) {
239  for (size_type i = 0; i < numTimers; ++i) {
240  TimeMonitor timeMon (* timers[i]);
241  slowLoop (loopLength);
242  }
243  }
244  for (size_type i = 0; i < numTimers; ++i) {
245  TEST_EQUALITY( timers[i]->numCalls(), numTrials );
246  }
247 
248  out << "Disabling one timer and trying again" << endl;
249  // Disable timers[0] only, and repeat the above loops.
251  for (int k = 0; k < numTrials; ++k) {
252  for (size_type i = 0; i < numTimers; ++i) {
253  TimeMonitor timeMon (* timers[i]);
254  slowLoop (loopLength);
255  }
256  }
257  TEST_EQUALITY( timers[0]->numCalls(), numTrials );
258  for (size_type i = 1; i < numTimers; ++i) {
259  TEST_EQUALITY( timers[i]->numCalls(), 2*numTrials );
260  }
261 
262  out << "Reenabling the timer and trying again" << endl;
263  // Enable timers[0] and repeat the above loops.
264  TEST_NOTHROW( TimeMonitor::enableTimer ("Timer 0") );
265  for (int k = 0; k < numTrials; ++k) {
266  for (size_type i = 0; i < numTimers; ++i) {
267  TimeMonitor timeMon (* timers[i]);
268  slowLoop (loopLength);
269  }
270  }
271  TEST_EQUALITY( timers[0]->numCalls(), 2*numTrials );
272  for (size_type i = 1; i < numTimers; ++i) {
273  TEST_EQUALITY( timers[i]->numCalls(), 3*numTrials );
274  }
275 
276  out << "Test that summarize() reports enabled and disabled timers" << endl;
277  // Make sure that summarize() reports all timers. Disabling a
278  // timer must _not_ exclude it from the list of timers printed by
279  // summarize(). Disable a different timer this time just for fun.
281  {
282  std::ostringstream oss;
284 
285  // Echo summarize() output to the FancyOStream out (which is a
286  // standard unit test argument). Output should only appear in
287  // show-all-test-details mode.
288  out << oss.str () << std::endl;
289 
290  // Make sure that each timer's name shows up in the output.
291  for (size_type i = 0; i < numTimers; ++i) {
292  const std::string name = timers[i]->name ();
294  const size_t substr_i = oss.str ().find (name);
295  TEST_INEQUALITY(substr_i, std::string::npos);
296  }
297  }
298  }
299 
300  // This sets up for the next unit test.
302  }
303 
304 
305  //
306  // Test correct quoting of labels for TimeMonitor's YAML output.
307  //
308  TEUCHOS_UNIT_TEST( TimeMonitor, YamlLabelQuoting )
309  {
310  using Teuchos::Array;
312  using Teuchos::parameterList;
313  using Teuchos::RCP;
314  using Teuchos::Time;
315  typedef Array<std::string>::size_type size_type;
316 
317  Array<std::string> inputLabels, outputLabels;
318 
319  // Make sure to exercise things that don't need quoting, like
320  // spaces and certain punctuation, as well as things that do need
321  // quoting, like colons, inner double quotes, and backslashes.
322  inputLabels.push_back ("NoQuotingNeeded");
323  inputLabels.push_back ("No quoting needed");
324  inputLabels.push_back ("\"AlreadyQuotedNoQuotingNeeded\"");
325  inputLabels.push_back ("\"Already quoted, no quoting needed\"");
326  inputLabels.push_back ("\"Already quoted: quoting needed\"");
327  inputLabels.push_back ("NotQuoted:QuotingNeeded");
328  inputLabels.push_back ("Not quoted: quoting needed");
329  // Test both individual double quotes, and pairs of double quotes.
330  inputLabels.push_back ("Not quoted \" quoting needed");
331  inputLabels.push_back ("Not quoted \" \" quoting needed");
332  inputLabels.push_back ("\"Already quoted \" quoting needed\"");
333  inputLabels.push_back ("\"Already quoted \" \" quoting needed\"");
334  // Remember that in C strings, a double backslash turns into a
335  // single backslash. Our YAML output routine should turn each
336  // single backslash back into a double backslash.
337  inputLabels.push_back ("Not quoted \\ quoting needed");
338  inputLabels.push_back ("Not quoted \\\\ quoting needed");
339  inputLabels.push_back ("Not quoted \\ \\ quoting needed");
340  inputLabels.push_back ("\"Already quoted \\ quoting needed\"");
341  inputLabels.push_back ("\"Already quoted \\\\ quoting needed\"");
342  inputLabels.push_back ("\"Already quoted \\ \\ quoting needed\"");
343 
344  outputLabels.push_back ("NoQuotingNeeded");
345  outputLabels.push_back ("No quoting needed");
346  outputLabels.push_back ("\"AlreadyQuotedNoQuotingNeeded\"");
347  outputLabels.push_back ("\"Already quoted, no quoting needed\"");
348  outputLabels.push_back ("\"Already quoted: quoting needed\"");
349  outputLabels.push_back ("\"NotQuoted:QuotingNeeded\"");
350  outputLabels.push_back ("\"Not quoted: quoting needed\"");
351  outputLabels.push_back ("\"Not quoted \\\" quoting needed\"");
352  outputLabels.push_back ("\"Not quoted \\\" \\\" quoting needed\"");
353  outputLabels.push_back ("\"Already quoted \\\" quoting needed\"");
354  outputLabels.push_back ("\"Already quoted \\\" \\\" quoting needed\"");
355  outputLabels.push_back ("\"Not quoted \\\\ quoting needed\"");
356  outputLabels.push_back ("\"Not quoted \\\\\\\\ quoting needed\"");
357  outputLabels.push_back ("\"Not quoted \\\\ \\\\ quoting needed\"");
358  outputLabels.push_back ("\"Already quoted \\\\ quoting needed\"");
359  outputLabels.push_back ("\"Already quoted \\\\\\\\ quoting needed\"");
360  outputLabels.push_back ("\"Already quoted \\\\ \\\\ quoting needed\"");
361 
362  // Sanity check.
364  inputLabels.size () != outputLabels.size (),
365  std::logic_error,
366  "The number of input labels is different than the number of output labels."
367  " Please ask a Teuchos developer to make sure that every test input "
368  "label has a corresponding output label.");
369 
370  Array<RCP<Time> > timers;
371  for (size_type i = 0; i < inputLabels.size (); ++i) {
372  timers.push_back (TimeMonitor::getNewCounter (inputLabels[i]));
373  }
374 
375  // The actual number of operations in the loop is proportional to
376  // the cube of the loop length. Adjust the quantities below as
377  // necessary to ensure the timer reports a nonzero elapsed time
378  // for each of the invocations.
379  const size_t loopLength = 25;
380  for (int k = 0; k < 3; ++k) {
381  for (size_type i = 0; i < timers.size (); ++i) {
382  TimeMonitor timeMon (* timers[i]);
383  slowLoop (loopLength);
384  }
385  }
386 
387  { // YAML output, compact style.
388  std::ostringstream oss;
389  RCP<ParameterList> reportParams =
390  parameterList (* (TimeMonitor::getValidReportParameters ()));
391  reportParams->set ("Report format", "YAML");
392  reportParams->set ("YAML style", "compact");
393  TimeMonitor::report (oss, reportParams);
394 
395  // Echo output to the FancyOStream out (which is a standard unit
396  // test argument). Output should only appear in "show all test
397  // details" mode.
398  out << oss.str () << std::endl;
399 
400  // Make sure that all timer labels appear correctly in the output.
401  for (size_type i = 0; i < inputLabels.size(); ++i) {
402  const size_t pos = oss.str ().find (outputLabels[i]);
403  TEST_INEQUALITY(pos, std::string::npos);
404  }
405  }
406 
407  { // YAML output, spacious style.
408  std::ostringstream oss;
409  RCP<ParameterList> reportParams =
410  parameterList (* (TimeMonitor::getValidReportParameters ()));
411  reportParams->set ("Report format", "YAML");
412  reportParams->set ("YAML style", "spacious");
413  TimeMonitor::report (oss, reportParams);
414 
415  // Echo output to the FancyOStream out (which is a standard unit
416  // test argument). Output should only appear in "show all test
417  // details" mode.
418  out << oss.str () << std::endl;
419 
420  // Make sure that all timer labels appear correctly in the output.
421  for (size_type i = 0; i < inputLabels.size(); ++i) {
422  const size_t pos = oss.str ().find (outputLabels[i]);
423  TEST_INEQUALITY(pos, std::string::npos);
424  }
425  }
426 
427  // This sets up for the next unit test.
429  }
430 
431 
432  //
433  // Test filtering of timer labels.
434  //
435  TEUCHOS_UNIT_TEST( TimeMonitor, TimerLabelFiltering )
436  {
437  using Teuchos::Array;
439  using Teuchos::parameterList;
440  using Teuchos::RCP;
441  using Teuchos::Time;
442  typedef Array<std::string>::size_type size_type;
443 
444  // Filters to use in the test.
445  Array<std::string> filters;
446  filters.push_back ("Foo:");
447  filters.push_back ("Bar:");
448  filters.push_back ("Baz:");
449 
450  // All the timer labels.
451  Array<std::string> labels;
452  labels.push_back ("Foo: timer 1");
453  labels.push_back ("Foo: timer 2");
454  labels.push_back ("Foo: timer 3");
455  labels.push_back ("Bar: timer 1");
456  labels.push_back ("Bar: timer 2");
457  labels.push_back ("Baz: timer 1");
458  labels.push_back ("Xyzzy");
459  labels.push_back ("This is not a pipe");
460  labels.push_back ("You should not see this");
461 
462  Array<Array<std::string> > outLabels (3);
463  // Label(s) that should be printed for filters[0]
464  outLabels[0].push_back ("Foo: timer 1");
465  outLabels[0].push_back ("Foo: timer 2");
466  outLabels[0].push_back ("Foo: timer 3");
467  // Label(s) that should be printed for filters[1]
468  outLabels[1].push_back ("Bar: timer 1");
469  outLabels[1].push_back ("Bar: timer 2");
470  // Label(s) that should be printed for filters[2]
471  outLabels[2].push_back ("Baz: timer 1");
472 
473  // Labels that should not be printed for any of the filters below.
474  Array<std::string> otherLabels;
475  otherLabels.push_back ("Xyzzy");
476  otherLabels.push_back ("This is not a pipe");
477  otherLabels.push_back ("You should not see this");
478 
479  Array<RCP<Time> > timers;
480  for (size_type i = 0; i < labels.size (); ++i) {
481  timers.push_back (TimeMonitor::getNewCounter (labels[i]));
482  }
483 
484  // The actual number of operations in the loop is proportional to
485  // the cube of the loop length. Adjust the quantities below as
486  // necessary to ensure the timer reports a nonzero elapsed time
487  // for each of the invocations.
488  const size_t loopLength = 25;
489  for (int k = 0; k < 3; ++k) {
490  for (size_type i = 0; i < timers.size (); ++i) {
491  TimeMonitor timeMon (* timers[i]);
492  slowLoop (loopLength);
493  }
494  }
495 
496  try {
497  // FIXME (mfh 21 Aug 2012) We don't yet have a test ensuring that
498  // the filter only selects at the beginning of the timer label.
499 
500  // Test for each filter.
501  for (size_type i = 0; i < filters.size (); ++i) {
502  { // Default (tabular) output format.
503  std::ostringstream oss;
504  RCP<ParameterList> reportParams =
505  parameterList (* (TimeMonitor::getValidReportParameters ()));
506  TimeMonitor::report (oss, filters[i], reportParams);
507 
508  // Echo output to the FancyOStream out (which is a standard unit
509  // test argument). Output should only appear in "show all test
510  // details" mode.
511  out << oss.str () << std::endl;
512 
513  // Check whether the labels that were supposed to be printed
514  // were actually printed.
516  for (size_type j = 0; j < outLabels[i].size(); ++j) {
517  const size_t pos = oss.str ().find (outLabels[i][j]);
518  TEST_INEQUALITY(pos, std::string::npos);
519  }
520  }
521 
522  // Check whether the labels that were _not_ supposed to be
523  // printed were actually printed.
524  //
525  // First, check the labels that should only be printed with
526  // the other filters.
527  for (size_type ii = 0; ii < outLabels.size(); ++ii) {
528  if (ii != i) {
529  for (size_type j = 0; j < outLabels[ii].size(); ++j) {
530  const size_t pos = oss.str ().find (outLabels[ii][j]);
531  TEST_EQUALITY(pos, std::string::npos);
532  }
533  }
534  }
535  // Next, check the labels that should not be printed for any
536  // filters.
537  for (size_type j = 0; j < otherLabels.size(); ++j) {
538  const size_t pos = oss.str ().find (otherLabels[j]);
539  TEST_EQUALITY(pos, std::string::npos);
540  }
541  }
542 
543  { // YAML output, compact style.
544  std::ostringstream oss;
545  RCP<ParameterList> reportParams =
546  parameterList (* (TimeMonitor::getValidReportParameters ()));
547  reportParams->set ("Report format", "YAML");
548  reportParams->set ("YAML style", "compact");
549  TimeMonitor::report (oss, filters[i], reportParams);
550 
551  // Echo output to the FancyOStream out (which is a standard unit
552  // test argument). Output should only appear in "show all test
553  // details" mode.
554  out << oss.str () << std::endl;
555 
556  // Check whether the labels that were supposed to be printed
557  // were actually printed.
558  for (size_type j = 0; j < outLabels[i].size(); ++j) {
559  const size_t pos = oss.str ().find (outLabels[i][j]);
560  TEST_INEQUALITY(pos, std::string::npos);
561  }
562 
563  // Check whether the labels that were _not_ supposed to be
564  // printed were actually printed.
565  //
566  // First, check the labels that should only be printed with
567  // the other filters.
568  for (size_type ii = 0; ii < outLabels.size(); ++ii) {
569  if (ii != i) {
570  for (size_type j = 0; j < outLabels[ii].size(); ++j) {
571  const size_t pos = oss.str ().find (outLabels[ii][j]);
572  TEST_EQUALITY(pos, std::string::npos);
573  }
574  }
575  }
576  // Next, check the labels that should not be printed for any
577  // filters.
578  for (size_type j = 0; j < otherLabels.size(); ++j) {
579  const size_t pos = oss.str ().find (otherLabels[j]);
580  TEST_EQUALITY(pos, std::string::npos);
581  }
582  }
583 
584  { // YAML output, spacious style.
585  std::ostringstream oss;
586  RCP<ParameterList> reportParams =
587  parameterList (* (TimeMonitor::getValidReportParameters ()));
588  reportParams->set ("Report format", "YAML");
589  reportParams->set ("YAML style", "spacious");
590  TimeMonitor::report (oss, filters[i], reportParams);
591 
592  // Echo output to the FancyOStream out (which is a standard unit
593  // test argument). Output should only appear in "show all test
594  // details" mode.
595  out << oss.str () << std::endl;
596 
597  // Check whether the labels that were supposed to be printed
598  // were actually printed.
599  for (size_type j = 0; j < outLabels[i].size(); ++j) {
600  const size_t pos = oss.str ().find (outLabels[i][j]);
601  TEST_INEQUALITY(pos, std::string::npos);
602  }
603 
604  // Check whether the labels that were _not_ supposed to be
605  // printed were actually printed.
606  //
607  // First, check the labels that should only be printed with
608  // the other filters.
609  for (size_type ii = 0; ii < outLabels.size(); ++ii) {
610  if (ii != i) {
611  for (size_type j = 0; j < outLabels[ii].size(); ++j) {
612  const size_t pos = oss.str ().find (outLabels[ii][j]);
613  TEST_EQUALITY(pos, std::string::npos);
614  }
615  }
616  }
617  // Next, check the labels that should not be printed for any
618  // filters.
619  for (size_type j = 0; j < otherLabels.size(); ++j) {
620  const size_t pos = oss.str ().find (otherLabels[j]);
621  TEST_EQUALITY(pos, std::string::npos);
622  }
623  }
624  }
625  }
626  catch (...) {
627  // Make sure to clear the counters, so that they don't pollute
628  // the remaining tests. (The Teuchos unit test framework may
629  // catch any exceptions that the above code throws, but allow
630  // the remaining tests to continue.)
632  throw;
633  }
634 
635  // This sets up for the next unit test.
637  }
638 
639 
640 
641  //
642  // TimeMonitor nested timers test: create two timers on all (MPI)
643  // processes, use the second inside the scope of the first, and make
644  // sure that TimeMonitor::summarize() reports both timers.
645  //
646  TEUCHOS_UNIT_TEST( TimeMonitor, FUNC_TIME_MONITOR_tested )
647  {
649  using Teuchos::parameterList;
650  using Teuchos::RCP;
651 
652  func_time_monitor2 ();
653 
654  {
655  std::ostringstream oss;
657 
658  // Echo summarize() output to the FancyOStream out (which is a
659  // standard unit test argument). Output should only appear in
660  // show-all-test-details mode.
661  out << oss.str() << std::endl;
662 
664  const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
665  TEST_INEQUALITY(substr_i, std::string::npos);
666  const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
667  TEST_INEQUALITY(substr_inner_i, std::string::npos);
668  }
669  }
670 
671  { // Repeat test for YAML output, compact style.
672  std::ostringstream oss;
673  RCP<ParameterList> reportParams =
674  parameterList (* (TimeMonitor::getValidReportParameters ()));
675  reportParams->set ("Report format", "YAML");
676  reportParams->set ("YAML style", "compact");
677  TimeMonitor::report (oss, reportParams);
678 
679  // Echo output to the FancyOStream out (which is a standard unit
680  // test argument). Output should only appear in "show all test
681  // details" mode.
682  out << oss.str () << std::endl;
683 
684  const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
685  TEST_INEQUALITY(substr_i, std::string::npos);
686  const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
687  TEST_INEQUALITY(substr_inner_i, std::string::npos);
688  }
689 
690  { // Repeat test for YAML output, spacious style.
691  std::ostringstream oss;
692  RCP<ParameterList> reportParams =
693  parameterList (* (TimeMonitor::getValidReportParameters ()));
694  reportParams->set ("Report format", "YAML");
695  reportParams->set ("YAML style", "spacious");
696  TimeMonitor::report (oss, reportParams);
697 
698  // Echo output to the FancyOStream out (which is a standard unit
699  // test argument). Output should only appear in "show all test
700  // details" mode.
701  out << oss.str () << std::endl;
702 
703  const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
704  TEST_INEQUALITY(substr_i, std::string::npos);
705  const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
706  TEST_INEQUALITY(substr_inner_i, std::string::npos);
707  }
708 
709  // This sets up for the next unit test.
711  }
712 
713  //
714  // Test whether TimeMonitor::summarize() does the right thing when
715  // different MPI processes create different sets of timers. This
716  // test is only meaningful if running with more than one MPI
717  // process, but it should also pass if running in a non-MPI build or
718  // with only one MPI process.
719  //
720  TEUCHOS_UNIT_TEST( TimeMonitor, SUMMARIZE_diffTimerSets )
721  {
723  const int numProcs = comm->getSize ();
724  const int myRank = comm->getRank ();
725 
726  // If MPI has not been initialized, turn the MPI communicator into
727  // a "serial" communicator. This may not be necessary when using
728  // the Teuchos Unit Test Framework.
729 #ifdef HAVE_MPI
730  {
731  int mpiHasBeenInitialized = 0;
732  MPI_Initialized (&mpiHasBeenInitialized);
733  if (! mpiHasBeenInitialized) {
735  }
736  }
737 #endif // HAVE_MPI
738 
739  // Store the output of TimeMonitor::summarize() here.
740  std::ostringstream oss;
741 
742  // Timer A gets created on all MPI processes.
743  // Timer B only gets created on Proc 0.
744  RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
745  RCP<Time> timerB;
746  if (myRank == 0) {
747  timerB = TimeMonitor::getNewCounter ("Timer B");
748  }
749  else {
750  timerB = null; // True anyway, but I want to make this explicit.
751  }
752 
753  // The actual number of operations in the loop is proportional to
754  // the cube of the loop length. Adjust the quantities below as
755  // necessary to ensure the timer reports a nonzero elapsed time
756  // for each of the invocations.
757  const size_t timerA_loopLength = 150;
758  const size_t timerB_loopLength = 200;
759 
760  // Timer A gets a call count of 3.
761  for (size_t k = 0; k < 3; ++k) {
762  TimeMonitor monitorA (*timerA);
763  slowLoop (timerA_loopLength);
764  }
765  if (myRank == 0) { // Timer B gets a call count of 1 on Proc 0.
766  TimeMonitor monitorB (*timerB);
767  slowLoop (timerB_loopLength);
768  }
769 
770  const bool alwaysWriteLocal = false; // the default
771  const bool writeGlobalStats = true; // the default
772  const bool writeZeroTimers = true; // the default
773  TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
774  writeZeroTimers, Intersection);
775 
776  // Echo summarize() output to the FancyOStream out (which is a
777  // standard unit test argument). Output should only appear in
778  // show-all-test-details mode.
779  out << std::endl << "Testing intersection of timers:" << std::endl
780  << oss.str() << std::endl;
781 
782  // Since setOp == Intersection, only Timer A should be reported,
783  // unless there is only one (MPI) process.
785  size_t substr_i = oss.str().find ("Timer A");
786  TEST_INEQUALITY(substr_i, std::string::npos);
787  if (numProcs > 1) {
788  substr_i = oss.str().find ("Timer B");
789  TEST_EQUALITY(substr_i, std::string::npos);
790  }
791  }
792 
793  // Now call summarize(), but ask for a union of timers.
794  std::ostringstream ossUnion;
795  TimeMonitor::summarize (ossUnion, alwaysWriteLocal, writeGlobalStats,
796  writeZeroTimers, Union);
797 
798  // Echo summarize() output to the FancyOStream out (which is a
799  // standard unit test argument). Output should only appear in
800  // show-all-test-details mode.
801  out << std::endl << "Testing union of timers:" << std::endl
802  << ossUnion.str() << std::endl;
803 
804  // Since setOp == Union, both Timer A and Timer B should be
805  // reported.
807  size_t substr_i = ossUnion.str().find ("Timer A");
808  TEST_INEQUALITY(substr_i, std::string::npos);
809  substr_i = ossUnion.str().find ("Timer B");
810  TEST_INEQUALITY(substr_i, std::string::npos);
811  }
812 
813  // This sets up for the next unit test.
815  }
816 
817  //
818  // Test whether the option to filter out zero timers works, for the
819  // case that all (MPI) processes have the same call counts.
820  //
821  TEUCHOS_UNIT_TEST( TimeMonitor, FILTER_ZERO_TIMERS_sameParallelCallCounts )
822  {
823  // Store the output of TimeMonitor::summarize() here.
824  std::ostringstream oss;
825 
826  RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
827  RCP<Time> timerB = TimeMonitor::getNewCounter ("Timer B");
828  RCP<Time> timerC = TimeMonitor::getNewCounter ("Timer C");
829 
830  // Timers A and B get nonzero elapsed times and call counts on all
831  // (MPI) processes. Timer C never gets started, so it should have
832  // a zero elapsed time and zero call count on all processes.
833 
834  // The actual number of operations in the loop is proportional to
835  // the cube of the loop length. Adjust the quantities below as
836  // necessary to ensure the timer reports a nonzero elapsed time
837  // for each of the invocations.
838  const size_t timerA_loopLength = 200;
839  const size_t timerB_loopLength = 250;
840 
841  // Timer A gets a call count of 3.
842  for (size_t k = 0; k < 3; ++k) {
843  TimeMonitor monitorA (*timerA);
844  slowLoop (size_t (timerA_loopLength));
845  }
846  // Timer B gets a call count of 1.
847  {
848  TimeMonitor monitorB (*timerB);
849  slowLoop (size_t (timerB_loopLength));
850  }
851 
852  const bool alwaysWriteLocal = false; // the default
853  const bool writeGlobalStats = true; // the default
854  const bool writeZeroTimers = false; // NOT the default
855  TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
856  writeZeroTimers);
857 
858  // Echo summarize() output to the FancyOStream out (which is a
859  // standard unit test argument). Output should only appear in
860  // show-all-test-details mode.
861  out << oss.str() << std::endl;
862 
863  // Timers A and B should be reported.
865  size_t substr_i = oss.str().find ("Timer A");
866  TEST_INEQUALITY(substr_i, std::string::npos);
867  substr_i = oss.str().find ("Timer B");
868  TEST_INEQUALITY(substr_i, std::string::npos);
869 
870  // Timer C should NOT be reported.
871  substr_i = oss.str().find ("Timer C");
872  TEST_EQUALITY(substr_i, std::string::npos);
873  }
874 
875  // This sets up for the next unit test.
877  }
878 
879 
880  //
881  // Test whether the option to filter out zero timers works, for the
882  // case that different (MPI) processes have different call counts.
883  //
884  TEUCHOS_UNIT_TEST( TimeMonitor, FILTER_ZERO_TIMERS_differentParallelCallCounts )
885  {
887  const int myRank = comm->getRank ();
888 
889  // If MPI has not been initialized, turn the MPI communicator into
890  // a "serial" communicator. This may not be necessary when using
891  // the Teuchos Unit Test Framework.
892 #ifdef HAVE_MPI
893  {
894  int mpiHasBeenInitialized = 0;
895  MPI_Initialized (&mpiHasBeenInitialized);
896  if (! mpiHasBeenInitialized) {
898  }
899  }
900 #endif // HAVE_MPI
901 
902  // Store the output of TimeMonitor::summarize() here.
903  std::ostringstream oss;
904 
905  RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
906  RCP<Time> timerB = TimeMonitor::getNewCounter ("Timer B");
907  RCP<Time> timerC = TimeMonitor::getNewCounter ("Timer C");
908 
909  // Timer A gets a nonzero elapsed time and call count on Proc 0,
910  // but a zero elapsed time and call count elsewhere.
911  //
912  // Timer B gets the same nonzero elapsed time and call count on
913  // all MPI procs.
914  //
915  // Timer C gets a zero elapsed time and call count on all procs.
916  //
917  // The actual number of operations in the loop is proportional to
918  // the cube of the loop length. Adjust the quantities below as
919  // necessary to ensure the timer reports a nonzero elapsed time
920  // for each of the invocations.
921  const size_t timerA_loopLength = 200;
922  const size_t timerB_loopLength = 500;
923 
924  if (myRank == 0) {
925  // Timer A gets a call count of 3 on Proc 0.
926  for (int k = 0; k < 3; ++k) {
927  TimeMonitor monitorA (*timerA);
928  slowLoop (size_t (timerA_loopLength));
929  }
930  }
931 
932  // Timer B gets a call count of 1 on all procs.
933  {
934  TimeMonitor monitorB (*timerB);
935  slowLoop (size_t (timerB_loopLength));
936  }
937 
938  const bool alwaysWriteLocal = false; // the default
939  const bool writeGlobalStats = true; // the default
940  const bool writeZeroTimers = false; // NOT the default
941  TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
942  writeZeroTimers, Union);
943 
944  // Echo summarize() output to the FancyOStream out (which is a
945  // standard unit test argument). Output should only appear in
946  // show-all-test-details mode.
947  out << oss.str() << std::endl;
948 
950  // Timers A and B should both be reported.
951  size_t substr_i = oss.str().find ("Timer A");
952  TEST_INEQUALITY(substr_i, std::string::npos);
953  substr_i = oss.str().find ("Timer B");
954  TEST_INEQUALITY(substr_i, std::string::npos);
955 
956  // Timer C should NOT be reported.
957  substr_i = oss.str().find ("Timer C");
958  TEST_EQUALITY(substr_i, std::string::npos);
959  }
960 
961  // This sets up for the next unit test (if there is one).
963  }
964 
965  //
966  // Test option to disregard missing timers from processes in TimeMonitor::summarize().
967  //
968  TEUCHOS_UNIT_TEST( TimeMonitor, IgnoreMissingTimers )
969  {
971  const int myRank = comm->getRank ();
972 
973 #ifdef HAVE_MPI
974  {
975  int mpiHasBeenInitialized = 0;
976  MPI_Initialized (&mpiHasBeenInitialized);
977  if (! mpiHasBeenInitialized) {
979  }
980  }
981 #endif // HAVE_MPI
982 
983  // Store the output of TimeMonitor::summarize() here.
984  std::ostringstream oss;
985 
986  std::string timerName="Timer Z";
987  // Timer Z appears on all PIDs except 0.
988  {
989  switch (myRank) {
990  case 1 :
991  break;
992  case 0 :
993  {
994  RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
995  TimeMonitor monitor (*timer);
996  sleep(1);
997  }
998  break;
999  case 2 :
1000  {
1001  RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
1002  TimeMonitor monitor (*timer);
1003  sleep(1);
1004  }
1005  break;
1006  default :
1007  {
1008  RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
1009  TimeMonitor monitor (*timer);
1010  sleep(1);
1011  }
1012  }
1013  }
1014 
1016  // test two versions of summarize with default behavior
1018 
1019  //version 1, comm provided
1020  const bool alwaysWriteLocal = false;
1021  const bool writeGlobalStats = true;
1022  const bool writeZeroTimers = false;
1023  bool ignoreMissingTimers = false; // the default
1024  std::string filter = "";
1025  TimeMonitor::summarize (comm.ptr(), oss, alwaysWriteLocal, writeGlobalStats,
1026  writeZeroTimers, Union, filter, ignoreMissingTimers);
1027 
1028  // Echo summarize() output to the FancyOStream out (which is a
1029  // standard unit test argument). Output should only appear in
1030  // show-all-test-details mode.
1031  out << oss.str() << std::endl;
1032 
1033  if (comm->getSize() > 1) {
1034  // The min should be 0
1036  size_t substr_i = oss.str().find ("0 (0)");
1037  TEST_INEQUALITY(substr_i, std::string::npos);
1038  }
1039  }
1040 
1041  //version 2, no comm provided
1042  std::ostringstream oss2;
1043  TimeMonitor::summarize (oss2, alwaysWriteLocal, writeGlobalStats,
1044  writeZeroTimers, Union, filter, ignoreMissingTimers);
1045  out << oss2.str() << std::endl;
1046  if (comm->getSize() > 1) {
1047  // The min should be 0
1049  size_t substr_i = oss2.str().find ("0 (0)");
1050  TEST_INEQUALITY(substr_i, std::string::npos);
1051  }
1052  }
1053 
1055  // test two versions of summarize with *non* default behavior
1057  //version 1, comm provided
1058  ignoreMissingTimers = true; // NOT the default
1059  std::ostringstream oss3;
1060  TimeMonitor::summarize (comm.ptr(), oss3, alwaysWriteLocal, writeGlobalStats,
1061  writeZeroTimers, Union, filter, ignoreMissingTimers);
1062  out << oss3.str() << std::endl;
1063 
1064  // The min should be different from 0
1065  size_t substr_i = oss3.str().find ("0 (0)");
1066  TEST_EQUALITY(substr_i, std::string::npos);
1067 
1068  //version 2, no comm provided
1069  std::ostringstream oss4;
1070  TimeMonitor::summarize (oss4, alwaysWriteLocal, writeGlobalStats,
1071  writeZeroTimers, Union, filter, ignoreMissingTimers);
1072  out << oss4.str() << std::endl;
1073  // The min should be different from 0
1074  substr_i = oss4.str().find ("0 (0)");
1075  TEST_EQUALITY(substr_i, std::string::npos);
1076 
1077  // This sets up for the next unit test (if there is one).
1079  }
1080 
1081 } // 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.
ParameterList & set(std::string const &name, T const &value, std::string const &docString="", RCP< const ParameterEntryValidator > const &validator=null)
Set a parameter whose value has type T.
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.
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.
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...