Skip to content
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.

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

[Windows] test_int.test_denial_of_service failed: took 15ms #114911

Open
encukou opened this issue Feb 2, 2024 · 8 comments
Open

[Windows] test_int.test_denial_of_service failed: took 15ms #114911

encukou opened this issue Feb 2, 2024 · 8 comments
Labels
tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error

Comments

@encukou
Copy link
Member

encukou commented Feb 2, 2024

test_int recently failed on a buildbot:

======================================================================
FAIL: test_denial_of_service_prevented_str_to_int (test.test_int.IntSubclassStrDigitLimitsTests.test_denial_of_service_prevented_str_to_int)
Regression test: ensure we fail before performing O(N**2) work.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "b:\uildarea\3.12.ware-win11.nondebug\build\Lib\test\test_int.py", line 743, in test_denial_of_service_prevented_str_to_int
    self.assertLessEqual(seconds_to_fail_extra_huge, seconds_to_convert/2)
AssertionError: 0.015625 not less than or equal to 0.0078125

I don't know for sure, but my guess is that a GC collection got triggered at the wrong time.

I'd like to add a test helper for timing CPU-bound tasks. It should disable GC and use process_time; perhaps it can do other tricks in the future too.

Linked PRs

encukou added a commit to encukou/cpython that referenced this issue Feb 2, 2024
A few of our tests measure the time of CPU-bound operation, mainly
to avoid quadratic or worse behaviour.
Add a helper to ignore GC and time spent in other processes.
@encukou encukou added type-bug An unexpected behavior, bug, or error tests Tests in the Lib/test dir labels Feb 2, 2024
@vstinner
Copy link
Member

AssertionError: 0.015625 not less than or equal to 0.0078125

The problem here is that time.monotonic() has a resolution of 15.6 ms on Windows. It can return 0 or 15.6 ms for short timing, nothing in between. I added "CLOCK_RES" to some tests:

$ grep 'CLOCK_RES =' Lib/test/ -R
Lib/test/test_asyncio/utils.py:CLOCK_RES = 0.050
Lib/test/_test_eintr.py:CLOCK_RES = 0.020
Lib/test/_test_multiprocessing.py:CLOCK_RES = 0.100
Lib/test/test_os.py:    CLOCK_RES = CLOCK_RES_NS * 1e-9

@vstinner
Copy link
Member

The problem here is that time.monotonic() has a resolution of 15.6 ms on Windows

I don't know if it's the root issue or not. I will try to reproduce to debug the issue on Windows.

@encukou
Copy link
Member Author

encukou commented Feb 12, 2024

Hm, this is usingprocess_time. Should it use perf_counter instead?

@sobolevn
Copy link
Member

Happened again: #115504 (comment)

encukou added a commit that referenced this issue Feb 28, 2024
A few of our tests measure the time of CPU-bound operation, mainly
to avoid quadratic or worse behaviour.
Add a helper to ignore GC and time spent in other processes.
woodruffw pushed a commit to woodruffw-forks/cpython that referenced this issue Mar 4, 2024
A few of our tests measure the time of CPU-bound operation, mainly
to avoid quadratic or worse behaviour.
Add a helper to ignore GC and time spent in other processes.
adorilson pushed a commit to adorilson/cpython that referenced this issue Mar 25, 2024
A few of our tests measure the time of CPU-bound operation, mainly
to avoid quadratic or worse behaviour.
Add a helper to ignore GC and time spent in other processes.
diegorusso pushed a commit to diegorusso/cpython that referenced this issue Apr 17, 2024
A few of our tests measure the time of CPU-bound operation, mainly
to avoid quadratic or worse behaviour.
Add a helper to ignore GC and time spent in other processes.
@encukou
Copy link
Member Author

encukou commented Oct 8, 2024

@terryjreedy, do you see this on a machine where you could test a fix?

@terryjreedy
Copy link
Member

I observed 2 failures in about 18 tries on installed 3.13.0 no-debug gil. I could hand-patch (copy-patch) a bit of test_int.

On fairly fresh local debug no-gil build I got 0 failures in 40 tries. Easy to patch from PR, but need something that fails to test fix.

@vstinner
Copy link
Member

The problem here is that time.monotonic() has a resolution of 15.6 ms on Windows.

I changed time.monotonic() in Python 3.13 to use QueryPerformanceCounter(). It now has a resolution better than 1 microsecond.

@chris-eibl
Copy link
Contributor

The problem here is that time.monotonic() has a resolution of 15.6 ms on Windows.

test_denial_of_service_prevented_str_to_int uses process_time (before and after Petr's PR #114912).

process_times claims a resolution of 1e-07 for Windows, but that's just the "units" which are used to report, see e.g. #82040 (comment).

Like @eryksun mentioned there, the "real" resolution is 15.625 ms by default, hence the 0.015625 in the traceback.

On my PC sw_convert.seconds is in the order of 20 milliseconds (wall time).
Here are example frequencies for process_times of sw_convert.seconds for 100 runs using collections.Counter:
Counter({0.015625: 67, 0.03125: 30, 0.0: 3})
which means, that in about two out of three cases sw_convert.seconds equals 0.015625, 3 times the test bails out using SkipTest('"slow" conversion') and 30% I end up with 0.03125.

It can return 0 or 15.6 ms for short timing, nothing in between.

Exactly this happens in very rare cases for sw_fail_huge.seconds or sw_fail_extra_huge.seconds even though they are only 2 to 4 microseconds wall time on my PC. Almost always this results in process_time=0, but sometimes you get process_time=15.625 ms and then the test fails.

If we fix the reported resolution of process_time, then we will have to increase the digits for Windows, because otherwise we would almost always skip the test.
Or calculate the needed digits at runtime instead of hard coding, like @time-one suggests in #118686.

Hm, this is using process_time. Should it use perf_counter instead?

This would fix Windows and other OSs having such poor resolution for process_times. All platforms should have "good enough" resolution in case of perf_counter:

[...] i.e. a clock with the highest available resolution to measure a short duration.

But then CPUStopwatch should be renamed to just Stopwatch or WalltimeStopwatch?

@vstinner vstinner changed the title test_int.test_denial_of_service failed: took 15ms [Windows] test_int.test_denial_of_service failed: took 15ms Jan 9, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error
Projects
None yet
Development

No branches or pull requests

5 participants