Repository navigation
Subtest durations become negative when time is mocked (subtests.py bypasses _pytest.timing) #15201
Description
- a detailed description of the bug or problem you are having
- output of
pip listfrom the virtual environment you are using - pytest and operating system versions
- minimal example if possible
Description
When a test mocks time.perf_counter / time.time (as clock-mocking libraries like freezegun and time-machine do), subtests report negative durations and a stop timestamp of 0.0 (January 1, 1970). Normal tests are unaffected by the same mocking.
Reproducer
# test_repro.py
import time
def test_normal(monkeypatch):
real_sleep = time.sleep
monkeypatch.setattr(time, "perf_counter", lambda: 0.0)
monkeypatch.setattr(time, "time", lambda: 0.0)
real_sleep(0.3)
def test_with_subtest(subtests, monkeypatch):
real_sleep = time.sleep
with subtests.test(msg="frozen clock"):
monkeypatch.setattr(time, "perf_counter", lambda: 0.0)
monkeypatch.setattr(time, "time", lambda: 0.0)
real_sleep(0.3)$ pytest -q --junitxml=out.xml
.u. [100%]
2 passed, 1 subtests passed in 1.23s
$ grep -o 'name="[^"]*" time="[^"]*"' out.xml
name="test_normal" time="0.301"
name="test_with_subtest" time="-1194.217"
Both tests sleep 0.3s under a mocked clock. The normal test reports 0.301s; the subtest reports −1194s (the exact value depends on the machine's uptime).
Cause
Normal test execution and subtests handle timing differently.
In src/_pytest/runner.py, pytest uses timing.Instant() and instant.elapsed() from _pytest.timing. However, src/_pytest/subtests.py imports the time module directly and calls time.time() and time.perf_counter():
$ grep -n "time\." src/_pytest/subtests.py
219: self._start = time.time()
220: self._precise_start = time.perf_counter()
245: precise_stop = time.perf_counter()
247: stop = time.time()
_pytest.timing imports perf_counter directly using from time import perf_counter, so it keeps its original function reference even if time.perf_counter is patched later. subtests.py looks up the function on the time module whenever it is called, so it picks up the patched value.
So if a subtest starts on the real clock and the test then patches time.perf_counter to return 0.0, the subtest computes its duration from the real start time and the patched end time, giving a negative duration. The same happens with time.time(), giving a stop timestamp of 0.0.
This is the situation _pytest.timing exists to prevent. Its docstring says pytest grabs time functions internally "to avoid tests mocking "time" to affect pytest runtime information (issue #185)", and #7764 covered the freezegun case for --durations. The subtests module, merged later, doesn't follow that rule.
Proposed fix
Switch subtests.py to timing.Instant() / .elapsed(), matching runner.py. If this approach sounds right, I'd be happy to send a PR with a regression test.
Related
#14412 (fixed in #14670) addressed how subtest timings are aggregated in the terminal with console_output_style='times'. This is a separate problem: the timing values themselves are wrong when time is mocked, and it still reproduces on main after #14670.
Environment
- pytest
9.2.0.dev388+g420cf37a3(main, editable install) - Python 3.10.12
- Ubuntu 22.04.5 LTS
pip list
Package Version
------------------ -----------------------
argcomplete 3.6.3
asynctest 0.13.0
attrs 25.4.0
certifi 2026.1.4
charset-normalizer 3.4.4
coverage 7.13.1
elementpath 5.1.0
exceptiongroup 1.3.1
execnet 2.1.2
hypothesis 6.150.0
idna 3.11
iniconfig 2.3.0
mock 5.2.0
numpy 2.2.6
packaging 25.0
pexpect 4.9.0
pluggy 1.6.0
ptyprocess 0.7.0
pygments 2.19.2
pytest 9.2.0.dev388+g420cf37a3
pytest-xdist 3.8.0
pyyaml 6.0.3
requests 2.32.5
setuptools 80.9.0
sortedcontainers 2.4.0
tomli 2.3.0
typing-extensions 4.15.0
urllib3 2.6.3
xmlschema 4.3.0
Activity