Skip to content

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

Open
RonnyPfannschmidt wants to merge 4 commits into
mainfrom
claude/callinfo-duration-8dkzw2
Open

RonnyPfannschmidt wants to merge 4 commits into
mainfrom
claude/callinfo-duration-8dkzw2

Conversation

@RonnyPfannschmidt

@RonnyPfannschmidt RonnyPfannschmidt commented Oct 18, 2026 •

Copy link
Copy Markdown
Member

Requested by Ronny · project thread

🤖 Written by Claude Opus 5.5 via Claude Code for the pytest maintainers; I prompted it, it did the work, I read it.

Closes #15201. Supersedes #15204.

Before: CallInfo stores start, stop and duration as three independent floats, and its three construction sites fill them differently. from_call uses timing.Instant. subtests.test() calls time.time()/time.perf_counter() directly, so a test that mocks time inside a subtest gets negative or bogus durations (the #185 class of bug). unittest subTest passes literal start=stop=duration=0.

After: CallInfo stores one private timing.Duration, and start/stop/duration are properties derived from it. All internal construction goes through CallInfo._from_duration(result, excinfo, duration, when). The pattern for any new site is to take a timing.Instant() when the phase begins and pass instant.elapsed(). Where there is nothing to measure, the site passes the named timing.UNMEASURED placeholder (all zeros). unittest subtests are the one such site: unittest reports them after the fact, without timing. Their reported values are unchanged from main; the zeros, inherited from pytest-subtests in #13738, are now just named.

Backward compatibility: external code still uses the float API, so it is kept.

  • The float constructor CallInfo(result, excinfo, start, stop, duration, when, _ispytest=True) is used by pytest-subtests (still widely installed, plus Debian/deepin packaging), pytest-asyncio-concurrent and NVIDIA's isvtest. It now builds the Duration from the floats.
  • Attribute assignment (call.start = ..., call.stop = ..., call.duration = ...) is used by pytest-asyncio-cooperative and pytest-velo. Setters update the stored Duration independently, so each field keeps its old meaning.
  • timing.Instant fields become init-able (still defaulting to "now") so a Duration can represent externally supplied floats.

Visible change: dataclasses.fields(CallInfo) now lists _duration instead of start/stop/duration, and == compares the stored Duration.

Tests: a subtest regression test for mocked time (fails on main), a unittest subtest test asserting timing.UNMEASURED, and test_runner.py coverage for _from_duration and for the float constructor and setters.

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) <noreply@anthropic.com>
@pyba-chronographer pyba-chronographer Bot added the bot:chronographer:provided (automation) changelog entry is part of PR label Oct 18, 2026
@RonnyPfannschmidt RonnyPfannschmidt self-assigned this Oct 18, 2026
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) <noreply@anthropic.com>
@RonnyPfannschmidt RonnyPfannschmidt changed the title Build CallInfo timing from a single timing.Duration CallInfo: store a timing.Duration, keep start/stop/duration as aliases Oct 18, 2026
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) <noreply@anthropic.com>
@RonnyPfannschmidt
RonnyPfannschmidt marked this pull request as ready for review October 18, 2026 20:13
@RonnyPfannschmidt
RonnyPfannschmidt requested review from bluetech and nicoddemus and removed request for bluetech October 18, 2026 20:13
@PersuasivePost

Copy link
Copy Markdown

I reported #15201 and tested this branch (claude/callinfo-duration-8dkzw2) against my original reproducer, which patches time.time and time.perf_counter to lambda: 0.0 inside the test and inside a subtest, and sleeps 0.3s.

main @ 420cf37: test_with_subtest reported −1194.217s
this PR: test_with_subtest reports 0.606s (test_normal: 0.301s)

The negative duration is gone. Thanks for the quick fix.

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) <noreply@anthropic.com>

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bot:chronographer:provided (automation) changelog entry is part of PR

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Subtest durations become negative when time is mocked (subtests.py bypasses _pytest.timing)

3 participants