test_thread_time fails on NetBSD: time difference exceeds expected threshold

[furkanonder]

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

• gh-123978: Fix test_thread_time failure on NetBSD by adjusting threshold for time difference #123979
• gh-123978: Remove broken time.thread_time() on NetBSD #124116
• gh-123978: Remove support for thread_time and thread_time_ns in NetBSD #124196
• [3.13] gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116) #124425
• [3.12] gh-123978: Remove broken time.thread_time() on NetBSD (GH-124116) #124427

[furkanonder]

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]

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

[serhiy-storchaka]

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]

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.