Skip to content

feat(timing): book each turn's head and tail as their own buckets - #165

Open
uipreliga wants to merge 11 commits into
fix/timing-capture-and-reportingfrom
feat/turn-head-tail-timing
Open

feat(timing): book each turn's head and tail as their own buckets#165
uipreliga wants to merge 11 commits into
fix/timing-capture-and-reportingfrom
feat/turn-head-tail-timing

Conversation

@uipreliga

@uipreliga uipreliga commented Sep 11, 2026

Copy link
Copy Markdown
Collaborator

Stacked on #164 — base is fix/timing-capture-and-reporting, whose tiling fixes are prerequisites. GitHub will retarget this to main automatically when #164 merges. Review the 11 commits here, not the 21 against main.

What and why

A turn's wall clock was only partly explained. Generation windows and tool execution were measured; the turn's head (turn start → first generation window opens) and tail (last window closes → turn end) were not, so they surfaced as Unaccounted in the evalboard. On OpenCode that was ~2.5 s per turn of CLI boot reported as unexplained time.

Both are now booked as optional TurnRecord fields, computed once at the EventCollector seam.

The head's composition genuinely differs per harness and is deliberately not decomposed. On an in-process SDK the first window already covers dispatch and TTFT, so it reads 0.0; on a subprocess harness it fuses CLI boot, provider resolution, dispatch and TTFT with no marker between them (measured on OpenCode: the process spawns in ~3 ms, its first event lands at ~3.9 s). The fields are named for the interval they measure, never for what they contain — docs/agents/HARNESS_PARITY.md records the per-harness composition.

The invariant

None means never measured; 0.0 means measured and instant. These stay distinguishable end to end, Python model → task.json → TypeScript → rendered cell ( vs 0ms). CE058 is widened to cover both new names and the TurnRecord constructor.

The identity, and the three defects that closed it

Σ generation + ∪ tool + head + tail ≈ duration_seconds. Each of these was found by measurement, not by reading:

  1. The tool term must be the union, not the sum. One Pi turn overlapped a Write and a Bash by 18.4 ms and produced exactly an 18.3 ms residual.
  2. The four buckets were not disjoint. Generation windows are tool-subtracted; the head and tail were not. A tool escaping every window — Antigravity force-closes an orphan at finalization, inside the tail — was counted twice. On the committed antigravity_d_orphaned_tool fixture that is −86% of wall clock, with all 72 golden tests passing.
  3. claude-code did not subtract tool time from its generation windows at all. It was exempt on the premise that a tool's execution falls between two windows — but a tool's timer starts at the emission carrying its tool_use block, and one assistant turn spans several emissions, so a later emission's window runs concurrently with a tool already timing. Measured at 482 ms and 340 ms of double-count on two ~18–25 s turns. It cannot subtract while flushing (a tool from an earlier emission is still running when the next window closes), so _subtract_tool_time_from_windows runs once at finalization.

Also fixed: placeholder now() stamps (rollout rebuild, sub-agent recovery, synthesized terminal — all of which declare generation_duration_ms=None) were read as window bounds, so a Codex turn rebuilt from its rollout booked the entire turn as startup; bounds depended on list append order; and a collector outliving a turn could pair this attempt's start with the last attempt's end.

Live verification

The first pass used tasks/hello_date, which has no concurrent tools and no sub-agents — so it never exercised the code the fixes touch, and defect 3 survived it. A second pass added a task issuing five parallel writes, five reads and two concurrent Bash calls, plus a sub-agent delegation.

Final, all five harnesses, 13 turns of which 9 carried overlapping tool calls:

harness worst |residual| % of wall
antigravity 0.047 ms 0.000%
claude-code 1.351 ms 0.007%
codex 0.376 ms 0.002%
opencode 0.326 ms 0.002%
pi 1.718 ms 0.012%

claude-code went from 481 ms / 2.691% → 1.4 ms / 0.007% on the same task. Head/tail magnitudes (means of six hello_date turns per harness) are in the parity doc; reproduce any of it with scripts/timing/decompose_run.py.

Guard added

The golden corpus could catch an absence but not a double-count. The fixture clocks are now unified — codex stamped its items at a fixed 2027 epoch and opencode a month in the past, while both agents stamp now(), so a codex replay recorded a harness_startup_ms of ~126 days — and assert_timing_captured asserts the identity. The threshold is relative with an absolute floor, which is what makes it work: defect 2 read +55% of wall but only +0.175 ms.

Mutation-verified: reintroducing defect 2 fails test_antigravity_golden[d_orphaned_tool]. 22 of 27 scenarios are checked; 5 inject SDK stamps in integer milliseconds (17–900 ms of declared item time against a sub-millisecond replay), so no rebasing makes them commensurable — exempt via FICTIONAL_DURATIONS, each named with its reason.

Known and documented, not fixed

  • claude-code's and antigravity's 0.0 head is a clamped negative, not a measured interval — their first window opens before the AgentStartEvent stamp. Measured at 0.03 ms (0.10 ms with four plugin roots), so it is the sub-millisecond skew the clamp exists for. Moving the emit earlier would not change the number and would cost the event its effective model; TestClaudeHeadIsStructurallyZero pins the build cost so the reasoning can't rot silently.
  • "A tool outside every generation window" has no live coverage — defect 2's fix rests on unit tests and the antigravity_d_orphaned_tool fixture.
  • Two guards deferred to .claude/harness-candidates.md: no TypeScript counterpart to CE058, and the naive/aware datetime assumption.

Test plan

  • make verify — 5246 passed, 92.71% coverage
  • make evalboard-verify — 742 tests, tsc, build
  • make lint — 561
  • Live: 30 hello_date runs for head/tail magnitudes, plus 26 runs on a concurrent-tool + sub-agent task across all five harnesses

🤖 Generated with Claude Code

uipreliga and others added 9 commits September 10, 2026 22:28
Measured live on all five harnesses, generation + tool left 0.1%-42% of the
turn unexplained, and the whole remainder sat in two places: before the first
generation window opened, and after the last one closed. EventCollector now
measures both between the agent's own AgentStart/AgentEnd stamps and the
first/last AssistantMessage, and publishes them on TurnRecord.

One live turn per harness, residual after all four buckets:

  antigravity  wall 14348 ms  startup    0.0  teardown   3.5  -0.010 ms
  claude-code  wall 13295 ms  startup    0.0  teardown 834.7  +0.086 ms
  codex        wall 11842 ms  startup 5075.2  teardown  13.9  -0.019 ms
  opencode     wall  8157 ms  startup 3047.9  teardown  33.1  +0.022 ms
  pi           wall  6906 ms  startup  345.4  teardown  26.6  +0.621 ms

The turn now reconciles to under a millisecond everywhere. The residual sign
flips, so the invariant is |residual| < 1 ms rather than <= wall: head and
tail are measured between event stamps while duration_seconds is the agent's
own monotonic span, and the field descriptions say so.

The head is NOT decomposed further, deliberately. Its composition differs per
harness and the stream carries no marker to split it: OpenCode's process
spawns in 3 ms and its first event lands at 3921 ms, so CLI boot, provider
resolution, dispatch and TTFT are fused. claude-code and Antigravity read a
measured 0.0 because their first window already covers dispatch — which is
also why nothing folds that time OUT of their generation: for an in-process
SDK it IS the generation. Hence names for the interval measured, not for what
it contains.

`agents/_timing.py` moves to `coder_eval/timing.py`. It is stdlib-only, but
importing anything under `agents/` executes that package's __init__, which
imports every agent, which imports streaming — so the collector could not
reach it. A cycle-free leaf beside the other shared arithmetic, mirroring
models/cli_match.py's rationale.

Both fields join the golden-stream scrub list. They are measured wall values
like duration_seconds and generation_duration_ms beside them; left unscrubbed
they drifted 24 of 68 golden tests on an unchanged re-run.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`harness_startup_ms` / `harness_teardown_ms` were cited as CE058-guarded but
matched neither `_TIMING_NAME` nor `_TIMING_CONSTRUCTORS`, so the guard the
head/tail work leans on did not exist for the two fields it was named for.

Add one alternation arm (`[a-z_]*_(?:startup|teardown)_ms`, leading segment
required like the `_duration_ms` arm) and `TurnRecord` to the constructor set,
which is what arms form 1. Mutating the real collector call site from
`harness_startup_ms=startup_ms` to `0.0` now fires the rule.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
… strip

The Unaccounted cell was reporting a harness's CLI boot as unexplained time:
opencode's ~3.4s head and claude-code's ~1.0s tail are measured intervals, not
residual. Parse `harness_startup_ms` / `harness_teardown_ms` off each turn, sum
them across the task's iterations, render them as their own Startup and
Teardown cells, and subtract both so Unaccounted is a true residual.

Aggregation is `null` — never 0 — when no turn measured that end, mirroring the
TurnRecord fields' own contract; a measured 0 (an in-process SDK whose first
generation window already covers dispatch) is preserved and renders as `0ms`.
An older run without either field renders exactly as before, including the
25% red threshold, which now reads the corrected number in both directions.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…y contain

Extend `assert_timing_captured` with the one thing the golden replays can
support: a turn that produced an assistant message reports both buckets, and a
turn that produced none reports neither. Keyed on that message rather than on
`expect_generation_window` — `codex_e_orphan_tool` and
`claude_i_in_loop_deadline_break` clear the flag while still having a head and
a tail, so the flag would have left them unchecked. No golden regeneration: all
27 dumps already carried both fields and still match.

`HARNESS_PARITY.md` gains the rows this change exists to publish — what the
FIRST generation window covers per harness, and the measured head and tail —
plus the reason the head is deliberately not split into CLI boot vs TTFT, and
a Known-divergences note for `TurnStartEvent`'s inconsistent emission point.

Live verification (15 runs, 3 turns × 5 harnesses) corrected the identity
itself: `Σ tool` books overlapping tool calls twice, and one Pi turn overlapped
a Write and a Bash by 18.4 ms, producing exactly an 18.3 ms residual. The tool
term is the UNION (`timing.py::busy_ms`), as it already is where a harness
subtracts tool time out of a generation window. With all four buckets and the
union, every harness reconciles to under 0.012% of wall clock.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Three defects the final review found, each breaking the invariant the change
exists to establish.

**A placeholder stamp was read as a window bound.** Codex's rollout rebuild,
both its sub-agent recovery builders and Claude's synthesized terminal message
all stamp `started_at == completed_at == now()` at APPEND time and declare
`generation_duration_ms=None` to say no window was measurable. `_overhead_ms`
read those stamps anyway, so a Codex turn rebuilt from its rollout — stamped
at turn end — booked the ENTIRE TURN as harness startup. Skip them, the same
exemption CE059 already makes for the same reason.

**The bounds depended on append order.** Codex appends recovered sub-agent
messages after the parent's last flush, so `generations[-1]` is not the last
generation. Use min/max instead of the first and last list entries.

**The four buckets were not disjoint.** Generation windows are tool-subtracted;
the head and tail were not. A tool that escapes every window — Antigravity
force-closes an orphan at finalization, inside the tail, and backgrounds
anything over ten seconds — was counted both as tool and as head or tail. On
the committed `antigravity_d_orphaned_tool` fixture that is a residual of -86%
of wall clock. `decompose_turn` now subtracts tool time from both ends via the
same `busy_ms` the windows use.

Also: reset the terminal event when a new turn starts, so the one collector
that outlives a turn (EarlyStopWatcher, across retries) cannot pair this
attempt's start with the last attempt's end and publish the clamped inversion
as a measured 0.0; stop `decompose_run.py` double-counting a sub-agent's
generation against its parent Agent call's interval; and say plainly in
HARNESS_PARITY.md that claude-code's and antigravity's `0.0` head is a clamped
value rather than a measured interval.

One golden dump changes, by two lines: `codex_g_items_rebuild` now honestly
reports `null` for both buckets instead of a number derived from a placeholder.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The first is the valuable one: a golden-corpus assertion of the four-bucket
identity would have caught this work's worst defect, and it is blocked only
because 5 of 27 fixtures stamp generations on a clock that is not
commensurable with their agent events.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…harness

The post-fix re-verification doubled the sample. Figures move by 5-30% with
CLI cache warmth, which is why the table already says to read their order of
magnitude.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…ntity

The golden corpus could not catch a DOUBLE-COUNT, only an absence. That is how
the head/tail work shipped a defect where an orphaned tool was booked both in
the tool union and in the tail: `antigravity_d_orphaned_tool` reconciled at
-86% of its own wall clock while all 72 golden tests passed.

Unify the clocks first, because the assertion is meaningless without it. Codex
stamped its SDK items at a fixed 2027 epoch and OpenCode a month in the past,
while both agents stamp their own lifecycle events with `now()` — so a codex
replay recorded a `harness_startup_ms` of ~126 days and no presence-only check
could see it. Both catalogues stay declarative with an absolute base; the
runners now shift that base onto the replay's own clock, which keeps every
derived duration exact (a 250 ms command stays 250 ms) and fixes only the era.
No golden dump changes — these stamps are scrubbed.

Then assert it: generation + UNION(tool) + head + tail cannot exceed
`duration_seconds`, because the four are disjoint. The threshold is relative
with an absolute floor, which is what makes it work at fixture scale — the
defect reads +55% of wall but only +0.175 ms, so an absolute-only bound
generous enough to survive scheduler jitter would have missed it.
Mutation-verified: reintroducing the defect fails the antigravity fixture.

22 of 27 scenarios are checked. The other 5 inject SDK stamps in integer
MILLISECONDS — 17 to 900 ms of declared item time against a replay that runs
in well under one — so no rebasing makes them commensurable and they are
exempt via `FICTIONAL_DURATIONS`, named individually with the reason. Closing
that last gap needs the agent's own clock faked, not the fixtures' rebased.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The question was whether to emit `AgentStartEvent` before
`_build_claude_query`, so the head became a measurement rather than a clamped
negative. Measured first: the build is 0.03 ms, and 0.10 ms with four plugin
roots — not the hundreds of milliseconds the review hypothesised, because the
transport is constructed lazily and plugin resolution is path work.

So: no. Moving the emit would not change the number anyway — `last_event_wall`,
which becomes the first window's start, is stamped before the build too, so
the build sits inside msg0's generation window either way. It would only
convert a -0.03 ms clamp into a +0.03 ms measurement, and it would cost the
event its `model=effective_model`, which the build resolves and the live
renderers display. Surfacing the build cost would need the window re-seeded
after it, which is the generation-window seeding change HARNESS_PARITY.md
already rules out for an in-process SDK.

Both rejections rest on the build being cheap, so guard that rather than
leaving it as a claim in a commit message: `TestClaudeHeadIsStructurallyZero`
holds it under 50 ms (~300x headroom, best-of-5 so a loaded runner cannot trip
it) and its docstring carries the reasoning. The parity doc now states the
measured figures instead of implying an unquantified gap.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@github-actions

github-actions Bot commented Sep 11, 2026

Copy link
Copy Markdown

Claude finished @uipreliga's task in 1m 37s —— View job


Code Review in Progress

Todo List:

  • Read .github/code_review.md for review standards
  • Read CLAUDE.md for project conventions
  • Review the diff (git diff origin/fix/timing-capture-and-reporting...HEAD)
  • Examine changed files for cross-file consistency
  • Check timing identity invariant implementation
  • Verify test coverage for the new timing fields
  • Complete review and provide feedback

uipreliga and others added 2 commits September 11, 2026 07:21
Live verification on a task with concurrent tool calls — the earlier runs all
used `hello_date`, which has none — found the four-bucket identity failing on
claude-code alone, by 482 ms and 340 ms on two ~18-25 s turns. The residual
equals the generation/tool overlap to within 1.4 ms on every claude-code turn
measured, including the two whose overlap was under a millisecond and which
reconciled to within 0.1 ms.

Cause is a documented exemption whose premise does not hold: claude-code is
the one harness that does not subtract tool time from its generation windows,
on the reasoning that a tool's execution falls between two windows. A tool's
timer starts at the EMISSION carrying its tool_use block, and one assistant
turn spans several emissions, so a later emission's window runs concurrently
with a tool already timing. The other four harnesses overlapped by ~2.0-2.3 s
on the same task and reconciled to within 1.2 ms, because they subtract it.

This predates the head/tail work — generation-vs-tool timing is older — but
that work's identity is what made it visible, and the parity table was
claiming "yes" for all five. Correct the table and the paragraph, state the
measurement, and track the fix as a candidate: applying `busy_ms` here changes
a published `generation_duration_ms` on the most-used harness, so it needs its
own golden regeneration and live pass rather than a quiet amendment here.

Also warn in the new golden identity assertion's failure text, so a future
claude-code fixture that trips it is not misdiagnosed as a fresh double-count.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
claude-code was the one harness that did not, and the reason it was exempt is
measurably wrong. The premise was that because it marks the end of the previous
SDK event and reads again when the next message arrives, a tool's execution
falls BETWEEN two windows. But a tool's timer starts at the EMISSION carrying
its `tool_use` block, and one assistant turn spans several emissions, so a
later emission's window runs concurrently with a tool already timing.

Measured on a task with five parallel writes, five reads and two concurrent
`Bash` calls: 482 ms and 340 ms of overlap on two ~18-25 s turns, and the
four-bucket residual came out at exactly -481 ms and -339 ms. The other four
harnesses overlapped by ~2.0-2.3 s on the same task and still reconciled to
within 1.2 ms, because they subtract it. Two claude-code turns in the same
batch whose overlap happened to be under a millisecond reconciled to 0.1 ms,
which is what isolated the cause to the missing subtraction rather than to
anything about the head and tail.

The subtraction cannot happen while flushing: a tool issued by an earlier
emission is still running when the next window closes, so its interval does
not exist yet. `_subtract_tool_time_from_windows` therefore runs once at
finalization, when every span is known, and uses the same `busy_ms` union the
other four use — the union and not the sum, because these tools overlap each
other too. Sub-agent emissions are skipped: their own tools are not in this
command list, and the Agent call that spawned them already spans their run.

Re-verified live, same task: claude-code 481 ms / 2.691% -> 1.4 ms / 0.006%
over four turns that all carried overlapping tool calls, and all five harnesses
reconcile (worst 1.7 ms, 0.012%). `generation_duration_ms` now means the same
thing on every harness, so the parity table's identity row is "yes" for all
five without a caveat.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant