test_thread_time fails on NetBSD: time difference exceeds expected threshold #123978

furkanonder · 2024-09-11T21:03:09Z

Bug report

Bug description:

$ ./python -m test test_time -m test_thread_time
Using random seed: 4026164953
0:00:00 load avg: 2.27 Run 1 test sequentially in a single process
0:00:00 load avg: 2.27 [1/1] test_time
test test_time failed -- Traceback (most recent call last):
  File "/home/blue/cpython/Lib/test/test_time.py", line 535, in test_thread_time
    self.assertLess(stop - start, 0.2)
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^
AssertionError: 0.26 not less than 0.2

test_time failed (1 failure)

== Tests result: FAILURE ==

1 test failed:
    test_time

OS: NetBSD 10.0 amd64

CPython versions tested on:

CPython main branch

Operating systems tested on:

Other

Linked PRs

The text was updated successfully, but these errors were encountered:

furkanonder · 2024-09-11T21:04:24Z

I have run the test many times, I get results between 0.10 and 0.30.

Using random seed: 818701931
0:00:00 load avg: 2.28 Run 1 test sequentially in a single process
0:00:00 load avg: 2.28 [1/1] test_time
test test_time failed -- Traceback (most recent call last):
  File "/home/blue/cpython/Lib/test/test_time.py", line 535, in test_thread_time
    self.assertLess(stop - start, 0.2)
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^
AssertionError: 0.27 not less than 0.2

test_time failed (1 failure)

== Tests result: FAILURE ==

1 test failed:
    test_time

Total duration: 353 ms
Total tests: run=1 (filtered) failures=1
Total test files: run=1/1 (filtered) failed=1
Result: FAILURE

Using random seed: 1543948201
0:00:00 load avg: 4.24 Run 1 test sequentially in a single process
0:00:00 load avg: 4.24 [1/1] test_time
test test_time failed -- Traceback (most recent call last):
  File "/home/blue/cpython/Lib/test/test_time.py", line 534, in test_thread_time
    self.assertLess(stop - start, 0.020)
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
AssertionError: 0.12 not less than 0.02

test_time failed (1 failure)

== Tests result: FAILURE ==

1 test failed:
    test_time

Total duration: 472 ms
Total tests: run=1 (filtered) failures=1
Total test files: run=1/1 (filtered) failed=1
Result: FAILURE

Using random seed: 2805084624
0:00:00 load avg: 3.83 Run 1 test sequentially in a single process
0:00:00 load avg: 3.83 [1/1] test_time
test_thread_time (test.test_time.TimeTestCase.test_thread_time) ... FAIL

======================================================================
FAIL: test_thread_time (test.test_time.TimeTestCase.test_thread_time)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/blue/cpython/Lib/test/test_time.py", line 534, in test_thread_time
    self.assertLess(stop - start, 0.020)
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
AssertionError: 0.11000000000000004 not less than 0.02

----------------------------------------------------------------------
Ran 1 test in 0.128s

FAILED (failures=1)
test test_time failed
test_time failed (1 failure)

== Tests result: FAILURE ==

1 test failed:
    test_time

Total duration: 380 ms
Total tests: run=1 (filtered) failures=1
Total test files: run=1/1 (filtered) failed=1
Result: FAILURE

test_thread_time (test.test_time.TimeTestCase.test_thread_time) ... FAIL

======================================================================
FAIL: test_thread_time (test.test_time.TimeTestCase.test_thread_time)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/blue/cpython/Lib/test/test_time.py", line 522, in test_thread_time
    self.assertLess(stop - start, 0.020)
AssertionError: 0.10999999999999999 not less than 0.02

----------------------------------------------------------------------
Ran 1 test in 0.109s

FAILED (failures=1)
test test_time failed
test_time failed (1 failure)

== Tests result: FAILURE ==

vstinner · 2024-09-13T21:24:55Z

I suggest to skip test_thread_time() on NetBSD with a refererence to this issue.

serhiy-storchaka · 2024-09-16T09:13:53Z

From the discussion on #123979, it seems that CLOCK_THREAD_CPUTIME_ID does not work as intended on NetBSD. The following example:

import time
names = ['time', 'monotonic', 'process_time', 'thread_time']
funcs = [getattr(time, name) for name in names]
times = [f() for f in funcs]
time.sleep(10)
for name, f, t in zip(names, funcs, times):
    print(name, f() - t)

produces the following output:

time 10.000223636627197
monotonic 10.000407570973039
process_time 0.00038799999999999946
thread_time 10.0

It is expected time.thread_time() returning the result close to time.process_time() on single-thread program, not close to time.time() or time.monotonic(). The result includes the sleeping time, which should not be accounted.

And this issue is known to the NetBSD developers: https://gnats.netbsd.org/57512.

We should either skip thread_time related tests on NetBSD and leave it to the users to deal with this issue, or remove the broken time.thread_time() on NetBSD. Not all clocks are supported on all platforms, so the latter should be more expected. Unfortunately we do not know when they fix this in NetBSD and how to detect that it is fixed (besides checking the OS version number which is still not known).

There was similar issue on Solaris and Illumos (see #79636, https://www.illumos.org/issues/14126). Even if CLOCK_THREAD_CPUTIME_ID was provided in headers, clock_gettime() returned EINVAL. Unfortunately, there is no gethrvtime() or other replacement on NetBSD.

serhiy-storchaka · 2024-09-18T06:25:27Z

It puzzled me why time.process_time() is not broken in the same way. It uses the getrusage(RUSAGE_SELF) implementation. It turned out that while the clock_gettime(CLOCK_PROCESS_CPUTIME_ID) implementation has higher priority, the clock_gettime(CLOCK_PROF) implementation has even higher priority if CLOCK_PROF is defined.

CLOCK_PROF is defined on NetBSD, but not supported, so clock_gettime(CLOCK_PROF) always fails and the code falls back to getrusage(RUSAGE_SELF). We are lucky that two errors cancel one other. But it is better to explicitly disable using CLOCK_PROCESS_CPUTIME_ID on NetBSD, until they fix it.

There is also an error in conditions for the clock_gettime(CLOCK_THREAD_CPUTIME_ID) implementation: CLOCK_PROCESS_CPUTIME_ID is used instead of CLOCK_THREAD_CPUTIME_ID. Although they are usually defined in pair, so this does not cause any practical issue.

…-124116) (cherry picked from commit e670a11) Co-authored-by: Serhiy Storchaka <[email protected]>

…ythonGH-124116) (cherry picked from commit e670a11) Co-authored-by: Serhiy Storchaka <[email protected]>

Sep 30, 2024 · 2024-09-30T21:15:51Z

I think we should skip the test instead of disabling the functionality altogether. It's a platform bug that the underlying APIs don't behave as expected, and it shouldn't make our tests fail, but we don't have control over the platform. The platform could be fixed and then any older releases of Python would still refuse those APIs. (FWIW, Greg was in contact with a NetBSD friend who thought it would be fixed soon.)

Maybe if we had configure-time checks of the functionality it would make sense to skip them, but that seems like a lot of work for this. Let's skip the test and leave it at that.

…) (GH-124427) (cherry picked from commit e670a11)

serhiy-storchaka · 2024-10-03T09:30:42Z

I think that it is safer to not provide a function than provide a function which returns a wrong result and there is no way to easy detect that it is broken. It is broken not only because the result includes the sleeping time, -- according to the NetBSD issue, this timer can go backward. The discussion stopped a year ago, so it is unlikely it will be solved soon.

@gpshead merged the backport to 3.12, and it is now included in 3.12.7. Should we revert this change or accept the backport to 3.13?

vstinner · 2024-10-03T10:09:45Z

I agree with @serhiy-storchaka, that's why I approved his PRs. It's a silly situation, but it's better to not add the function to Python, rather than just skipping tests.

…) (GH-124425) (cherry picked from commit e670a11) Co-authored-by: Serhiy Storchaka <[email protected]>

furkanonder added type-bug An unexpected behavior, bug, or error tests Tests in the Lib/test dir 3.12 bugs and security fixes 3.13 bugs and security fixes 3.14 new features, bugs and security fixes labels Sep 11, 2024

bedevere-app bot mentioned this issue Sep 11, 2024

gh-123978: Fix test_thread_time failure on NetBSD by adjusting threshold for time difference #123979

Closed

vstinner mentioned this issue Sep 13, 2024

OSError: Invalid argument in test_get_clock_info when testing thread_time clock on NetBSD #123974

Closed

serhiy-storchaka added a commit to serhiy-storchaka/cpython that referenced this issue Sep 16, 2024

pythongh-123978: Remove broken time.thread_time() on NetBSD

86fd156

This was referenced Sep 16, 2024

gh-123978: Remove broken time.thread_time() on NetBSD #124116

Merged

gh-123978: Remove support for thread_time and thread_time_ns in NetBSD #124196

Closed

serhiy-storchaka added a commit that referenced this issue Sep 24, 2024

gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116)

e670a11

miss-islington pushed a commit to miss-islington/cpython that referenced this issue Sep 24, 2024

pythongh-123978: Remove broken time.thread_time() on NetBSD (pythonGH…

17b4b0f

…-124116) (cherry picked from commit e670a11) Co-authored-by: Serhiy Storchaka <[email protected]>

bedevere-app bot mentioned this issue Sep 24, 2024

[3.13] gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116) #124425

Merged

serhiy-storchaka added a commit to serhiy-storchaka/cpython that referenced this issue Sep 24, 2024

[3.12] pythongh-123978: Remove broken time.thread_time() on NetBSD (p…

b736ab6

…ythonGH-124116) (cherry picked from commit e670a11) Co-authored-by: Serhiy Storchaka <[email protected]>

bedevere-app bot mentioned this issue Sep 24, 2024

[3.12] gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116) #124427

Merged

serhiy-storchaka self-assigned this Sep 26, 2024

gpshead pushed a commit that referenced this issue Oct 2, 2024

[3.12] gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116…

829cdf0

…) (GH-124427) (cherry picked from commit e670a11)

serhiy-storchaka added a commit that referenced this issue Oct 23, 2024

[3.13] gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116…

77d7998

…) (GH-124425) (cherry picked from commit e670a11) Co-authored-by: Serhiy Storchaka <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test_thread_time fails on NetBSD: time difference exceeds expected threshold #123978

test_thread_time fails on NetBSD: time difference exceeds expected threshold #123978

furkanonder commented Sep 11, 2024 •

edited by bedevere-app bot

Loading

furkanonder commented Sep 11, 2024

vstinner commented Sep 13, 2024

serhiy-storchaka commented Sep 16, 2024

serhiy-storchaka commented Sep 18, 2024

Sep 30, 2024

serhiy-storchaka commented Oct 3, 2024

vstinner commented Oct 3, 2024

test_thread_time fails on NetBSD: time difference exceeds expected threshold #123978

test_thread_time fails on NetBSD: time difference exceeds expected threshold #123978

Comments

furkanonder commented Sep 11, 2024 • edited by bedevere-app bot Loading

Bug report

Bug description:

CPython versions tested on:

Operating systems tested on:

Linked PRs

furkanonder commented Sep 11, 2024

vstinner commented Sep 13, 2024

serhiy-storchaka commented Sep 16, 2024

serhiy-storchaka commented Sep 18, 2024

Sep 30, 2024

serhiy-storchaka commented Oct 3, 2024

vstinner commented Oct 3, 2024

furkanonder commented Sep 11, 2024 •

edited by bedevere-app bot

Loading