Timing improvements

pyomo/common/tee.py

@@ -24,7 +24,7 @@
 from io import StringIO
 
 _mswindows = sys.platform.startswith('win')
-_poll_interval = 0.1
+_poll_interval = 0.0001
 try:
     if _mswindows:
         from msvcrt import get_osfhandle
@@ -244,15 +244,15 @@ def close(self, in_exception=False):
             h.close()
 
         # Join all stream processing threads
-        join_iter = 1
+        _poll = _poll_interval
         while True:
             for th in self._threads:
-                th.join(_poll_interval*join_iter)
+                th.join(_poll)
             self._threads[:] = [th for th in self._threads if th.is_alive()]
             if not self._threads:
                 break
-            join_iter += 1
-            if join_iter == 10:
+            _poll *= 2
+            if _poll >= 2:  # bail after a total of 2 seconds * #threads
                 if in_exception:
                     # We are already processing an exception: no reason
                     # to trigger another
@@ -310,9 +310,20 @@ def _streamReader(self, handle):
     def _mergedReader(self):
         noop = []
         handles = self._handles
+        _poll = _poll_interval
+        _fast_poll_ct = 10
+        new_data = '' # something not None
         while handles:
-            if _mswindows:
+            if new_data is None:
+                if _fast_poll_ct:
+                    _fast_poll_ct -= 1
+                    if not _fast_poll_ct:
+                        _poll *= 10
+                        if _poll < 0.095:
+                            _fast_poll_ct = 10
+            else:
                 new_data = None
+            if _mswindows:
                 for handle in list(handles):
                     try:
                         pipe = get_osfhandle(handle.read_pipe)
@@ -328,7 +339,7 @@ def _mergedReader(self):
                 if new_data is None:
                     # PeekNamedPipe is non-blocking; to avoid swamping
                     # the core, sleep for a "short" amount of time
-                    time.sleep(_poll_interval)
+                    time.sleep(_poll)
                     continue
             else:
                 # Because we could be *adding* handles to the TeeStream
@@ -339,8 +350,9 @@ def _mergedReader(self):
                 # deadlocks when handles are added while select() is
                 # waiting
                 ready_handles = select(
-                    list(handles), noop, noop, _poll_interval)[0]
+                    list(handles), noop, noop, _poll)[0]
                 if not ready_handles:
+                    new_data = None
                     continue
 
                 handle = ready_handles[0]

pyomo/common/tests/test_tee.py

@@ -51,10 +51,10 @@ def test_merge_out_and_err(self):
             # flush() and short pause should help
             t.STDOUT.write("Hello\nWorld")
             t.STDOUT.flush()
-            time.sleep(tee._poll_interval*2)
+            time.sleep(tee._poll_interval*20)
             t.STDERR.write("interrupting\ncow")
             t.STDERR.flush()
-            time.sleep(tee._poll_interval*3)
+            time.sleep(tee._poll_interval*30)
         self.assertEqual(a.getvalue(), "Hello\ninterrupting\ncowWorld")
         self.assertEqual(b.getvalue(), "Hello\ninterrupting\ncowWorld")
 

pyomo/common/tests/test_timing.py

@@ -11,6 +11,7 @@
 import pyomo.common.unittest as unittest
 from pyomo.common.tee import capture_output
 
+import gc
 from io import StringIO
 import sys
 import time
@@ -21,6 +22,14 @@
 from pyomo.environ import ConcreteModel, RangeSet, Var, TransformationFactory
 
 class TestTiming(unittest.TestCase):
+    def setUp(self):
+        self.reenable_gc = gc.isenabled()
+        gc.disable()
+
+    def tearDown(self):
+        if self.reenable_gc:
+            gc.enable()
+
     def test_raw_construction_timer(self):
         a = ConstructionTimer(None)
         self.assertIn(
@@ -86,7 +95,7 @@ def test_report_timing(self):
 
     def test_TicTocTimer_tictoc(self):
         SLEEP = 0.1
-        RES = 0.02 # resolution (seconds): 1/5 the sleep
+        RES = 0.01 # resolution (seconds): 1/10 the sleep
         timer = TicTocTimer()
         abs_time = time.time()
 
@@ -143,7 +152,7 @@ def test_TicTocTimer_tictoc(self):
         # Note: pypy on GHA frequently has timing differences of >0.05s
         # for the following tests
         if 'pypy_version_info' in dir(sys):
-            RES = 6.5e-2
+            RES = 0.065
 
         with capture_output() as out:
             delta = timer.toc()
@@ -165,7 +174,7 @@ def test_TicTocTimer_tictoc(self):
         )
 
     def test_HierarchicalTimer(self):
-        RES = 1e-2 # resolution (seconds)
+        RES = 0.01 # resolution (seconds)
 
         timer = HierarchicalTimer()
         start_time = time.time()

pyomo/environ/tests/test_environ.py

@@ -152,6 +152,7 @@ def test_tpl_import_time(self):
             'gzip',
             'imp',
             'runpy',
+            'six',
             'tarfile',
             'zipfile',
         }