bpo-35513: Replace time.time() with time.monotonic() in tests (GH-11182)

Replace time.time() with time.monotonic() in tests to measure time
delta.

test_zipfile64: display progress every minute (60 secs) rather than
every 5 minutes (5*60 seconds).

Lib/pydoc.py

@@ -2231,14 +2231,14 @@ def _start_server(urlhandler, hostname, port):
         Let the server do its thing. We just need to monitor its status.
         Use time.sleep so the loop doesn't hog the CPU.
 
-        >>> starttime = time.time()
+        >>> starttime = time.monotonic()
         >>> timeout = 1                    #seconds
 
         This is a short timeout for testing purposes.
 
         >>> while serverthread.serving:
         ...     time.sleep(.01)
-        ...     if serverthread.serving and time.time() - starttime > timeout:
+        ...     if serverthread.serving and time.monotonic() - starttime > timeout:
         ...          serverthread.stop()
         ...          break
 

Lib/test/_test_multiprocessing.py

@@ -155,11 +155,11 @@ class TimingWrapper(object):
         self.elapsed = None
 
     def __call__(self, *args, **kwds):
-        t = time.time()
+        t = time.monotonic()
         try:
             return self.func(*args, **kwds)
         finally:
-            self.elapsed = time.time() - t
+            self.elapsed = time.monotonic() - t
 
 #
 # Base class for test cases
@@ -1034,9 +1034,9 @@ class _TestQueue(BaseTestCase):
 
     def test_timeout(self):
         q = multiprocessing.Queue()
-        start = time.time()
+        start = time.monotonic()
         self.assertRaises(pyqueue.Empty, q.get, True, 0.200)
-        delta = time.time() - start
+        delta = time.monotonic() - start
         # bpo-30317: Tolerate a delta of 100 ms because of the bad clock
         # resolution on Windows (usually 15.6 ms). x86 Windows7 3.x once
         # failed because the delta was only 135.8 ms.
@@ -1440,9 +1440,9 @@ class _TestCondition(BaseTestCase):
         sem.release()
         with cond:
             expected = 0.1
-            dt = time.time()
+            dt = time.monotonic()
             result = cond.wait_for(lambda : state.value==4, timeout=expected)
-            dt = time.time() - dt
+            dt = time.monotonic() - dt
             # borrow logic in assertTimeout() from test/lock_tests.py
             if not result and expected * 0.6 < dt < expected * 10.0:
                 success.value = True
@@ -2533,7 +2533,7 @@ class _TestPool(BaseTestCase):
         # process would fill the result queue (after the result handler thread
         # terminated, hence not draining it anymore).
 
-        t_start = time.time()
+        t_start = time.monotonic()
 
         with self.assertRaises(ValueError):
             with self.Pool(2) as p:
@@ -2545,7 +2545,7 @@ class _TestPool(BaseTestCase):
                     p.join()
 
         # check that we indeed waited for all jobs
-        self.assertGreater(time.time() - t_start, 0.9)
+        self.assertGreater(time.monotonic() - t_start, 0.9)
 
     def test_release_task_refs(self):
         # Issue #29861: task arguments and results should not be kept
@@ -4108,9 +4108,9 @@ class TestWait(unittest.TestCase):
         expected = 5
         a, b = multiprocessing.Pipe()
 
-        start = time.time()
+        start = time.monotonic()
         res = wait([a, b], expected)
-        delta = time.time() - start
+        delta = time.monotonic() - start
 
         self.assertEqual(res, [])
         self.assertLess(delta, expected * 2)
@@ -4118,9 +4118,9 @@ class TestWait(unittest.TestCase):
 
         b.send(None)
 
-        start = time.time()
+        start = time.monotonic()
         res = wait([a, b], 20)
-        delta = time.time() - start
+        delta = time.monotonic() - start
 
         self.assertEqual(res, [a])
         self.assertLess(delta, 0.4)
@@ -4144,9 +4144,9 @@ class TestWait(unittest.TestCase):
         self.assertIsInstance(p.sentinel, int)
         self.assertTrue(sem.acquire(timeout=20))
 
-        start = time.time()
+        start = time.monotonic()
         res = wait([a, p.sentinel, b], expected + 20)
-        delta = time.time() - start
+        delta = time.monotonic() - start
 
         self.assertEqual(res, [p.sentinel])
         self.assertLess(delta, expected + 2)
@@ -4154,18 +4154,18 @@ class TestWait(unittest.TestCase):
 
         a.send(None)
 
-        start = time.time()
+        start = time.monotonic()
         res = wait([a, p.sentinel, b], 20)
-        delta = time.time() - start
+        delta = time.monotonic() - start
 
         self.assertEqual(sorted_(res), sorted_([p.sentinel, b]))
         self.assertLess(delta, 0.4)
 
         b.send(None)
 
-        start = time.time()
+        start = time.monotonic()
         res = wait([a, p.sentinel, b], 20)
-        delta = time.time() - start
+        delta = time.monotonic() - start
 
         self.assertEqual(sorted_(res), sorted_([a, p.sentinel, b]))
         self.assertLess(delta, 0.4)
@@ -4176,9 +4176,9 @@ class TestWait(unittest.TestCase):
     def test_neg_timeout(self):
         from multiprocessing.connection import wait
         a, b = multiprocessing.Pipe()
-        t = time.time()
+        t = time.monotonic()
         res = wait([a], timeout=-1)
-        t = time.time() - t
+        t = time.monotonic() - t
         self.assertEqual(res, [])
         self.assertLess(t, 1)
         a.close()

Lib/test/lock_tests.py

@@ -74,7 +74,7 @@ class BaseTestCase(unittest.TestCase):
         support.reap_children()
 
     def assertTimeout(self, actual, expected):
-        # The waiting and/or time.time() can be imprecise, which
+        # The waiting and/or time.monotonic() can be imprecise, which
         # is why comparing to the expected value would sometimes fail
         # (especially under Windows).
         self.assertGreaterEqual(actual, expected * 0.6)
@@ -190,16 +190,16 @@ class BaseLockTests(BaseTestCase):
         # TIMEOUT_MAX is ok
         lock.acquire(timeout=TIMEOUT_MAX)
         lock.release()
-        t1 = time.time()
+        t1 = time.monotonic()
         self.assertTrue(lock.acquire(timeout=5))
-        t2 = time.time()
+        t2 = time.monotonic()
         # Just a sanity test that it didn't actually wait for the timeout.
         self.assertLess(t2 - t1, 5)
         results = []
         def f():
-            t1 = time.time()
+            t1 = time.monotonic()
             results.append(lock.acquire(timeout=0.5))
-            t2 = time.time()
+            t2 = time.monotonic()
             results.append(t2 - t1)
         Bunch(f, 1).wait_for_finished()
         self.assertFalse(results[0])
@@ -382,9 +382,9 @@ class EventTests(BaseTestCase):
         N = 5
         def f():
             results1.append(evt.wait(0.0))
-            t1 = time.time()
+            t1 = time.monotonic()
             r = evt.wait(0.5)
-            t2 = time.time()
+            t2 = time.monotonic()
             results2.append((r, t2 - t1))
         Bunch(f, N).wait_for_finished()
         self.assertEqual(results1, [False] * N)
@@ -545,9 +545,9 @@ class ConditionTests(BaseTestCase):
         N = 5
         def f():
             cond.acquire()
-            t1 = time.time()
+            t1 = time.monotonic()
             result = cond.wait(0.5)
-            t2 = time.time()
+            t2 = time.monotonic()
             cond.release()
             results.append((t2 - t1, result))
         Bunch(f, N).wait_for_finished()
@@ -584,9 +584,9 @@ class ConditionTests(BaseTestCase):
         success = []
         def f():
             with cond:
-                dt = time.time()
+                dt = time.monotonic()
                 result = cond.wait_for(lambda : state==4, timeout=0.1)
-                dt = time.time() - dt
+                dt = time.monotonic() - dt
                 self.assertFalse(result)
                 self.assertTimeout(dt, 0.1)
                 success.append(None)
@@ -692,9 +692,9 @@ class BaseSemaphoreTests(BaseTestCase):
         self.assertFalse(sem.acquire(timeout=0.005))
         sem.release()
         self.assertTrue(sem.acquire(timeout=0.005))
-        t = time.time()
+        t = time.monotonic()
         self.assertFalse(sem.acquire(timeout=0.5))
-        dt = time.time() - t
+        dt = time.monotonic() - t
         self.assertTimeout(dt, 0.5)
 
     def test_default_value(self):

Lib/test/support/__init__.py

@@ -2259,11 +2259,11 @@ def start_threads(threads, unlock=None):
         try:
             if unlock:
                 unlock()
-            endtime = starttime = time.time()
+            endtime = starttime = time.monotonic()
             for timeout in range(1, 16):
                 endtime += 60
                 for t in started:
-                    t.join(max(endtime - time.time(), 0.01))
+                    t.join(max(endtime - time.monotonic(), 0.01))
                 started = [t for t in started if t.isAlive()]
                 if not started:
                     break

Lib/test/test_asyncio/utils.py

@@ -107,10 +107,10 @@ def run_briefly(loop):
 
 
 def run_until(loop, pred, timeout=30):
-    deadline = time.time() + timeout
+    deadline = time.monotonic() + timeout
     while not pred():
         if timeout is not None:
-            timeout = deadline - time.time()
+            timeout = deadline - time.monotonic()
             if timeout <= 0:
                 raise futures.TimeoutError()
         loop.run_until_complete(tasks.sleep(0.001))

Lib/test/test_asyncore.py

@@ -70,8 +70,8 @@ def capture_server(evt, buf, serv):
         pass
     else:
         n = 200
-        start = time.time()
-        while n > 0 and time.time() - start < 3.0:
+        start = time.monotonic()
+        while n > 0 and time.monotonic() - start < 3.0:
             r, w, e = select.select([conn], [], [], 0.1)
             if r:
                 n -= 1

Lib/test/test_dummy_thread.py

@@ -70,14 +70,14 @@ class LockTests(unittest.TestCase):
             to_unlock.release()
 
         self.lock.acquire()
-        start_time = int(time.time())
+        start_time = int(time.monotonic())
         _thread.start_new_thread(delay_unlock,(self.lock, DELAY))
         if support.verbose:
             print()
             print("*** Waiting for thread to release the lock "\
             "(approx. %s sec.) ***" % DELAY)
         self.lock.acquire()
-        end_time = int(time.time())
+        end_time = int(time.monotonic())
         if support.verbose:
             print("done")
         self.assertGreaterEqual(end_time - start_time, DELAY,

Lib/test/test_ossaudiodev.py

@@ -77,10 +77,10 @@ class OSSAudioDevTests(unittest.TestCase):
         # set parameters based on .au file headers
         dsp.setparameters(AFMT_S16_NE, nchannels, rate)
         self.assertTrue(abs(expected_time - 3.51) < 1e-2, expected_time)
-        t1 = time.time()
+        t1 = time.monotonic()
         dsp.write(data)
         dsp.close()
-        t2 = time.time()
+        t2 = time.monotonic()
         elapsed_time = t2 - t1
 
         percent_diff = (abs(elapsed_time - expected_time) / expected_time) * 100

Lib/test/test_pydoc.py

@@ -1131,12 +1131,12 @@ class PydocServerTest(unittest.TestCase):
         serverthread = pydoc._start_server(my_url_handler, hostname='0.0.0.0', port=0)
         self.assertIn('0.0.0.0', serverthread.docserver.address)
 
-        starttime = time.time()
+        starttime = time.monotonic()
         timeout = 1  #seconds
 
         while serverthread.serving:
             time.sleep(.01)
-            if serverthread.serving and time.time() - starttime > timeout:
+            if serverthread.serving and time.monotonic() - starttime > timeout:
                 serverthread.stop()
                 break
 

Lib/test/test_signal.py

@@ -1163,18 +1163,18 @@ class StressTest(unittest.TestCase):
         self.setsig(signal.SIGALRM, second_handler)  # for ITIMER_REAL
 
         expected_sigs = 0
-        deadline = time.time() + 15.0
+        deadline = time.monotonic() + 15.0
 
         while expected_sigs < N:
             os.kill(os.getpid(), signal.SIGPROF)
             expected_sigs += 1
             # Wait for handlers to run to avoid signal coalescing
-            while len(sigs) < expected_sigs and time.time() < deadline:
+            while len(sigs) < expected_sigs and time.monotonic() < deadline:
                 time.sleep(1e-5)
 
             os.kill(os.getpid(), signal.SIGUSR1)
             expected_sigs += 1
-            while len(sigs) < expected_sigs and time.time() < deadline:
+            while len(sigs) < expected_sigs and time.monotonic() < deadline:
                 time.sleep(1e-5)
 
         # All ITIMER_REAL signals should have been delivered to the
@@ -1197,7 +1197,7 @@ class StressTest(unittest.TestCase):
         self.setsig(signal.SIGALRM, handler)  # for ITIMER_REAL
 
         expected_sigs = 0
-        deadline = time.time() + 15.0
+        deadline = time.monotonic() + 15.0
 
         while expected_sigs < N:
             # Hopefully the SIGALRM will be received somewhere during
@@ -1207,7 +1207,7 @@ class StressTest(unittest.TestCase):
 
             expected_sigs += 2
             # Wait for handlers to run to avoid signal coalescing
-            while len(sigs) < expected_sigs and time.time() < deadline:
+            while len(sigs) < expected_sigs and time.monotonic() < deadline:
                 time.sleep(1e-5)
 
         # All ITIMER_REAL signals should have been delivered to the

Lib/test/test_threadsignals.py

@@ -95,9 +95,9 @@ class ThreadSignals(unittest.TestCase):
             lock = thread.allocate_lock()
             lock.acquire()
             signal.alarm(1)
-            t1 = time.time()
+            t1 = time.monotonic()
             self.assertRaises(KeyboardInterrupt, lock.acquire, timeout=5)
-            dt = time.time() - t1
+            dt = time.monotonic() - t1
             # Checking that KeyboardInterrupt was raised is not sufficient.
             # We want to assert that lock.acquire() was interrupted because
             # of the signal, not that the signal handler was called immediately
@@ -136,9 +136,9 @@ class ThreadSignals(unittest.TestCase):
                     rlock.release()
                     time.sleep(0.01)
                 signal.alarm(1)
-                t1 = time.time()
+                t1 = time.monotonic()
                 self.assertRaises(KeyboardInterrupt, rlock.acquire, timeout=5)
-                dt = time.time() - t1
+                dt = time.monotonic() - t1
                 # See rationale above in test_lock_acquire_interruption
                 self.assertLess(dt, 3.0)
         finally:
@@ -203,9 +203,9 @@ class ThreadSignals(unittest.TestCase):
         old_handler = signal.signal(signal.SIGUSR1, my_handler)
         try:
             def timed_acquire():
-                self.start = time.time()
+                self.start = time.monotonic()
                 lock.acquire(timeout=0.5)
-                self.end = time.time()
+                self.end = time.monotonic()
             def send_signals():
                 for _ in range(40):
                     time.sleep(0.02)

Lib/test/test_timeout.py

@@ -127,11 +127,11 @@ class TimeoutTestCase(unittest.TestCase):
         self.sock.settimeout(timeout)
         method = getattr(self.sock, method)
         for i in range(count):
-            t1 = time.time()
+            t1 = time.monotonic()
             try:
                 method(*args)
             except socket.timeout as e:
-                delta = time.time() - t1
+                delta = time.monotonic() - t1
                 break
         else:
             self.fail('socket.timeout was not raised')

Lib/test/test_zipfile64.py

@@ -22,7 +22,7 @@ from test.support import TESTFN, requires_zlib
 TESTFN2 = TESTFN + "2"
 
 # How much time in seconds can pass before we print a 'Still working' message.
-_PRINT_WORKING_MSG_INTERVAL = 5 * 60
+_PRINT_WORKING_MSG_INTERVAL = 60
 
 class TestsWithSourceFile(unittest.TestCase):
     def setUp(self):
@@ -43,12 +43,12 @@ class TestsWithSourceFile(unittest.TestCase):
         # raw data to store.
         filecount = 6*1024**3 // len(self.data)
 
-        next_time = time.time() + _PRINT_WORKING_MSG_INTERVAL
+        next_time = time.monotonic() + _PRINT_WORKING_MSG_INTERVAL
         for num in range(filecount):
             zipfp.writestr("testfn%d" % num, self.data)
             # Print still working message since this test can be really slow
-            if next_time <= time.time():
-                next_time = time.time() + _PRINT_WORKING_MSG_INTERVAL
+            if next_time <= time.monotonic():
+                next_time = time.monotonic() + _PRINT_WORKING_MSG_INTERVAL
                 print((
                    '  zipTest still writing %d of %d, be patient...' %
                    (num, filecount)), file=sys.__stdout__)
@@ -60,8 +60,8 @@ class TestsWithSourceFile(unittest.TestCase):
         for num in range(filecount):
             self.assertEqual(zipfp.read("testfn%d" % num), self.data)
             # Print still working message since this test can be really slow
-            if next_time <= time.time():
-                next_time = time.time() + _PRINT_WORKING_MSG_INTERVAL
+            if next_time <= time.monotonic():
+                next_time = time.monotonic() + _PRINT_WORKING_MSG_INTERVAL
                 print((
                    '  zipTest still reading %d of %d, be patient...' %
                    (num, filecount)), file=sys.__stdout__)

Misc/NEWS.d/next/Tests/2018-12-16-23-36-47.bpo-35513.k4WHlA.rst

+Replace :func:`time.time` with :func:`time.monotonic` in tests to measure
+time delta.