From db0a258e796703e12befea9d6dec04e349ca2f5b Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Fri, 29 Sep 2023 13:49:30 +0200 Subject: gh-110088, gh-109878: Fix test_asyncio timeouts (#110092) Fix test_asyncio timeouts: don't measure the maximum duration, a test should not measure a CI performance. Only measure the minimum duration when a task has a timeout or delay. Add CLOCK_RES to test_asyncio.utils. --- Lib/test/test_asyncio/test_base_events.py | 7 ++----- Lib/test/test_asyncio/test_events.py | 8 ++++---- Lib/test/test_asyncio/test_timeouts.py | 20 -------------------- Lib/test/test_asyncio/test_waitfor.py | 15 --------------- Lib/test/test_asyncio/test_windows_events.py | 13 +++---------- Lib/test/test_asyncio/utils.py | 6 ++++++ .../2023-09-29-12-48-42.gh-issue-110088.qUhRga.rst | 4 ++++ 7 files changed, 19 insertions(+), 54 deletions(-) create mode 100644 Misc/NEWS.d/next/Tests/2023-09-29-12-48-42.gh-issue-110088.qUhRga.rst diff --git a/Lib/test/test_asyncio/test_base_events.py b/Lib/test/test_asyncio/test_base_events.py index 3b4026c..abcb6f5 100644 --- a/Lib/test/test_asyncio/test_base_events.py +++ b/Lib/test/test_asyncio/test_base_events.py @@ -273,7 +273,7 @@ class BaseEventLoopTests(test_utils.TestCase): self.loop.stop() self.loop._process_events = mock.Mock() - delay = 0.1 + delay = 0.100 when = self.loop.time() + delay self.loop.call_at(when, cb) @@ -282,10 +282,7 @@ class BaseEventLoopTests(test_utils.TestCase): dt = self.loop.time() - t0 # 50 ms: maximum granularity of the event loop - self.assertGreaterEqual(dt, delay - 0.050, dt) - # tolerate a difference of +800 ms because some Python buildbots - # are really slow - self.assertLessEqual(dt, 0.9, dt) + self.assertGreaterEqual(dt, delay - test_utils.CLOCK_RES) with self.assertRaises(TypeError, msg="when cannot be None"): self.loop.call_at(None, cb) diff --git a/Lib/test/test_asyncio/test_events.py b/Lib/test/test_asyncio/test_events.py index f22cb5e..3ee6565 100644 --- a/Lib/test/test_asyncio/test_events.py +++ b/Lib/test/test_asyncio/test_events.py @@ -293,10 +293,11 @@ class EventLoopTestsMixin: # 15.6 msec, we use fairly long sleep times here (~100 msec). def test_run_until_complete(self): + delay = 0.100 t0 = self.loop.time() - self.loop.run_until_complete(asyncio.sleep(0.1)) - t1 = self.loop.time() - self.assertTrue(0.08 <= t1-t0 <= 0.8, t1-t0) + self.loop.run_until_complete(asyncio.sleep(delay)) + dt = self.loop.time() - t0 + self.assertGreaterEqual(dt, delay - test_utils.CLOCK_RES) def test_run_until_complete_stopped(self): @@ -1717,7 +1718,6 @@ class EventLoopTestsMixin: self.loop._run_once = _run_once async def wait(): - loop = self.loop await asyncio.sleep(1e-2) await asyncio.sleep(1e-4) await asyncio.sleep(1e-6) diff --git a/Lib/test/test_asyncio/test_timeouts.py b/Lib/test/test_asyncio/test_timeouts.py index 8b6b9a1..e9b59b9 100644 --- a/Lib/test/test_asyncio/test_timeouts.py +++ b/Lib/test/test_asyncio/test_timeouts.py @@ -46,7 +46,6 @@ class TimeoutTests(unittest.IsolatedAsyncioTestCase): self.assertTrue(cm2.expired()) async def test_waiter_cancelled(self): - loop = asyncio.get_running_loop() cancelled = False with self.assertRaises(TimeoutError): async with asyncio.timeout(0.01): @@ -59,39 +58,26 @@ class TimeoutTests(unittest.IsolatedAsyncioTestCase): async def test_timeout_not_called(self): loop = asyncio.get_running_loop() - t0 = loop.time() async with asyncio.timeout(10) as cm: await asyncio.sleep(0.01) t1 = loop.time() self.assertFalse(cm.expired()) - # 2 sec for slow CI boxes - self.assertLess(t1-t0, 2) self.assertGreater(cm.when(), t1) async def test_timeout_disabled(self): - loop = asyncio.get_running_loop() - t0 = loop.time() async with asyncio.timeout(None) as cm: await asyncio.sleep(0.01) - t1 = loop.time() self.assertFalse(cm.expired()) self.assertIsNone(cm.when()) - # 2 sec for slow CI boxes - self.assertLess(t1-t0, 2) async def test_timeout_at_disabled(self): - loop = asyncio.get_running_loop() - t0 = loop.time() async with asyncio.timeout_at(None) as cm: await asyncio.sleep(0.01) - t1 = loop.time() self.assertFalse(cm.expired()) self.assertIsNone(cm.when()) - # 2 sec for slow CI boxes - self.assertLess(t1-t0, 2) async def test_timeout_zero(self): loop = asyncio.get_running_loop() @@ -101,8 +87,6 @@ class TimeoutTests(unittest.IsolatedAsyncioTestCase): await asyncio.sleep(10) t1 = loop.time() self.assertTrue(cm.expired()) - # 2 sec for slow CI boxes - self.assertLess(t1-t0, 2) self.assertTrue(t0 <= cm.when() <= t1) async def test_timeout_zero_sleep_zero(self): @@ -113,8 +97,6 @@ class TimeoutTests(unittest.IsolatedAsyncioTestCase): await asyncio.sleep(0) t1 = loop.time() self.assertTrue(cm.expired()) - # 2 sec for slow CI boxes - self.assertLess(t1-t0, 2) self.assertTrue(t0 <= cm.when() <= t1) async def test_timeout_in_the_past_sleep_zero(self): @@ -125,8 +107,6 @@ class TimeoutTests(unittest.IsolatedAsyncioTestCase): await asyncio.sleep(0) t1 = loop.time() self.assertTrue(cm.expired()) - # 2 sec for slow CI boxes - self.assertLess(t1-t0, 2) self.assertTrue(t0 >= cm.when() <= t1) async def test_foreign_exception_passed(self): diff --git a/Lib/test/test_asyncio/test_waitfor.py b/Lib/test/test_asyncio/test_waitfor.py index e714b15..d52f325 100644 --- a/Lib/test/test_asyncio/test_waitfor.py +++ b/Lib/test/test_asyncio/test_waitfor.py @@ -66,17 +66,12 @@ class AsyncioWaitForTest(unittest.IsolatedAsyncioTestCase): fut = loop.create_future() fut.set_result('done') - t0 = loop.time() ret = await asyncio.wait_for(fut, 0) - t1 = loop.time() self.assertEqual(ret, 'done') self.assertTrue(fut.done()) - self.assertLess(t1 - t0, 0.1) async def test_wait_for_timeout_less_then_0_or_0_coroutine_do_not_started(self): - loop = asyncio.get_running_loop() - foo_started = False async def foo(): @@ -84,12 +79,9 @@ class AsyncioWaitForTest(unittest.IsolatedAsyncioTestCase): foo_started = True with self.assertRaises(asyncio.TimeoutError): - t0 = loop.time() await asyncio.wait_for(foo(), 0) - t1 = loop.time() self.assertEqual(foo_started, False) - self.assertLess(t1 - t0, 0.1) async def test_wait_for_timeout_less_then_0_or_0(self): loop = asyncio.get_running_loop() @@ -113,18 +105,14 @@ class AsyncioWaitForTest(unittest.IsolatedAsyncioTestCase): await started with self.assertRaises(asyncio.TimeoutError): - t0 = loop.time() await asyncio.wait_for(fut, timeout) - t1 = loop.time() self.assertTrue(fut.done()) # it should have been cancelled due to the timeout self.assertTrue(fut.cancelled()) self.assertEqual(foo_running, False) - self.assertLess(t1 - t0, 0.1) async def test_wait_for(self): - loop = asyncio.get_running_loop() foo_running = None async def foo(): @@ -139,13 +127,10 @@ class AsyncioWaitForTest(unittest.IsolatedAsyncioTestCase): fut = asyncio.create_task(foo()) with self.assertRaises(asyncio.TimeoutError): - t0 = loop.time() await asyncio.wait_for(fut, 0.1) - t1 = loop.time() self.assertTrue(fut.done()) # it should have been cancelled due to the timeout self.assertTrue(fut.cancelled()) - self.assertLess(t1 - t0, support.SHORT_TIMEOUT) self.assertEqual(foo_running, False) async def test_wait_for_blocking(self): diff --git a/Lib/test/test_asyncio/test_windows_events.py b/Lib/test/test_asyncio/test_windows_events.py index a36119a..6e6c90a 100644 --- a/Lib/test/test_asyncio/test_windows_events.py +++ b/Lib/test/test_asyncio/test_windows_events.py @@ -163,29 +163,25 @@ class ProactorTests(test_utils.TestCase): # Wait for unset event with 0.5s timeout; # result should be False at timeout - fut = self.loop._proactor.wait_for_handle(event, 0.5) + timeout = 0.5 + fut = self.loop._proactor.wait_for_handle(event, timeout) start = self.loop.time() done = self.loop.run_until_complete(fut) elapsed = self.loop.time() - start self.assertEqual(done, False) self.assertFalse(fut.result()) - # bpo-31008: Tolerate only 450 ms (at least 500 ms expected), - # because of bad clock resolution on Windows - self.assertTrue(0.45 <= elapsed <= 0.9, elapsed) + self.assertGreaterEqual(elapsed, timeout - test_utils.CLOCK_RES) _overlapped.SetEvent(event) # Wait for set event; # result should be True immediately fut = self.loop._proactor.wait_for_handle(event, 10) - start = self.loop.time() done = self.loop.run_until_complete(fut) - elapsed = self.loop.time() - start self.assertEqual(done, True) self.assertTrue(fut.result()) - self.assertTrue(0 <= elapsed < 0.3, elapsed) # asyncio issue #195: cancelling a done _WaitHandleFuture # must not crash @@ -199,11 +195,8 @@ class ProactorTests(test_utils.TestCase): # CancelledError should be raised immediately fut = self.loop._proactor.wait_for_handle(event, 10) fut.cancel() - start = self.loop.time() with self.assertRaises(asyncio.CancelledError): self.loop.run_until_complete(fut) - elapsed = self.loop.time() - start - self.assertTrue(0 <= elapsed < 0.1, elapsed) # asyncio issue #195: cancelling a _WaitHandleFuture twice # must not crash diff --git a/Lib/test/test_asyncio/utils.py b/Lib/test/test_asyncio/utils.py index 1e5ab6e..e1101bf 100644 --- a/Lib/test/test_asyncio/utils.py +++ b/Lib/test/test_asyncio/utils.py @@ -36,6 +36,12 @@ from test.support import socket_helper from test.support import threading_helper +# Use the maximum known clock resolution (gh-75191, gh-110088): Windows +# GetTickCount64() has a resolution of 15.6 ms. Use 20 ms to tolerate rounding +# issues. +CLOCK_RES = 0.020 + + def data_file(*filename): fullname = os.path.join(support.TEST_HOME_DIR, *filename) if os.path.isfile(fullname): diff --git a/Misc/NEWS.d/next/Tests/2023-09-29-12-48-42.gh-issue-110088.qUhRga.rst b/Misc/NEWS.d/next/Tests/2023-09-29-12-48-42.gh-issue-110088.qUhRga.rst new file mode 100644 index 0000000..cf44a12 --- /dev/null +++ b/Misc/NEWS.d/next/Tests/2023-09-29-12-48-42.gh-issue-110088.qUhRga.rst @@ -0,0 +1,4 @@ +Fix test_asyncio timeouts: don't measure the maximum duration, a test should +not measure a CI performance. Only measure the minimum duration when a task has +a timeout or delay. Add ``CLOCK_RES`` to ``test_asyncio.utils``. Patch by +Victor Stinner. -- cgit v0.12