CallInfo: store a timing.Duration, keep start/stop/duration as aliases

changelog/15201.bugfix.rst

@@ -0,0 +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.

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,68 @@ 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).
+        """
+        # 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
+    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.
@@ -364,15 +417,11 @@ def from_call(
             if reraise is not None and isinstance(excinfo.value, reraise):
                 raise
             result = None
-        duration = instant.elapsed()
-        return cls(
-            start=duration.start.time,
-            stop=duration.stop.time,
-            duration=duration.seconds,
-            when=when,
+        return cls._from_duration(
             result=result,
             excinfo=excinfo,
-            _ispytest=True,
+            duration=instant.elapsed(),
+            when=when,
         )
 
     def __repr__(self) -> str:

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

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:
@@ -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

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,12 @@ def addSubTest(
             case unreachable:
                 assert_never(unreachable)
 
-        call_info = CallInfo[None](
-            None,
-            exception_info,
-            start=0,
-            stop=0,
-            duration=0,
+        # unittest reports subtests after the fact, without timing.
+        call_info = CallInfo[None]._from_duration(
+            result=None,
+            excinfo=exception_info,
+            duration=timing.UNMEASURED,
             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)

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
 

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
@@ -1040,6 +1041,57 @@ 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 reports subtests without timing: they carry timing.UNMEASURED."""
+    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 == timing.UNMEASURED.start.time
+    assert report.stop == timing.UNMEASURED.stop.time
+    assert report.duration == timing.UNMEASURED.seconds
+
+
 class MyEnum(Enum):
     """Used in test_serialization, needs to be declared at the module level to be pickled."""