8000 test_asyncio.test_base_events: test_time_and_call_at() failed on GHA Windows x64 · Issue #110695 · python/cpython · GitHub
[go: up one dir, main page]
Skip to content

test_asyncio.test_base_events: test_time_and_call_at() failed on GHA Windows x64 #110695

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
vstinner opened this issue Oct 11, 2023 · 3 comments
Closed

test_asyncio.test_base_events: test_time_and_call_at() failed on GHA Windows x64 #110695

vstinner opened this issue Oct 11, 2023 · 3 comments
Labels
tests Tests in the Lib/test dir topic-asyncio

Comments

@vstinner
Copy link
Member
vstinner commented Oct 11, 2023 •
edited by bedevere-app bot
Loading

Recently, I modified asyncio tests to add a CLOCK_RES constant. Example of test_time_and_call_at() change:

+CLOCK_RES = 0.020
(...)
-        self.assertGreaterEqual(dt, delay - 0.050, dt)
+        self.assertGreaterEqual(dt, delay - test_utils.CLOCK_RES)

So the test now tolerates only 20 ms difference instead of 50 ms. Problem, the test failed on GHA Windows x64 CI :-(

asyncio uses time.monotonic() as loop.time(). test.pythoninfo reports a clock resolution of 15.6 ms.

call_at() creates a TimerHandle . _run_once() uses self._scheduled[0]._when - self.time() timeout to call self._selector.select(timeout). asyncio uses self._clock_resolution = time.get_clock_info('monotonic').resolution to decide in _run_once() if an event should be scheduled or not.

        # Handle 'later' callbacks that are ready.
        end_time = self.time() + self._clock_resolution
        while self._scheduled:
            handle = self._scheduled[0]
            if handle._when >= end_time:
                break

Maybe there is a rounding issue and sometimes a callback scheduled in 100 ms is actually run in 78 ms.

A timeout of 100 ms should wait 6 or 7 monotonic clock ticks, whereas 78 ms is around 5 clock ticks:

>>> k=0.015625
>>> 0.07799999999997453 / k
4.99199999999837
>>> 0.100 / k
6.4

The test reads the clock twice, maybe t0 is 1 tick ahead of when:

        when = self.loop.time() + delay
        self.loop.call_at(when, cb)
        t0 = self.loop.time()

It seems like the callback was called 2 ticks before the expected timeout when taking rounding issue in account:

>>> (0.100//k-1)*k, (0.100//k+1)*k
(0.078125, 0.109375)

The callback should be called between 78.1 ms (2 clicks before) and 109.4 ms (1 click after). It would be nice to only have an error of a maximum of 1 click:

>>> (0.100//k)*k, (0.100//k+1)*k
(0.09375, 0.109375)

Between 93.8 ms (1 click before) and 109.4 ms (1 click after).

I'm not sure what's going on.

GHA Windows x64:

FAIL: test_time_and_call_at (test.test_asyncio.test_base_events.BaseEventLoopTests.test_time_and_call_at)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_asyncio\test_base_events.py", line 285, in test_time_and_call_at
    self.assertGreaterEqual(dt, delay - test_utils.CLOCK_RES)
AssertionError: 0.07799999999997453 not greater than or equal to 0.08

test.pythoninfo:

time.altzone: -3600
time.daylight: 0
time.get_clock_info(monotonic): namespace(implementation='GetTickCount64()', monotonic=True, adjustable=False, resolution=0.015625)
time.get_clock_info(perf_counter): namespace(implementation='QueryPerformanceCounter()', monotonic=True, adjustable=False, resolution=1e-07)
time.get_clock_info(process_time): namespace(implementation='GetProcessTimes()', monotonic=True, adjustable=False, resolution=1e-07)
time.get_clock_info(thread_time): namespace(implementation='GetThreadTimes()', monotonic=True, adjustable=False, resolution=1e-07)
time.get_clock_info(time): namespace(implementation='GetSystemTimeAsFileTime()', monotonic=False, adjustable=True, resolution=0.015625)
time.time: 1696993710.9453082
time.timezone: 0
time.tzname: ('Coordinated Universal Time', 'Coordinated Universal Time')

build: https://github.com/python/cpython/actions/runs/6477453109/job/17587684818?pr=110677

cc @sobolevn @kumaraditya303

Linked PRs
@vstinner vstinner added tests Tests in the Lib/test dir topic-asyncio labels Oct 11, 2023
8000
@github-project-automation github-project-automation bot moved this to Todo in asyncio Oct 11, 2023
@kumaraditya303
Copy link
Contributor
kumaraditya303 commented Oct 12, 2023 •
edited
Loading

This happens because on windows it uses a lower precision clock, I once worked on a PR to use a higher precision clock but it was rejected in the hopes that by default monotonic would use higher precision clock but I don't think this it was ever implemented. I still think we should just change asyncio to use better precision clock instead of waiting for the default clock to change.

@gvanrossum
Copy link
Member

If you two (@vstinner and @kumaraditya303) agree, I will also agree to that proposal.

vstinner added a commit to vstinner/cpython that referenced this issue Oct 16, 2023
@vstinner
pythongh-110695: test_asyncio uses 50 ms for clock resolution
1fbd24a 
Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
@bedevere-app bedevere-app bot mentioned this issue Oct 16, 2023
Merged
@vstinner
Copy link
Member Author

This happens because on windows it uses a lower precision clock

Maybe asyncio could do better to not miss so many clock ticks, but I'm not really interested to enhance asyncio accuracy on Windows.

So I wrote PR #110952 to simply restore test_asyncio to its previous status quo, before commit db0a258: tolerate 50 ms difference.

This was referenced Oct 17, 2023
Merged
Merged
miss-islington pushed a commit to miss-islington/cpython that referenced this issue Oct 17, 2023
@vstinner @miss-islington
pythongh-110695: test_asyncio uses 50 ms for clock resolution (python…
89cc6a8 
…GH-110952)

Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
(cherry picked from commit 9a9fba8)

Co-authored-by: Victor Stinner <vstinner@python.org>
vstinner added a commit that referenced this issue Oct 17, 2023
@vstinner
gh-110695: test_asyncio uses 50 ms for clock resolution (#110952)
9a9fba8 
Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
miss-islington pushed a commit to miss-islington/cpython that referenced this issue Oct 17, 2023
@vstinner @miss-islington
pythongh-110695: test_asyncio uses 50 ms for clock resolution (python…
e6b2b5e 
…GH-110952)

Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
(cherry picked from commit 9a9fba8)

Co-authored-by: Victor Stinner <vstinner@python.org>
@github-project-automation github-project-automation bot moved this from Todo to Done in asyncio Oct 17, 2023
vstinner added a commit that referenced this issue Oct 17, 2023
@miss-islington @vstinner
[3.11] gh-110695: test_asyncio uses 50 ms for clock resolution (GH-11…
ae495de 
…0952) (#110971)

gh-110695: test_asyncio uses 50 ms for clock resolution (GH-110952)

Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
(cherry picked from commit 9a9fba8)

Co-authored-by: Victor Stinner <vstinner@python.org>
vstinner added a commit that referenced this issue Oct 17, 2023
@miss-islington @vstinner
[3.12] gh-110695: test_asyncio uses 50 ms for clock resolution (GH-11…
9aa8993 
…0952) (#110970)

gh-110695: test_asyncio uses 50 ms for clock resolution (GH-110952)

Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
(cherry picked from commit 9a9fba8)

Co-authored-by: Victor Stinner <vstinner@python.org>
aisk pushed a commit to aisk/cpython that referenced this issue Feb 11, 2024
@vstinner @aisk
pythongh-110695: test_asyncio uses 50 ms for clock resolution (python…
c548279 
…#110952)

Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
Glyphack pushed a commit to Glyphack/cpython that referenced this issue Sep 2, 2024
@vstinner @Glyphack
pythongh-110695: test_asyncio uses 50 ms for clock resolution (python…
21ec40b 
…#110952)

Before utils.CLOCK_RES constant was added (20 ms), test_asyncio
already used 50 ms.
@bharel bharel mentioned this issue Oct 21, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
tests Tests in the Lib/test dir topic-asyncio
Projects
asyncio
Status: Done
Milestone
No milestone
Development

No branches or pull requests
3 participants
@vstinner @gvanrossum @kumaraditya303
0