From 929c5693fcf8f3b1c338c06df3348bf281140518 Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 18 Oct 2026 19:17:23 +0000 Subject: [PATCH 1/4] Build CallInfo timing from a single timing.Duration Add CallInfo._from_duration() so internal construction sites take their start/stop/duration from one _pytest.timing.Duration instead of passing three loose floats. from_call, subtests and unittest subtests now all go through it. Subtests measured time with time.time()/time.perf_counter() directly, so a test mocking time under subtests.test() produced negative or bogus durations (#15201, same class of bug as #185). unittest subtests reported start=stop=0 (the epoch); they now report a zero-length call at the current time. Fixes #15201. Co-Authored-By: Claude Opus 5.5 (1M context) --- changelog/15201.bugfix.rst | 3 +++ src/_pytest/runner.py | 29 ++++++++++++++++++--- src/_pytest/subtests.py | 20 +++++---------- src/_pytest/unittest.py | 15 ++++++----- testing/test_subtests.py | 52 ++++++++++++++++++++++++++++++++++++++ 5 files changed, 95 insertions(+), 24 deletions(-) create mode 100644 changelog/15201.bugfix.rst diff --git a/changelog/15201.bugfix.rst b/changelog/15201.bugfix.rst new file mode 100644 index 00000000000..aa2529e0d4c --- /dev/null +++ b/changelog/15201.bugfix.rst @@ -0,0 +1,3 @@ +Subtest timing (start, stop and duration) no longer breaks when the test under ``subtests.test()`` mocks :func:`time.time` or :func:`time.perf_counter`; it now uses pytest's internal timing like regular test phases do. + +``unittest`` subtests are now reported with their real timestamp and a duration of zero, instead of a start and stop time of ``0`` (the epoch). diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 27c5739845a..35a597f0ead 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -364,14 +364,37 @@ def from_call( if reraise is not None and isinstance(excinfo.value, reraise): raise result = None - duration = instant.elapsed() + return cls._from_duration( + result=result, + excinfo=excinfo, + duration=instant.elapsed(), + when=when, + ) + + @classmethod + def _from_duration( + cls, + result: TResult | None, + excinfo: ExceptionInfo[BaseException] | None, + duration: timing.Duration, + when: Literal["collect", "setup", "call", "teardown"], + ) -> CallInfo[TResult]: + """Create a CallInfo whose timing comes from a single + :class:`_pytest.timing.Duration`. + + Internal code should construct CallInfo through this (or + :meth:`from_call`) instead of passing ``start``/``stop``/``duration`` + by hand, so all three always come from the same measurement and from + :mod:`_pytest.timing`, which is immune to tests mocking :mod:`time` + (#185). + """ return cls( + result=result, + excinfo=excinfo, start=duration.start.time, stop=duration.stop.time, duration=duration.seconds, when=when, - result=result, - excinfo=excinfo, _ispytest=True, ) diff --git a/src/_pytest/subtests.py b/src/_pytest/subtests.py index 0c66e289a4d..dcb2a4d7ab3 100644 --- a/src/_pytest/subtests.py +++ b/src/_pytest/subtests.py @@ -11,13 +11,13 @@ from contextlib import ExitStack from contextlib import nullcontext import dataclasses -import time from types import TracebackType from typing import Any from typing import TYPE_CHECKING import pluggy +from _pytest import timing from _pytest._code import ExceptionInfo from _pytest._io.saferepr import saferepr from _pytest.capture import CaptureFixture @@ -216,8 +216,7 @@ class _SubTestContextManager: def __enter__(self) -> None: __tracebackhide__ = True - self._start = time.time() - self._precise_start = time.perf_counter() + self._start = timing.Instant() self._exc_info = None self._exit_stack = ExitStack() @@ -242,18 +241,11 @@ def __exit__( self._exit_stack.close() - precise_stop = time.perf_counter() - duration = precise_stop - self._precise_start - stop = time.time() - - call_info = CallInfo[None]( - None, - exc_info, - start=self._start, - stop=stop, - duration=duration, + call_info = CallInfo[None]._from_duration( + result=None, + excinfo=exc_info, + duration=self._start.elapsed(), when="call", - _ispytest=True, ) report = self.ihook.pytest_runtest_makereport( item=self.request.node, call=call_info diff --git a/src/_pytest/unittest.py b/src/_pytest/unittest.py index 2c9e0dcb80b..2bd0095f608 100644 --- a/src/_pytest/unittest.py +++ b/src/_pytest/unittest.py @@ -18,6 +18,7 @@ from unittest import TestCase from _pytest import fixtures +from _pytest import timing import _pytest._code from _pytest._code import ExceptionInfo from _pytest.compat import assert_never @@ -441,14 +442,14 @@ def addSubTest( case unreachable: assert_never(unreachable) - call_info = CallInfo[None]( - None, - exception_info, - start=0, - stop=0, - duration=0, + # unittest does not tell us when a subtest started, so report it as a + # zero-length call at the time unittest notified us about it. + now = timing.Instant() + call_info = CallInfo[None]._from_duration( + result=None, + excinfo=exception_info, + duration=timing.Duration(start=now, stop=now), when="call", - _ispytest=True, ) msg = None if test._message is _subtest_msg_sentinel else str(test._message) # type: ignore[attr-defined] report = self.ihook.pytest_runtest_makereport(item=self, call=call_info) diff --git a/testing/test_subtests.py b/testing/test_subtests.py index a64897c6fc3..a331d1227b2 100644 --- a/testing/test_subtests.py +++ b/testing/test_subtests.py @@ -1040,6 +1040,58 @@ def test(subtests): ) +def test_timing_unaffected_by_mocked_time(pytester: pytest.Pytester) -> None: + """Subtest timing uses _pytest.timing, so tests mocking ``time`` do not + corrupt the reported start/stop/duration (#15201, #185).""" + reprec = pytester.inline_runsource( + """ + import time + + def test(subtests, monkeypatch): + with subtests.test("mocked"): + monkeypatch.setattr(time, "time", lambda: 0.0) + monkeypatch.setattr(time, "perf_counter", lambda: -1e9) + """ + ) + reports = [ + r + for r in reprec.getreports("pytest_runtest_logreport") + if isinstance(r, SubtestReport) + ] + assert len(reports) == 1 + [report] = reports + assert report.passed + assert report.start > 0 + assert report.duration >= 0 + assert report.stop - report.start == pytest.approx(report.duration, abs=1) + + +def test_unittest_subtest_timing(pytester: pytest.Pytester) -> None: + """Unittest does not tell us when a subtest started: it is reported as a + zero-length call at a real timestamp instead of at the epoch.""" + reprec = pytester.inline_runsource( + """ + from unittest import TestCase + + class T(TestCase): + def test(self): + with self.subTest("a"): + assert False + """ + ) + reports = [ + r + for r in reprec.getreports("pytest_runtest_logreport") + if isinstance(r, SubtestReport) + ] + assert len(reports) == 1 + [report] = reports + assert report.failed + assert report.start > 0 + assert report.stop == report.start + assert report.duration == 0 + + class MyEnum(Enum): """Used in test_serialization, needs to be declared at the module level to be pickled.""" From f64a2379dbb1c6727789a9d06a736931ee6ea5e1 Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 18 Oct 2026 19:28:55 +0000 Subject: [PATCH 2/4] Store a timing.Duration in CallInfo CallInfo now keeps the measured timing.Duration and exposes start, stop and duration as properties derived from it, instead of three loose floats that could disagree. External code still constructs CallInfo from floats (pytest-subtests, pytest-asyncio-concurrent) and assigns the timing attributes (pytest-asyncio-cooperative, pytest-velo), so the float constructor and the attribute setters keep working on top of the stored Duration. timing.Instant fields become init-able to support that. Co-Authored-By: Claude Opus 5.5 (1M context) --- src/_pytest/runner.py | 102 ++++++++++++++++++++++++++--------------- src/_pytest/timing.py | 4 +- testing/test_runner.py | 23 ++++++++++ 3 files changed, 91 insertions(+), 38 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index 35a597f0ead..baa56e685d5 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -296,12 +296,8 @@ class CallInfo(Generic[TResult]): _result: TResult | None #: The captured exception of the call, if it raised. excinfo: ExceptionInfo[BaseException] | None - #: The system time when the call started, in seconds since the epoch. - start: float - #: The system time when the call ended, in seconds since the epoch. - stop: float - #: The call duration, in seconds. - duration: float + # The timing of the call; ``start``, ``stop`` and ``duration`` are views on it. + _duration: timing.Duration #: The context of invocation: "collect", "setup", "call" or "teardown". when: Literal["collect", "setup", "call", "teardown"] @@ -319,11 +315,72 @@ def __init__( check_ispytest(_ispytest) self._result = result self.excinfo = excinfo - self.start = start - self.stop = stop - self.duration = duration + # Kept for plugins which construct CallInfo from plain floats; pytest + # itself uses _from_duration(). + self._duration = timing.Duration( + start=timing.Instant(time=start, perf_count=0.0), + stop=timing.Instant(time=stop, perf_count=duration), + ) self.when = when + @classmethod + def _from_duration( + cls, + result: TResult | None, + excinfo: ExceptionInfo[BaseException] | None, + duration: timing.Duration, + when: Literal["collect", "setup", "call", "teardown"], + ) -> CallInfo[TResult]: + """Create a CallInfo timed by a :class:`_pytest.timing.Duration`. + + Internal code should construct CallInfo through this (or + :meth:`from_call`), measuring with :class:`_pytest.timing.Instant`, + which is immune to tests mocking :mod:`time` (#185). + """ + call = cls( + result, + excinfo, + duration.start.time, + duration.stop.time, + duration.seconds, + when, + _ispytest=True, + ) + call._duration = duration + return call + + @property + def start(self) -> float: + """The system time when the call started, in seconds since the epoch.""" + return self._duration.start.time + + @start.setter + def start(self, value: float) -> None: + start = dataclasses.replace(self._duration.start, time=value) + self._duration = dataclasses.replace(self._duration, start=start) + + @property + def stop(self) -> float: + """The system time when the call ended, in seconds since the epoch.""" + return self._duration.stop.time + + @stop.setter + def stop(self, value: float) -> None: + stop = dataclasses.replace(self._duration.stop, time=value) + self._duration = dataclasses.replace(self._duration, stop=stop) + + @property + def duration(self) -> float: + """The call duration, in seconds.""" + return self._duration.seconds + + @duration.setter + def duration(self, value: float) -> None: + stop = dataclasses.replace( + self._duration.stop, perf_count=self._duration.start.perf_count + value + ) + self._duration = dataclasses.replace(self._duration, stop=stop) + @property def result(self) -> TResult: """The return value of the call, if it didn't raise. @@ -371,33 +428,6 @@ def from_call( when=when, ) - @classmethod - def _from_duration( - cls, - result: TResult | None, - excinfo: ExceptionInfo[BaseException] | None, - duration: timing.Duration, - when: Literal["collect", "setup", "call", "teardown"], - ) -> CallInfo[TResult]: - """Create a CallInfo whose timing comes from a single - :class:`_pytest.timing.Duration`. - - Internal code should construct CallInfo through this (or - :meth:`from_call`) instead of passing ``start``/``stop``/``duration`` - by hand, so all three always come from the same measurement and from - :mod:`_pytest.timing`, which is immune to tests mocking :mod:`time` - (#185). - """ - return cls( - result=result, - excinfo=excinfo, - start=duration.start.time, - stop=duration.stop.time, - duration=duration.seconds, - when=when, - _ispytest=True, - ) - def __repr__(self) -> str: if self.excinfo is None: return f"" diff --git a/src/_pytest/timing.py b/src/_pytest/timing.py index 639bd99bd3e..1f70f9b1757 100644 --- a/src/_pytest/timing.py +++ b/src/_pytest/timing.py @@ -32,14 +32,14 @@ class Instant: # Creation time of this instant, using time.time(), to measure actual time. # Note: using a `lambda` to correctly get the mocked time via `MockTiming`. + # Only pass explicitly to represent timings given as plain floats. # pylint: disable-next=lambda-assignment - time: float = dataclasses.field(default_factory=lambda: time(), init=False) # noqa: PLW0108 + time: float = dataclasses.field(default_factory=lambda: time()) # noqa: PLW0108 # Performance counter tick of the instant, used to measure precise elapsed time. # Note: using a `lambda` to correctly get the mocked time via `MockTiming`. perf_count: float = dataclasses.field( default_factory=lambda: perf_counter(), # noqa: PLW0108 - init=False, ) def elapsed(self) -> Duration: diff --git a/testing/test_runner.py b/testing/test_runner.py index b5c3839c79e..5c4172ecd3c 100644 --- a/testing/test_runner.py +++ b/testing/test_runner.py @@ -12,6 +12,7 @@ from _pytest import outcomes from _pytest import reports from _pytest import runner +from _pytest import timing from _pytest._code import ExceptionInfo from _pytest._code.code import ExceptionChainRepr from _pytest.config import ExitCode @@ -597,6 +598,28 @@ def raise_assertion(): assert "\n" not in repr(ci3) +def test_callinfo_timing_from_duration(mock_timing) -> None: + instant = timing.Instant() + timing.sleep(3) + duration = instant.elapsed() + ci = runner.CallInfo[None]._from_duration(None, None, duration, "call") + assert ci.start == duration.start.time + assert ci.stop == duration.stop.time + assert ci.duration == duration.seconds == 3 + + +def test_callinfo_timing_from_floats() -> None: + """Plugins construct CallInfo from plain floats and assign the timing + attributes; both keep working on top of the stored Duration.""" + ci = runner.CallInfo[None](None, None, 10.0, 15.0, 4.5, "call", _ispytest=True) + assert (ci.start, ci.stop, ci.duration) == (10.0, 15.0, 4.5) + + ci.start = 20.0 + ci.stop = 30.0 + ci.duration = 9.5 + assert (ci.start, ci.stop, ci.duration) == (20.0, 30.0, 9.5) + + # design question: do we want general hooks in python files? # then something like the following functional tests makes sense From 52c3793b697e39508f9ed672aa3c35bc3e623802 Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 18 Oct 2026 19:56:46 +0000 Subject: [PATCH 3/4] Name the unittest subtest placeholder timing timing.UNMEASURED unittest reports subtests after the fact without timing. Keep the start=stop=duration=0 values inherited from pytest-subtests, but spell them as a named timing.UNMEASURED Duration instead of literal zeros. Co-Authored-By: Claude Opus 5.5 (1M context) --- changelog/15201.bugfix.rst | 2 -- src/_pytest/timing.py | 9 +++++++++ src/_pytest/unittest.py | 6 ++---- testing/test_subtests.py | 10 +++++----- 4 files changed, 16 insertions(+), 11 deletions(-) diff --git a/changelog/15201.bugfix.rst b/changelog/15201.bugfix.rst index aa2529e0d4c..758a3522149 100644 --- a/changelog/15201.bugfix.rst +++ b/changelog/15201.bugfix.rst @@ -1,3 +1 @@ Subtest timing (start, stop and duration) no longer breaks when the test under ``subtests.test()`` mocks :func:`time.time` or :func:`time.perf_counter`; it now uses pytest's internal timing like regular test phases do. - -``unittest`` subtests are now reported with their real timestamp and a duration of zero, instead of a start and stop time of ``0`` (the epoch). diff --git a/src/_pytest/timing.py b/src/_pytest/timing.py index 1f70f9b1757..15e16819866 100644 --- a/src/_pytest/timing.py +++ b/src/_pytest/timing.py @@ -64,6 +64,15 @@ def seconds(self) -> float: return self.stop.perf_count - self.start.perf_count +#: Placeholder timing for calls pytest cannot measure, e.g. unittest subtests, +#: which unittest reports only after the fact without a start time. +#: Shows up as ``start == stop == duration == 0``. +UNMEASURED = Duration( + start=Instant(time=0.0, perf_count=0.0), + stop=Instant(time=0.0, perf_count=0.0), +) + + @dataclasses.dataclass class MockTiming: """Mocks _pytest.timing with a known object that can be used to control timing in tests diff --git a/src/_pytest/unittest.py b/src/_pytest/unittest.py index 2bd0095f608..a7c65d2856f 100644 --- a/src/_pytest/unittest.py +++ b/src/_pytest/unittest.py @@ -442,13 +442,11 @@ def addSubTest( case unreachable: assert_never(unreachable) - # unittest does not tell us when a subtest started, so report it as a - # zero-length call at the time unittest notified us about it. - now = timing.Instant() + # unittest reports subtests after the fact, without timing. call_info = CallInfo[None]._from_duration( result=None, excinfo=exception_info, - duration=timing.Duration(start=now, stop=now), + duration=timing.UNMEASURED, when="call", ) msg = None if test._message is _subtest_msg_sentinel else str(test._message) # type: ignore[attr-defined] diff --git a/testing/test_subtests.py b/testing/test_subtests.py index a331d1227b2..8ee05320831 100644 --- a/testing/test_subtests.py +++ b/testing/test_subtests.py @@ -5,6 +5,7 @@ import sys from typing import Literal +from _pytest import timing from _pytest._io.saferepr import saferepr from _pytest.subtests import SubtestContext from _pytest.subtests import SubtestReport @@ -1067,8 +1068,7 @@ def test(subtests, monkeypatch): def test_unittest_subtest_timing(pytester: pytest.Pytester) -> None: - """Unittest does not tell us when a subtest started: it is reported as a - zero-length call at a real timestamp instead of at the epoch.""" + """Unittest reports subtests without timing: they carry timing.UNMEASURED.""" reprec = pytester.inline_runsource( """ from unittest import TestCase @@ -1087,9 +1087,9 @@ def test(self): assert len(reports) == 1 [report] = reports assert report.failed - assert report.start > 0 - assert report.stop == report.start - assert report.duration == 0 + assert report.start == timing.UNMEASURED.start.time + assert report.stop == timing.UNMEASURED.stop.time + assert report.duration == timing.UNMEASURED.seconds class MyEnum(Enum): From 2f112eec242ba1d0e7eefca9a516565047b6404b Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 19 Oct 2026 18:42:57 +0000 Subject: [PATCH 4/4] Construct CallInfo._from_duration via __new__ Store the Duration directly instead of splitting it into floats for __init__ and then overwriting the rebuilt Duration. __init__ remains only as the legacy float entry point. Co-Authored-By: Claude Opus 5.5 (1M context) --- src/_pytest/runner.py | 14 +++++--------- 1 file changed, 5 insertions(+), 9 deletions(-) diff --git a/src/_pytest/runner.py b/src/_pytest/runner.py index baa56e685d5..23a1543bf50 100644 --- a/src/_pytest/runner.py +++ b/src/_pytest/runner.py @@ -337,16 +337,12 @@ def _from_duration( :meth:`from_call`), measuring with :class:`_pytest.timing.Instant`, which is immune to tests mocking :mod:`time` (#185). """ - call = cls( - result, - excinfo, - duration.start.time, - duration.stop.time, - duration.seconds, - when, - _ispytest=True, - ) + # Bypass __init__, which only exists to accept the legacy floats. + call = cls.__new__(cls) + call._result = result + call.excinfo = excinfo call._duration = duration + call.when = when return call @property