Teuchos Package Browser (Single Doxygen Collection) Version of the Day
TimeMonitor_UnitTests.cpp
Go to the documentation of this file.
00001 /*
00002 // @HEADER
00003 // ***********************************************************************
00004 //
00005 //                    Teuchos: Common Tools Package
00006 //                 Copyright (2004) Sandia Corporation
00007 //
00008 // Under terms of Contract DE-AC04-94AL85000, there is a non-exclusive
00009 // license for use of this work by or on behalf of the U.S. Government.
00010 //
00011 // Redistribution and use in source and binary forms, with or without
00012 // modification, are permitted provided that the following conditions are
00013 // met:
00014 //
00015 // 1. Redistributions of source code must retain the above copyright
00016 // notice, this list of conditions and the following disclaimer.
00017 //
00018 // 2. Redistributions in binary form must reproduce the above copyright
00019 // notice, this list of conditions and the following disclaimer in the
00020 // documentation and/or other materials provided with the distribution.
00021 //
00022 // 3. Neither the name of the Corporation nor the names of the
00023 // contributors may be used to endorse or promote products derived from
00024 // this software without specific prior written permission.
00025 //
00026 // THIS SOFTWARE IS PROVIDED BY SANDIA CORPORATION "AS IS" AND ANY
00027 // EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
00028 // IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
00029 // PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL SANDIA CORPORATION OR THE
00030 // CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL,
00031 // EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
00032 // PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
00033 // PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
00034 // LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
00035 // NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
00036 // SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
00037 //
00038 // Questions? Contact Michael A. Heroux (maherou@sandia.gov)
00039 //
00040 // ***********************************************************************
00041 // @HEADER
00042 */
00043 
00044 #include "Teuchos_TimeMonitor.hpp"
00045 #include "Teuchos_DefaultComm.hpp"
00046 #include "Teuchos_UnitTestHarness.hpp"
00047 
00048 // slowLoop does not reliably make a timer nonzero (RHEL6, gcc 4.4.7, OpenMPI 1.5.4).
00049 // Thus, I'm introducing headers to make sleep() available.
00050 #ifndef ICL
00051 #include <unistd.h>
00052 #else
00053 void sleep(int sec)
00054 {
00055   Sleep(sec);
00056 }
00057 #endif
00058 
00059 #ifdef _MSC_VER
00060 #pragma comment(lib, "Ws2_32.lib")
00061 # include <Winsock2.h>
00062 # include <process.h>
00063 void sleep(int sec)
00064 {
00065   Sleep(sec * 1000);
00066 }
00067 #endif
00068 
00069 namespace {
00070 
00071   void func_time_monitor1()
00072   {
00073     TEUCHOS_FUNC_TIME_MONITOR("FUNC_TIME_MONITOR1");
00074   }
00075 
00076 
00077   void func_time_monitor2()
00078   {
00079     TEUCHOS_FUNC_TIME_MONITOR("FUNC_TIME_MONITOR2");
00080     {
00081       TEUCHOS_FUNC_TIME_MONITOR_DIFF("FUNC_TIME_MONITOR2_inner", inner);
00082     }
00083   }
00084 
00085   // This function is commented out because no code in this file
00086   // actually uses it.  Commenting it out avoids compiler warnings
00087   // ("unused function").
00088 #if 0
00089   // Slowly compute the n-th Fibonacci number.  This gives timers
00090   // something to time.  Be careful not to make n too large, or you'll
00091   // run out of stack space.
00092   int
00093   fib (const int n)
00094   {
00095     if (n <= 0) {
00096       return 0;
00097     } else if (n == 1) {
00098       return 1;
00099     }
00100     else {
00101       // You should never compute the n-th Fibonacci number like this.
00102       // This is exponentially slow in n.  The point of using a slow
00103       // algorithm like this is to exercise timers.
00104       return fib (n-1) + fib (n-2);
00105     }
00106   }
00107 #endif // 0
00108 
00109   // Do a number of arithmetic operations proportional to n^3, in
00110   // order to have something to time.  Unlike the recursive function
00111   // fib() commented out above, this function shouldn't take up a lot
00112   // of stack space.
00113   double
00114   slowLoop (const size_t n)
00115   {
00116     const double inc = 1 / static_cast<double> (n);
00117     double x = 1.0;
00118 
00119     for (size_t i = 0; i < n; ++i) {
00120       for (size_t j = 0; j < n; ++j) {
00121         for (size_t k = 0; k < n; ++k) {
00122           x = x + inc;
00123         }
00124       }
00125     }
00126     return x;
00127   }
00128 
00129 } // namespace (anonymous)
00130 
00131 
00132 namespace Teuchos {
00133   //
00134   // Basic TimeMonitor test: create and exercise a timer on all (MPI)
00135   // processes, and make sure that TimeMonitor::summarize() reports it.
00136   //
00137   TEUCHOS_UNIT_TEST( TimeMonitor, FUNC_TIME_MONITOR  )
00138   {
00139     using Teuchos::ParameterList;
00140     using Teuchos::parameterList;
00141     using Teuchos::RCP;
00142 
00143     func_time_monitor1 (); // Function to time.
00144 
00145     { // Repeat test for default output format.
00146       std::ostringstream oss;
00147       TimeMonitor::summarize (oss);
00148 
00149       // Echo summarize() output to the FancyOStream out (which is a
00150       // standard unit test argument).  Output should only appear in
00151       // show-all-test-details mode.
00152       out << oss.str () << std::endl;
00153 
00154       // Make sure that the timer's name shows up in the output.
00155       const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
00156       TEST_INEQUALITY(substr_i, std::string::npos);
00157     }
00158 
00159     { // Repeat test for YAML output, compact style.
00160       std::ostringstream oss;
00161       RCP<ParameterList> reportParams =
00162         parameterList (* (TimeMonitor::getValidReportParameters ()));
00163       reportParams->set ("Report format", "YAML");
00164       reportParams->set ("YAML style", "compact");
00165       TimeMonitor::report (oss, reportParams);
00166 
00167       // Echo output to the FancyOStream out (which is a standard unit
00168       // test argument).  Output should only appear in "show all test
00169       // details" mode.
00170       out << oss.str () << std::endl;
00171 
00172       // Make sure that the timer's name shows up in the output.
00173       const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
00174       TEST_INEQUALITY(substr_i, std::string::npos);
00175     }
00176 
00177     { // Repeat test for YAML output, spacious style.
00178       std::ostringstream oss;
00179       RCP<ParameterList> reportParams =
00180         parameterList (* (TimeMonitor::getValidReportParameters ()));
00181       reportParams->set ("Report format", "YAML");
00182       reportParams->set ("YAML style", "spacious");
00183       TimeMonitor::report (oss, reportParams);
00184 
00185       // Echo output to the FancyOStream out (which is a standard unit
00186       // test argument).  Output should only appear in "show all test
00187       // details" mode.
00188       out << oss.str () << std::endl;
00189 
00190       // Make sure that the timer's name shows up in the output.
00191       const size_t substr_i = oss.str ().find ("FUNC_TIME_MONITOR1");
00192       TEST_INEQUALITY(substr_i, std::string::npos);
00193     }
00194 
00195     // This sets up for the next unit test.
00196     TimeMonitor::clearCounters ();
00197   }
00198 
00199   //
00200   // Test for TimeMonitor's enableTimer and disableTimer methods.
00201   //
00202   TEUCHOS_UNIT_TEST( TimeMonitor, enableTimer )
00203   {
00204     using Teuchos::Array;
00205     using Teuchos::OSTab;
00206     using Teuchos::ParameterList;
00207     using Teuchos::parameterList;
00208     using Teuchos::RCP;
00209     using Teuchos::rcpFromRef;
00210     using Teuchos::Time;
00211     using Teuchos::TimeMonitor;
00212     using std::endl;
00213     typedef Teuchos::Array<RCP<Time> >::size_type size_type;
00214 
00215     out << "Testing TimeMonitor's disableTimer() and enableTimer() methods"
00216         << endl;
00217     OSTab (rcpFromRef (out));
00218 
00219     out << "Creating timers" << endl;
00220     const int numTrials = 5;
00221     const int numTimers = 3;
00222     Array<RCP<Time> > timers (numTimers);
00223     for (size_type i = 0; i < numTimers; ++i) {
00224       std::ostringstream os; // construct timer name
00225       os << "Timer " << i;
00226       timers[i] = TimeMonitor::getNewTimer (os.str ());
00227     }
00228 
00229     out << "Running all timers without disabling any" << endl;
00230     // The actual number of operations in slowloop is proportional to
00231     // the cube of the loop length.  Adjust loopLength as necessary to
00232     // ensure the timer reports a nonzero elapsed time for each of the
00233     // invocations.
00234     const size_t loopLength = 25;
00235     for (int k = 0; k < numTrials; ++k) {
00236       for (size_type i = 0; i < numTimers; ++i) {
00237         TimeMonitor timeMon (* timers[i]);
00238         slowLoop (loopLength);
00239       }
00240     }
00241     for (size_type i = 0; i < numTimers; ++i) {
00242       TEST_EQUALITY( timers[i]->numCalls(), numTrials );
00243     }
00244 
00245     out << "Disabling one timer and trying again" << endl;
00246     // Disable timers[0] only, and repeat the above loops.
00247     TEST_NOTHROW( TimeMonitor::disableTimer ("Timer 0") );
00248     for (int k = 0; k < numTrials; ++k) {
00249       for (size_type i = 0; i < numTimers; ++i) {
00250         TimeMonitor timeMon (* timers[i]);
00251         slowLoop (loopLength);
00252       }
00253     }
00254     TEST_EQUALITY( timers[0]->numCalls(), numTrials );
00255     for (size_type i = 1; i < numTimers; ++i) {
00256       TEST_EQUALITY( timers[i]->numCalls(), 2*numTrials );
00257     }
00258 
00259     out << "Reenabling the timer and trying again" << endl;
00260     // Enable timers[0] and repeat the above loops.
00261     TEST_NOTHROW( TimeMonitor::enableTimer ("Timer 0") );
00262     for (int k = 0; k < numTrials; ++k) {
00263       for (size_type i = 0; i < numTimers; ++i) {
00264         TimeMonitor timeMon (* timers[i]);
00265         slowLoop (loopLength);
00266       }
00267     }
00268     TEST_EQUALITY( timers[0]->numCalls(), 2*numTrials );
00269     for (size_type i = 1; i < numTimers; ++i) {
00270       TEST_EQUALITY( timers[i]->numCalls(), 3*numTrials );
00271     }
00272 
00273     out << "Test that summarize() reports enabled and disabled timers" << endl;
00274     // Make sure that summarize() reports all timers.  Disabling a
00275     // timer must _not_ exclude it from the list of timers printed by
00276     // summarize().  Disable a different timer this time just for fun.
00277     TEST_NOTHROW( TimeMonitor::disableTimer ("Timer 1") );
00278     {
00279       std::ostringstream oss;
00280       TimeMonitor::summarize (oss);
00281 
00282       // Echo summarize() output to the FancyOStream out (which is a
00283       // standard unit test argument).  Output should only appear in
00284       // show-all-test-details mode.
00285       out << oss.str () << std::endl;
00286 
00287       // Make sure that each timer's name shows up in the output.
00288       for (size_type i = 0; i < numTimers; ++i) {
00289         const std::string name = timers[i]->name ();
00290         const size_t substr_i = oss.str ().find (name);
00291         TEST_INEQUALITY(substr_i, std::string::npos);
00292       }
00293     }
00294 
00295     // This sets up for the next unit test.
00296     TimeMonitor::clearCounters ();
00297   }
00298 
00299 
00300   //
00301   // Test correct quoting of labels for TimeMonitor's YAML output.
00302   //
00303   TEUCHOS_UNIT_TEST( TimeMonitor, YamlLabelQuoting )
00304   {
00305     using Teuchos::Array;
00306     using Teuchos::ParameterList;
00307     using Teuchos::parameterList;
00308     using Teuchos::RCP;
00309     using Teuchos::Time;
00310     typedef Array<std::string>::size_type size_type;
00311 
00312     Array<std::string> inputLabels, outputLabels;
00313 
00314     // Make sure to exercise things that don't need quoting, like
00315     // spaces and certain punctuation, as well as things that do need
00316     // quoting, like colons, inner double quotes, and backslashes.
00317     inputLabels.push_back ("NoQuotingNeeded");
00318     inputLabels.push_back ("No quoting needed");
00319     inputLabels.push_back ("\"AlreadyQuotedNoQuotingNeeded\"");
00320     inputLabels.push_back ("\"Already quoted, no quoting needed\"");
00321     inputLabels.push_back ("\"Already quoted: quoting needed\"");
00322     inputLabels.push_back ("NotQuoted:QuotingNeeded");
00323     inputLabels.push_back ("Not quoted: quoting needed");
00324     // Test both individual double quotes, and pairs of double quotes.
00325     inputLabels.push_back ("Not quoted \" quoting needed");
00326     inputLabels.push_back ("Not quoted \" \" quoting needed");
00327     inputLabels.push_back ("\"Already quoted \" quoting needed\"");
00328     inputLabels.push_back ("\"Already quoted \" \" quoting needed\"");
00329     // Remember that in C strings, a double backslash turns into a
00330     // single backslash.  Our YAML output routine should turn each
00331     // single backslash back into a double backslash.
00332     inputLabels.push_back ("Not quoted \\ quoting needed");
00333     inputLabels.push_back ("Not quoted \\\\ quoting needed");
00334     inputLabels.push_back ("Not quoted \\ \\ quoting needed");
00335     inputLabels.push_back ("\"Already quoted \\ quoting needed\"");
00336     inputLabels.push_back ("\"Already quoted \\\\ quoting needed\"");
00337     inputLabels.push_back ("\"Already quoted \\ \\ quoting needed\"");
00338 
00339     outputLabels.push_back ("NoQuotingNeeded");
00340     outputLabels.push_back ("No quoting needed");
00341     outputLabels.push_back ("\"AlreadyQuotedNoQuotingNeeded\"");
00342     outputLabels.push_back ("\"Already quoted, no quoting needed\"");
00343     outputLabels.push_back ("\"Already quoted: quoting needed\"");
00344     outputLabels.push_back ("\"NotQuoted:QuotingNeeded\"");
00345     outputLabels.push_back ("\"Not quoted: quoting needed\"");
00346     outputLabels.push_back ("\"Not quoted \\\" quoting needed\"");
00347     outputLabels.push_back ("\"Not quoted \\\" \\\" quoting needed\"");
00348     outputLabels.push_back ("\"Already quoted \\\" quoting needed\"");
00349     outputLabels.push_back ("\"Already quoted \\\" \\\" quoting needed\"");
00350     outputLabels.push_back ("\"Not quoted \\\\ quoting needed\"");
00351     outputLabels.push_back ("\"Not quoted \\\\\\\\ quoting needed\"");
00352     outputLabels.push_back ("\"Not quoted \\\\ \\\\ quoting needed\"");
00353     outputLabels.push_back ("\"Already quoted \\\\ quoting needed\"");
00354     outputLabels.push_back ("\"Already quoted \\\\\\\\ quoting needed\"");
00355     outputLabels.push_back ("\"Already quoted \\\\ \\\\ quoting needed\"");
00356 
00357     // Sanity check.
00358     TEUCHOS_TEST_FOR_EXCEPTION(
00359       inputLabels.size () != outputLabels.size (),
00360       std::logic_error,
00361       "The number of input labels is different than the number of output labels."
00362       "  Please ask a Teuchos developer to make sure that every test input "
00363       "label has a corresponding output label.");
00364 
00365     Array<RCP<Time> > timers;
00366     for (size_type i = 0; i < inputLabels.size (); ++i) {
00367       timers.push_back (TimeMonitor::getNewCounter (inputLabels[i]));
00368     }
00369 
00370     // The actual number of operations in the loop is proportional to
00371     // the cube of the loop length.  Adjust the quantities below as
00372     // necessary to ensure the timer reports a nonzero elapsed time
00373     // for each of the invocations.
00374     const size_t loopLength = 25;
00375     for (int k = 0; k < 3; ++k) {
00376       for (size_type i = 0; i < timers.size (); ++i) {
00377         TimeMonitor timeMon (* timers[i]);
00378         slowLoop (loopLength);
00379       }
00380     }
00381 
00382     { // YAML output, compact style.
00383       std::ostringstream oss;
00384       RCP<ParameterList> reportParams =
00385         parameterList (* (TimeMonitor::getValidReportParameters ()));
00386       reportParams->set ("Report format", "YAML");
00387       reportParams->set ("YAML style", "compact");
00388       TimeMonitor::report (oss, reportParams);
00389 
00390       // Echo output to the FancyOStream out (which is a standard unit
00391       // test argument).  Output should only appear in "show all test
00392       // details" mode.
00393       out << oss.str () << std::endl;
00394 
00395       // Make sure that all timer labels appear correctly in the output.
00396       for (size_type i = 0; i < inputLabels.size(); ++i) {
00397         const size_t pos = oss.str ().find (outputLabels[i]);
00398         TEST_INEQUALITY(pos, std::string::npos);
00399       }
00400     }
00401 
00402     { // YAML output, spacious style.
00403       std::ostringstream oss;
00404       RCP<ParameterList> reportParams =
00405         parameterList (* (TimeMonitor::getValidReportParameters ()));
00406       reportParams->set ("Report format", "YAML");
00407       reportParams->set ("YAML style", "spacious");
00408       TimeMonitor::report (oss, reportParams);
00409 
00410       // Echo output to the FancyOStream out (which is a standard unit
00411       // test argument).  Output should only appear in "show all test
00412       // details" mode.
00413       out << oss.str () << std::endl;
00414 
00415       // Make sure that all timer labels appear correctly in the output.
00416       for (size_type i = 0; i < inputLabels.size(); ++i) {
00417         const size_t pos = oss.str ().find (outputLabels[i]);
00418         TEST_INEQUALITY(pos, std::string::npos);
00419       }
00420     }
00421 
00422     // This sets up for the next unit test.
00423     TimeMonitor::clearCounters ();
00424   }
00425 
00426 
00427   //
00428   // Test filtering of timer labels.
00429   //
00430   TEUCHOS_UNIT_TEST( TimeMonitor, TimerLabelFiltering )
00431   {
00432     using Teuchos::Array;
00433     using Teuchos::ParameterList;
00434     using Teuchos::parameterList;
00435     using Teuchos::RCP;
00436     using Teuchos::Time;
00437     typedef Array<std::string>::size_type size_type;
00438 
00439     // Filters to use in the test.
00440     Array<std::string> filters;
00441     filters.push_back ("Foo:");
00442     filters.push_back ("Bar:");
00443     filters.push_back ("Baz:");
00444 
00445     // All the timer labels.
00446     Array<std::string> labels;
00447     labels.push_back ("Foo: timer 1");
00448     labels.push_back ("Foo: timer 2");
00449     labels.push_back ("Foo: timer 3");
00450     labels.push_back ("Bar: timer 1");
00451     labels.push_back ("Bar: timer 2");
00452     labels.push_back ("Baz: timer 1");
00453     labels.push_back ("Xyzzy");
00454     labels.push_back ("This is not a pipe");
00455     labels.push_back ("You should not see this");
00456 
00457     Array<Array<std::string> > outLabels (3);
00458     // Label(s) that should be printed for filters[0]
00459     outLabels[0].push_back ("Foo: timer 1");
00460     outLabels[0].push_back ("Foo: timer 2");
00461     outLabels[0].push_back ("Foo: timer 3");
00462     // Label(s) that should be printed for filters[1]
00463     outLabels[1].push_back ("Bar: timer 1");
00464     outLabels[1].push_back ("Bar: timer 2");
00465     // Label(s) that should be printed for filters[2]
00466     outLabels[2].push_back ("Baz: timer 1");
00467 
00468     // Labels that should not be printed for any of the filters below.
00469     Array<std::string> otherLabels;
00470     otherLabels.push_back ("Xyzzy");
00471     otherLabels.push_back ("This is not a pipe");
00472     otherLabels.push_back ("You should not see this");
00473 
00474     Array<RCP<Time> > timers;
00475     for (size_type i = 0; i < labels.size (); ++i) {
00476       timers.push_back (TimeMonitor::getNewCounter (labels[i]));
00477     }
00478 
00479     // The actual number of operations in the loop is proportional to
00480     // the cube of the loop length.  Adjust the quantities below as
00481     // necessary to ensure the timer reports a nonzero elapsed time
00482     // for each of the invocations.
00483     const size_t loopLength = 25;
00484     for (int k = 0; k < 3; ++k) {
00485       for (size_type i = 0; i < timers.size (); ++i) {
00486         TimeMonitor timeMon (* timers[i]);
00487         slowLoop (loopLength);
00488       }
00489     }
00490 
00491     try {
00492       // FIXME (mfh 21 Aug 2012) We don't yet have a test ensuring that
00493       // the filter only selects at the beginning of the timer label.
00494 
00495       // Test for each filter.
00496       for (size_type i = 0; i < filters.size (); ++i) {
00497         { // Default (tabular) output format.
00498           std::ostringstream oss;
00499           RCP<ParameterList> reportParams =
00500             parameterList (* (TimeMonitor::getValidReportParameters ()));
00501           TimeMonitor::report (oss, filters[i], reportParams);
00502 
00503           // Echo output to the FancyOStream out (which is a standard unit
00504           // test argument).  Output should only appear in "show all test
00505           // details" mode.
00506           out << oss.str () << std::endl;
00507 
00508           // Check whether the labels that were supposed to be printed
00509           // were actually printed.
00510           for (size_type j = 0; j < outLabels[i].size(); ++j) {
00511             const size_t pos = oss.str ().find (outLabels[i][j]);
00512             TEST_INEQUALITY(pos, std::string::npos);
00513           }
00514 
00515           // Check whether the labels that were _not_ supposed to be
00516           // printed were actually printed.
00517           //
00518           // First, check the labels that should only be printed with
00519           // the other filters.
00520           for (size_type ii = 0; ii < outLabels.size(); ++ii) {
00521             if (ii != i) {
00522               for (size_type j = 0; j < outLabels[ii].size(); ++j) {
00523                 const size_t pos = oss.str ().find (outLabels[ii][j]);
00524                 TEST_EQUALITY(pos, std::string::npos);
00525               }
00526             }
00527           }
00528           // Next, check the labels that should not be printed for any
00529           // filters.
00530           for (size_type j = 0; j < otherLabels.size(); ++j) {
00531             const size_t pos = oss.str ().find (otherLabels[j]);
00532             TEST_EQUALITY(pos, std::string::npos);
00533           }
00534         }
00535 
00536         { // YAML output, compact style.
00537           std::ostringstream oss;
00538           RCP<ParameterList> reportParams =
00539             parameterList (* (TimeMonitor::getValidReportParameters ()));
00540           reportParams->set ("Report format", "YAML");
00541           reportParams->set ("YAML style", "compact");
00542           TimeMonitor::report (oss, filters[i], reportParams);
00543 
00544           // Echo output to the FancyOStream out (which is a standard unit
00545           // test argument).  Output should only appear in "show all test
00546           // details" mode.
00547           out << oss.str () << std::endl;
00548 
00549           // Check whether the labels that were supposed to be printed
00550           // were actually printed.
00551           for (size_type j = 0; j < outLabels[i].size(); ++j) {
00552             const size_t pos = oss.str ().find (outLabels[i][j]);
00553             TEST_INEQUALITY(pos, std::string::npos);
00554           }
00555 
00556           // Check whether the labels that were _not_ supposed to be
00557           // printed were actually printed.
00558           //
00559           // First, check the labels that should only be printed with
00560           // the other filters.
00561           for (size_type ii = 0; ii < outLabels.size(); ++ii) {
00562             if (ii != i) {
00563               for (size_type j = 0; j < outLabels[ii].size(); ++j) {
00564                 const size_t pos = oss.str ().find (outLabels[ii][j]);
00565                 TEST_EQUALITY(pos, std::string::npos);
00566               }
00567             }
00568           }
00569           // Next, check the labels that should not be printed for any
00570           // filters.
00571           for (size_type j = 0; j < otherLabels.size(); ++j) {
00572             const size_t pos = oss.str ().find (otherLabels[j]);
00573             TEST_EQUALITY(pos, std::string::npos);
00574           }
00575         }
00576 
00577         { // YAML output, spacious style.
00578           std::ostringstream oss;
00579           RCP<ParameterList> reportParams =
00580             parameterList (* (TimeMonitor::getValidReportParameters ()));
00581           reportParams->set ("Report format", "YAML");
00582           reportParams->set ("YAML style", "spacious");
00583           TimeMonitor::report (oss, filters[i], reportParams);
00584 
00585           // Echo output to the FancyOStream out (which is a standard unit
00586           // test argument).  Output should only appear in "show all test
00587           // details" mode.
00588           out << oss.str () << std::endl;
00589 
00590           // Check whether the labels that were supposed to be printed
00591           // were actually printed.
00592           for (size_type j = 0; j < outLabels[i].size(); ++j) {
00593             const size_t pos = oss.str ().find (outLabels[i][j]);
00594             TEST_INEQUALITY(pos, std::string::npos);
00595           }
00596 
00597           // Check whether the labels that were _not_ supposed to be
00598           // printed were actually printed.
00599           //
00600           // First, check the labels that should only be printed with
00601           // the other filters.
00602           for (size_type ii = 0; ii < outLabels.size(); ++ii) {
00603             if (ii != i) {
00604               for (size_type j = 0; j < outLabels[ii].size(); ++j) {
00605                 const size_t pos = oss.str ().find (outLabels[ii][j]);
00606                 TEST_EQUALITY(pos, std::string::npos);
00607               }
00608             }
00609           }
00610           // Next, check the labels that should not be printed for any
00611           // filters.
00612           for (size_type j = 0; j < otherLabels.size(); ++j) {
00613             const size_t pos = oss.str ().find (otherLabels[j]);
00614             TEST_EQUALITY(pos, std::string::npos);
00615           }
00616         }
00617       }
00618     }
00619     catch (...) {
00620       // Make sure to clear the counters, so that they don't pollute
00621       // the remaining tests.  (The Teuchos unit test framework may
00622       // catch any exceptions that the above code throws, but allow
00623       // the remaining tests to continue.)
00624       TimeMonitor::clearCounters ();
00625       throw;
00626     }
00627 
00628     // This sets up for the next unit test.
00629     TimeMonitor::clearCounters ();
00630   }
00631 
00632 
00633 
00634   //
00635   // TimeMonitor nested timers test: create two timers on all (MPI)
00636   // processes, use the second inside the scope of the first, and make
00637   // sure that TimeMonitor::summarize() reports both timers.
00638   //
00639   TEUCHOS_UNIT_TEST( TimeMonitor, FUNC_TIME_MONITOR_tested  )
00640   {
00641     using Teuchos::ParameterList;
00642     using Teuchos::parameterList;
00643     using Teuchos::RCP;
00644 
00645     func_time_monitor2 ();
00646 
00647     {
00648       std::ostringstream oss;
00649       TimeMonitor::summarize (oss);
00650 
00651       // Echo summarize() output to the FancyOStream out (which is a
00652       // standard unit test argument).  Output should only appear in
00653       // show-all-test-details mode.
00654       out << oss.str() << std::endl;
00655 
00656       const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
00657       TEST_INEQUALITY(substr_i, std::string::npos);
00658       const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
00659       TEST_INEQUALITY(substr_inner_i, std::string::npos);
00660     }
00661 
00662     { // Repeat test for YAML output, compact style.
00663       std::ostringstream oss;
00664       RCP<ParameterList> reportParams =
00665         parameterList (* (TimeMonitor::getValidReportParameters ()));
00666       reportParams->set ("Report format", "YAML");
00667       reportParams->set ("YAML style", "compact");
00668       TimeMonitor::report (oss, reportParams);
00669 
00670       // Echo output to the FancyOStream out (which is a standard unit
00671       // test argument).  Output should only appear in "show all test
00672       // details" mode.
00673       out << oss.str () << std::endl;
00674 
00675       const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
00676       TEST_INEQUALITY(substr_i, std::string::npos);
00677       const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
00678       TEST_INEQUALITY(substr_inner_i, std::string::npos);
00679     }
00680 
00681     { // Repeat test for YAML output, spacious style.
00682       std::ostringstream oss;
00683       RCP<ParameterList> reportParams =
00684         parameterList (* (TimeMonitor::getValidReportParameters ()));
00685       reportParams->set ("Report format", "YAML");
00686       reportParams->set ("YAML style", "spacious");
00687       TimeMonitor::report (oss, reportParams);
00688 
00689       // Echo output to the FancyOStream out (which is a standard unit
00690       // test argument).  Output should only appear in "show all test
00691       // details" mode.
00692       out << oss.str () << std::endl;
00693 
00694       const size_t substr_i = oss.str().find ("FUNC_TIME_MONITOR2");
00695       TEST_INEQUALITY(substr_i, std::string::npos);
00696       const size_t substr_inner_i = oss.str().find ("FUNC_TIME_MONITOR2_inner");
00697       TEST_INEQUALITY(substr_inner_i, std::string::npos);
00698     }
00699 
00700     // This sets up for the next unit test.
00701     TimeMonitor::clearCounters ();
00702   }
00703 
00704   //
00705   // Test whether TimeMonitor::summarize() does the right thing when
00706   // different MPI processes create different sets of timers.  This
00707   // test is only meaningful if running with more than one MPI
00708   // process, but it should also pass if running in a non-MPI build or
00709   // with only one MPI process.
00710   //
00711   TEUCHOS_UNIT_TEST( TimeMonitor, SUMMARIZE_diffTimerSets )
00712   {
00713     RCP<const Comm<int> > comm = Teuchos::DefaultComm<int>::getComm ();
00714     const int numProcs = comm->getSize ();
00715     const int myRank = comm->getRank ();
00716 
00717     // If MPI has not been initialized, turn the MPI communicator into
00718     // a "serial" communicator.  This may not be necessary when using
00719     // the Teuchos Unit Test Framework.
00720 #ifdef HAVE_MPI
00721     {
00722       int mpiHasBeenInitialized = 0;
00723       MPI_Initialized (&mpiHasBeenInitialized);
00724       if (! mpiHasBeenInitialized) {
00725         comm = Teuchos::DefaultComm<int>::getDefaultSerialComm (null);
00726       }
00727     }
00728 #endif // HAVE_MPI
00729 
00730     // Store the output of TimeMonitor::summarize() here.
00731     std::ostringstream oss;
00732 
00733     // Timer A gets created on all MPI processes.
00734     // Timer B only gets created on Proc 0.
00735     RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
00736     RCP<Time> timerB;
00737     if (myRank == 0) {
00738       timerB = TimeMonitor::getNewCounter ("Timer B");
00739     }
00740     else {
00741       timerB = null; // True anyway, but I want to make this explicit.
00742     }
00743 
00744     // The actual number of operations in the loop is proportional to
00745     // the cube of the loop length.  Adjust the quantities below as
00746     // necessary to ensure the timer reports a nonzero elapsed time
00747     // for each of the invocations.
00748     const size_t timerA_loopLength = 150;
00749     const size_t timerB_loopLength = 200;
00750 
00751     // Timer A gets a call count of 3.
00752     for (size_t k = 0; k < 3; ++k) {
00753       TimeMonitor monitorA (*timerA);
00754       slowLoop (timerA_loopLength);
00755     }
00756     if (myRank == 0) { // Timer B gets a call count of 1 on Proc 0.
00757       TimeMonitor monitorB (*timerB);
00758       slowLoop (timerB_loopLength);
00759     }
00760 
00761     const bool alwaysWriteLocal = false; // the default
00762     const bool writeGlobalStats = true;  // the default
00763     const bool writeZeroTimers = true;  // the default
00764     TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
00765                             writeZeroTimers, Intersection);
00766 
00767     // Echo summarize() output to the FancyOStream out (which is a
00768     // standard unit test argument).  Output should only appear in
00769     // show-all-test-details mode.
00770     out << std::endl << "Testing intersection of timers:" << std::endl
00771         << oss.str() << std::endl;
00772 
00773     // Since setOp == Intersection, only Timer A should be reported,
00774     // unless there is only one (MPI) process.
00775     size_t substr_i = oss.str().find ("Timer A");
00776     TEST_INEQUALITY(substr_i, std::string::npos);
00777     if (numProcs > 1) {
00778       substr_i = oss.str().find ("Timer B");
00779       TEST_EQUALITY(substr_i, std::string::npos);
00780     }
00781 
00782     // Now call summarize(), but ask for a union of timers.
00783     std::ostringstream ossUnion;
00784     TimeMonitor::summarize (ossUnion, alwaysWriteLocal, writeGlobalStats,
00785                             writeZeroTimers, Union);
00786 
00787     // Echo summarize() output to the FancyOStream out (which is a
00788     // standard unit test argument).  Output should only appear in
00789     // show-all-test-details mode.
00790     out << std::endl << "Testing union of timers:" << std::endl
00791         << ossUnion.str() << std::endl;
00792 
00793     // Since setOp == Union, both Timer A and Timer B should be
00794     // reported.
00795     substr_i = ossUnion.str().find ("Timer A");
00796     TEST_INEQUALITY(substr_i, std::string::npos);
00797     substr_i = ossUnion.str().find ("Timer B");
00798     TEST_INEQUALITY(substr_i, std::string::npos);
00799 
00800     // This sets up for the next unit test.
00801     TimeMonitor::clearCounters ();
00802   }
00803 
00804   //
00805   // Test whether the option to filter out zero timers works, for the
00806   // case that all (MPI) processes have the same call counts.
00807   //
00808   TEUCHOS_UNIT_TEST( TimeMonitor, FILTER_ZERO_TIMERS_sameParallelCallCounts )
00809   {
00810     // Store the output of TimeMonitor::summarize() here.
00811     std::ostringstream oss;
00812 
00813     RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
00814     RCP<Time> timerB = TimeMonitor::getNewCounter ("Timer B");
00815     RCP<Time> timerC = TimeMonitor::getNewCounter ("Timer C");
00816 
00817     // Timers A and B get nonzero elapsed times and call counts on all
00818     // (MPI) processes.  Timer C never gets started, so it should have
00819     // a zero elapsed time and zero call count on all processes.
00820 
00821     // The actual number of operations in the loop is proportional to
00822     // the cube of the loop length.  Adjust the quantities below as
00823     // necessary to ensure the timer reports a nonzero elapsed time
00824     // for each of the invocations.
00825     const size_t timerA_loopLength = 200;
00826     const size_t timerB_loopLength = 250;
00827 
00828     // Timer A gets a call count of 3.
00829     for (size_t k = 0; k < 3; ++k) {
00830       TimeMonitor monitorA (*timerA);
00831       slowLoop (size_t (timerA_loopLength));
00832     }
00833     // Timer B gets a call count of 1.
00834     {
00835       TimeMonitor monitorB (*timerB);
00836       slowLoop (size_t (timerB_loopLength));
00837     }
00838 
00839     const bool alwaysWriteLocal = false; // the default
00840     const bool writeGlobalStats = true;  // the default
00841     const bool writeZeroTimers = false;  // NOT the default
00842     TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
00843                             writeZeroTimers);
00844 
00845     // Echo summarize() output to the FancyOStream out (which is a
00846     // standard unit test argument).  Output should only appear in
00847     // show-all-test-details mode.
00848     out << oss.str() << std::endl;
00849 
00850     // Timers A and B should be reported.
00851     size_t substr_i = oss.str().find ("Timer A");
00852     TEST_INEQUALITY(substr_i, std::string::npos);
00853     substr_i = oss.str().find ("Timer B");
00854     TEST_INEQUALITY(substr_i, std::string::npos);
00855 
00856     // Timer C should NOT be reported.
00857     substr_i = oss.str().find ("Timer C");
00858     TEST_EQUALITY(substr_i, std::string::npos);
00859 
00860     // This sets up for the next unit test.
00861     TimeMonitor::clearCounters ();
00862   }
00863 
00864 
00865   //
00866   // Test whether the option to filter out zero timers works, for the
00867   // case that different (MPI) processes have different call counts.
00868   //
00869   TEUCHOS_UNIT_TEST( TimeMonitor, FILTER_ZERO_TIMERS_differentParallelCallCounts )
00870   {
00871     RCP<const Comm<int> > comm = Teuchos::DefaultComm<int>::getComm ();
00872     const int myRank = comm->getRank ();
00873 
00874     // If MPI has not been initialized, turn the MPI communicator into
00875     // a "serial" communicator.  This may not be necessary when using
00876     // the Teuchos Unit Test Framework.
00877 #ifdef HAVE_MPI
00878     {
00879       int mpiHasBeenInitialized = 0;
00880       MPI_Initialized (&mpiHasBeenInitialized);
00881       if (! mpiHasBeenInitialized) {
00882         comm = Teuchos::DefaultComm<int>::getDefaultSerialComm (null);
00883       }
00884     }
00885 #endif // HAVE_MPI
00886 
00887     // Store the output of TimeMonitor::summarize() here.
00888     std::ostringstream oss;
00889 
00890     RCP<Time> timerA = TimeMonitor::getNewCounter ("Timer A");
00891     RCP<Time> timerB = TimeMonitor::getNewCounter ("Timer B");
00892     RCP<Time> timerC = TimeMonitor::getNewCounter ("Timer C");
00893 
00894     // Timer A gets a nonzero elapsed time and call count on Proc 0,
00895     // but a zero elapsed time and call count elsewhere.
00896     //
00897     // Timer B gets the same nonzero elapsed time and call count on
00898     // all MPI procs.
00899     //
00900     // Timer C gets a zero elapsed time and call count on all procs.
00901     //
00902     // The actual number of operations in the loop is proportional to
00903     // the cube of the loop length.  Adjust the quantities below as
00904     // necessary to ensure the timer reports a nonzero elapsed time
00905     // for each of the invocations.
00906     const size_t timerA_loopLength = 200;
00907     const size_t timerB_loopLength = 500;
00908 
00909     if (myRank == 0) {
00910       // Timer A gets a call count of 3 on Proc 0.
00911       for (int k = 0; k < 3; ++k) {
00912         TimeMonitor monitorA (*timerA);
00913         slowLoop (size_t (timerA_loopLength));
00914       }
00915     }
00916 
00917     // Timer B gets a call count of 1 on all procs.
00918     {
00919       TimeMonitor monitorB (*timerB);
00920       slowLoop (size_t (timerB_loopLength));
00921     }
00922 
00923     const bool alwaysWriteLocal = false; // the default
00924     const bool writeGlobalStats = true;  // the default
00925     const bool writeZeroTimers = false;  // NOT the default
00926     TimeMonitor::summarize (oss, alwaysWriteLocal, writeGlobalStats,
00927                             writeZeroTimers, Union);
00928 
00929     // Echo summarize() output to the FancyOStream out (which is a
00930     // standard unit test argument).  Output should only appear in
00931     // show-all-test-details mode.
00932     out << oss.str() << std::endl;
00933 
00934     // Timers A and B should both be reported.
00935     size_t substr_i = oss.str().find ("Timer A");
00936     TEST_INEQUALITY(substr_i, std::string::npos);
00937     substr_i = oss.str().find ("Timer B");
00938     TEST_INEQUALITY(substr_i, std::string::npos);
00939 
00940     // Timer C should NOT be reported.
00941     substr_i = oss.str().find ("Timer C");
00942     TEST_EQUALITY(substr_i, std::string::npos);
00943 
00944     // This sets up for the next unit test (if there is one).
00945     TimeMonitor::clearCounters ();
00946   }
00947 
00948   //
00949   // Test option to disregard missing timers from processes in TimeMonitor::summarize().
00950   //
00951   TEUCHOS_UNIT_TEST( TimeMonitor, IgnoreMissingTimers )
00952   {
00953     RCP<const Comm<int> > comm = Teuchos::DefaultComm<int>::getComm ();
00954     const int myRank = comm->getRank ();
00955 
00956 #ifdef HAVE_MPI
00957     {
00958       int mpiHasBeenInitialized = 0;
00959       MPI_Initialized (&mpiHasBeenInitialized);
00960       if (! mpiHasBeenInitialized) {
00961         comm = Teuchos::DefaultComm<int>::getDefaultSerialComm (null);
00962       }
00963     }
00964 #endif // HAVE_MPI
00965 
00966     // Store the output of TimeMonitor::summarize() here.
00967     std::ostringstream oss;
00968 
00969     std::string timerName="Timer Z";
00970     // Timer Z appears on all PIDs except 0.
00971     {
00972       switch (myRank) {
00973         case 1 :
00974           break;
00975         case 0 :
00976           {
00977           RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
00978           TimeMonitor monitor (*timer);
00979           sleep(1);
00980           }
00981           break;
00982         case 2 :
00983           {
00984           RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
00985           TimeMonitor monitor (*timer);
00986           sleep(1);
00987           }
00988           break;
00989         default :
00990           {
00991           RCP<Time> timer = TimeMonitor::getNewCounter (timerName);
00992           TimeMonitor monitor (*timer);
00993           sleep(1);
00994           }
00995     }
00996     }
00997 
00999     // test two versions of summarize with default behavior
01001 
01002     //version 1, comm provided
01003     const bool alwaysWriteLocal = false;
01004     const bool writeGlobalStats = true;
01005     const bool writeZeroTimers = false;
01006     bool ignoreMissingTimers = false;        // the default
01007     std::string filter = "";
01008     TimeMonitor::summarize (comm.ptr(), oss, alwaysWriteLocal, writeGlobalStats,
01009                             writeZeroTimers, Union, filter, ignoreMissingTimers);
01010 
01011     // Echo summarize() output to the FancyOStream out (which is a
01012     // standard unit test argument).  Output should only appear in
01013     // show-all-test-details mode.
01014     out << oss.str() << std::endl;
01015 
01016     if (comm->getSize() > 1) {
01017       // The min should be 0
01018       size_t substr_i = oss.str().find ("0 (0)");
01019       TEST_INEQUALITY(substr_i, std::string::npos);
01020     }
01021 
01022     //version 2, no comm provided
01023     std::ostringstream oss2;
01024     TimeMonitor::summarize (oss2, alwaysWriteLocal, writeGlobalStats,
01025                             writeZeroTimers, Union, filter, ignoreMissingTimers);
01026     out << oss2.str() << std::endl;
01027     if (comm->getSize() > 1) {
01028       // The min should be 0
01029       size_t substr_i = oss2.str().find ("0 (0)");
01030       TEST_INEQUALITY(substr_i, std::string::npos);
01031     }
01032 
01034     // test two versions of summarize with *non* default behavior
01036     //version 1, comm provided
01037     ignoreMissingTimers = true;              // NOT the default
01038     std::ostringstream oss3;
01039     TimeMonitor::summarize (comm.ptr(), oss3, alwaysWriteLocal, writeGlobalStats,
01040                             writeZeroTimers, Union, filter, ignoreMissingTimers);
01041     out << oss3.str() << std::endl;
01042 
01043     // The min should be different from 0
01044     size_t substr_i = oss3.str().find ("0 (0)");
01045     TEST_EQUALITY(substr_i, std::string::npos);
01046 
01047     //version 2, no comm provided
01048     std::ostringstream oss4;
01049     TimeMonitor::summarize (oss4, alwaysWriteLocal, writeGlobalStats,
01050                             writeZeroTimers, Union, filter, ignoreMissingTimers);
01051     out << oss4.str() << std::endl;
01052     // The min should be different from 0
01053     substr_i = oss4.str().find ("0 (0)");
01054     TEST_EQUALITY(substr_i, std::string::npos);
01055 
01056     // This sets up for the next unit test (if there is one).
01057     TimeMonitor::clearCounters ();
01058   }
01059 
01060 } // namespace Teuchos
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Defines