Merge pull request #2490 from jsiirola/timer-tests-win10

Improve `common.timing` test robustness

Author: mrmundt

pyomo/common/tests/test_timing.py

@@ -167,21 +167,25 @@ def test_TicTocTimer_tictoc(self):
 
         time.sleep(SLEEP)
 
-        ref = time.perf_counter()
         with capture_output() as out:
+            ref = time.perf_counter()
             delta = timer.toc()
         self.assertAlmostEqual(ref - start_time, delta, delta=RES)
-        # entering / leaving the context manager can take non-trivial
-        # time on some platforms (up to 0.02 on Windows)
-        self.assertAlmostEqual(0.01, timer.toc(None), delta=RES)
         self.assertRegex(
             out.getvalue(),
             r'\[\+   [.0-9]+\] .* in test_TicTocTimer_tictoc'
         )
-        ref = time.perf_counter()
         with capture_output() as out:
+            # entering / leaving the context manager can take non-trivial
+            # time on some platforms (up to 0.03 on Windows / Python 3.10)
+            self.assertAlmostEqual(
+                time.perf_counter() - ref, timer.toc(None), delta=RES)
+        self.assertEqual(out.getvalue(), '')
+
+        with capture_output() as out:
+            ref = time.perf_counter()
             total = timer.toc(delta=False)
-        self.assertAlmostEqual(ref - abs_time, total, delta=RES)
+        self.assertAlmostEqual(ref - start_time, total, delta=RES)
         self.assertRegex(
             out.getvalue(),
             r'\[    [.0-9]+\] .* in test_TicTocTimer_tictoc'

pyomo/common/timing.py

@@ -228,7 +228,7 @@ class was constructed). Note: timing logged using logger.info
             level (int): an optional logging output level.
 
         """
-        self._lastTime = default_timer()
+        self._lastTime = self._loadTime = default_timer()
         if msg is _NotSpecified:
             msg = "Resetting the tic/toc delta timer"
         if msg is not None:
@@ -258,9 +258,9 @@ def toc(self, msg=_NotSpecified, *args, delta=True,
             *args (tuple): optional positional arguments used for
                 %-formatting the `msg`
             delta (bool): print out the elapsed wall clock time since
-                the last call to :meth:`tic` or :meth:`toc`
-                (``True`` (default)) or since the module was first
-                loaded (``False``).
+                the last call to :meth:`tic` (``False``) or since the
+                most recent call to either :meth:`tic` or :meth:`toc`
+                (``True`` (default)).
             ostream (FILE): an optional output stream (overrides the ostream
                 provided when the class was constructed).
             logger (Logger): an optional output stream using the python
@@ -298,6 +298,9 @@ class was constructed). Note: timing logged using `level`
                 data = (ans, msg)
         else:
             ans = now - self._loadTime
+            # Even though we are reporting the cumulative time, we will
+            # still reset the delta timer.
+            self._lastTime = now
             if msg is not None:
                 fmt = "[%8.2f] %s"
                 data = (ans, msg)