fix(timing): account for generation and tool time on every harness - #164
Merged
Conversation
uipreliga
requested review from
CarlesUIPath,
akshaylive,
bai-uipath and
tmatup
as code owners
September 11, 2026 02:53
|
Claude finished @uipreliga's task in 1m 26s —— View job Code Review in Progress
|
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
uipreliga
added a commit
that referenced
this pull request
Sep 11, 2026
The Step stream carries no message id, so every Antigravity `AssistantMessage` was recorded with `message_id: None`. The evalboard groups assistant emissions by that field and falls back to a wall-clock gap threshold when either side lacks one — and PR #164 made this harness's generation windows contiguous, so the gap is now exactly 0 ms and the fallback folds a whole turn's generations into one timeline row. Synthesize the id the way Codex does (`{turn_id}-msg-{gen_index}`), reusing the `_assistant_turns` counter that already counts appended generations, read before its increment so the first id is `-msg-0`. Totals are unaffected: the evalboard sums token buckets across a group, and the turn/generation counts come from `_assistant_turns` Python-side. Only display granularity was lost. The five regenerated goldens are the regression sensor (`message_id` is not scrubbed); the new unit assertion pins the exact id strings, so moving the increment above the append fails loudly instead of silently making the ids 1-based. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
bai-uipath
approved these changes
Sep 11, 2026
bai-uipath
left a comment
bai-uipath
left a comment
Collaborator
There was a problem hiding this comment.
Approve both. The instrumentation is solid: the four-bucket identity closed to ~1ms on a live concurrent-tool task I ran against the stacked branch. The summary strip is the one thing worth a pass before merge.
UI improvements
- The strip flattens two levels into one row. Five buckets that sum to the task wall clock sit beside a three-way split of one of them, which sums to Generation instead. Moving the per-kind split onto its own line would separate them.
- "tool" means two unrelated things in the same row. Time spent writing tool arguments, and time tools spent running. Renaming the sub-cell to "tool args" fixes it.
- Unaccounted flips sign when tools overlap. It subtracts the sum of per-tool durations where the identity uses the union, so concurrent tools get counted twice. On a task with two concurrent sleeps it rendered -615ms amber where the honest answer is +2.5s of sandbox setup and grading.
- The execution bounds that needs are already in task.json, and already in scope where the per-tool duration is set, so it should be a small change.
Minor, fix if you agree
- No parity test covers the TS decomposition against the Python one. Every current TS test asserts against the sum, so the suite agrees with the bug above.
- opencode and pi don't subtract still-open tools the way antigravity and codex do, though the argument applies to them equally now their windows tile.
- The collector's head/tail measurement doesn't exclude sub-agent messages, unlike its two sibling call sites.
- Delegate in coder_eval_uipath keeps both defects this removes, while sitting outside the new rules' scope.
- #165 hasn't run the gating workflows, since its base is a feature branch. Verify, lint, pyright and the evalboard suite were all green locally against its head.
Two reporting fixes to the same surface: time figures that are each well-formed but never say what they should reconcile to. A. The task page's timeline strip gains an `Unaccounted` cell — task wall clock minus generation minus tool execution — so a harness that stops reporting one of them is visible on the page instead of reading as fast. Tinted red at or above a 25% residual. A negative residual (parallel tool calls, or a tool closing inside a generation window) renders signed and untinted rather than clamped: an overlap is a signal, not unreported time. `fmtMs` is now sign-aware so that reads as `-1.2s`, not `-1200ms`. B. The run list's Duration column now counts only what ran. Mature-skipped rows are carried-forward passes with no duration, so summing over them divides real seconds by a task count that never executed — a codex nightly rendered "1300 tasks · 15h 29m" describing 397 tasks. The two duplicated duration derivations in runs.ts collapse into one exported `deriveRunDuration`, which excludes those rows from both the sum and the `every()` completeness guard, and reports `executedTasks` alongside. Both run tables now name that count next to the duration when the two differ. `tasksExecuted` is carried through `RunSummary` / `RunOverview` / `ScopedRun` / `RunListingRow` rather than recomputed per consumer: the whole-run count comes from the same helper that produced the duration (over run.json's task_results), while `overview.tasks` drops rows with no task_id, so a recount could disagree with the duration's own denominator. A run with no mature skips renders exactly as before. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`AssistantMessage.generation_duration_ms` was a required `float`, so a
harness with no measurable window had to invent one — and every producer
that did wrote `0.0`, which reads downstream as a real, instant
generation. It is now `float | None` with `default=None`, aligning it with
`UserMessage.generation_duration_ms` in the same module.
Every live "unknown became zero" producer is fixed:
- Codex's rollout rebuild and both sub-agent syntheses record `None` —
Turn items carry no per-item timestamps and a sub-agent generation
arrives as a tool result, so no window was ever measurable.
- Claude's sub-agent terminal message, same reason.
- Claude's `_finalize_commands` no longer coerces an orphaned command's
`duration_ms` to `0.0`. Its `result_status` is already "unknown";
unknown status and unknown duration are the same fact. The command now
leaves BOTH sides of `avg_command_time_ms` instead of dragging the
average toward zero.
- `analysis.py`'s two slowest-command coalescings are gone: the duration
travels alongside its command as a pair, so it stays a float and an
untimed command simply is not ranked. `avg_command_time_ms` reports
`None` when nothing was timed rather than "0ms average".
- The simulator's trailing standalone turn passes a real
`duration_seconds`. It defaulted to 0.0 with no caller supplying it,
which halved `avg_turn` in the HTML report for every simulation task.
Two lint rules make the class permanently detectable. CE058: an unknown
timing value may not become a numeric literal — five syntactic forms, one
id, including the `if x is None: x = 0.0` guard where the live Claude
instance was hiding and the `model_copy(update={...})` dict a keyword-only
rule cannot see. CE059: an `AssistantMessage` may not take one clock read
as both bounds; it exempts a call that passes `generation_duration_ms=None`,
because saying "no window was measurable" in the field built to say it is
not a claim the two stamps have to support.
Antigravity's flush keeps its `0.0` under both noqas for one more commit;
the next one replaces it with a real measured window and deletes them.
Golden snapshots move in exactly four places, all `"<scrubbed>" -> null`.
No token bucket moves; `assert_reconciliation` passes unchanged.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The reducer read `datetime.now()` once per flush and passed it as BOTH `started_at` and `completed_at`, with a hardcoded `generation_duration_ms=0.0`. Every Antigravity row therefore reported no generation time at all: the task page's Generation cell read 0ms and its thinking/tool/text breakdown rendered 0%, for months, with nothing failing. 15% of wall clock was accounted for, against 97% on claude-code. The window is now marked at the turn's start (both stamps from one instant, captured in `communicate()`) and advanced by each flush that actually emits a message — never by the early-returning no-op flush, whose guard precedes every clock read. Tool execution that closes inside a window is subtracted, because this harness interleaves tool calls into one generation: the Step for the tool arrives and only a later `usage_metadata` Step cuts the message. The subtraction is the UNION of the closed intervals, clipped to the window — not the sum of their durations. Antigravity resolves several calls from one Step and backgrounds anything over ten seconds, so the intervals overlap; summing them over-subtracts by exactly the overlap, and four concurrent 400ms calls inside a 1000ms window would total 1600ms and clamp the result back to the 0.0 this commit exists to remove. Clipping is the other half: a tool that opened before the window only spent part of its life inside it. Do not "simplify" the subtraction to resetting the mark on tool end. A harness-local Read can close 8ms after it opens while 6.4s of model time separates the two flushes around it (measured: 2026-09-09_04-18-50/skill-rpa-uia-google-search), so a reset reports 8ms and loses the 6.4s. A controlled-clock test pins this. With the union clipped to the window, `max(0.0, ...)` is now only a clock-jitter guard — the span is monotonic while the intervals are wall — and a negative result logs at debug, since a clamped 0.0 is otherwise indistinguishable from a real instant generation. Still deliberately unaccounted (audit P2-1): time spent waiting on a tool that is STILL open contributes nothing to any subtraction, so an orphan-poll turn's window includes the wait. Token buckets are untouched and `assert_reconciliation` passes unchanged. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…g them The Codex SDK reports `started_at_ms` and `completed_at_ms` on every item notification. The agent read the start (for message windows) and threw both away for telemetry, publishing the SDK item's own `duration_ms` instead: `0.0` for 70 of 211 commands in one nightly, absent for 25 more, and no `execution_started_at` / `execution_completed_at` at all, so no Codex tool call could be placed on a timeline. One `_item_timing` helper now resolves timing for all three telemetry builders, so a command, a file change and an MCP call cannot disagree. Both raw stamps are checked BEFORE conversion — `_ms_to_dt(None)` is `datetime.now()`, so pairing a real stamp with a missing one would fabricate an interval running to the present moment. Without stamps the SDK's own duration is used only when it reports something: a `0` there is an unreported duration, not an instant command. `timestamp` becomes the tool's own start rather than `datetime.now()` at completion, which placed every call after its own execution; nothing orders on it (`collector._ordered_commands` sorts on `sequence_number`). Orphans keep their known start — the SDK marks `started_at_ms` required, so it IS knowable — while completion and duration stay None. Codex was the only harness whose unresolved calls could not be placed on a timeline. Publishing those bounds exposed a double-count the plan had assumed away. `_flush_message`'s generation window is seeded from the first item's start and extended to the LAST item's completion, so any generation containing a tool call already contains that tool's execution: a tool-only emission reported 250ms of "generation" beside a 250ms `echo hi`, and a collab scenario put 1790ms of generation-plus-tool inside a 900ms window. Left alone, the task page's new Unaccounted cell would have read -98% on every Codex row. The window now subtracts the union of the closed tool intervals clipped to it — the same treatment, and now the same shared helper (`agents/_timing.py::busy_ms`, moved out of the Antigravity agent), as the previous commit. Generation + tool execution equals the window exactly. The golden snapshots cannot catch a swapped stamp — the scrubber masks every non-null timestamp, so they assert presence, not value — so the wiring has its own end-to-end test that reads the values back. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The message reducer assumed one block kind per emission, which is a Claude CLI property. Everywhere else it breaks, and it breaks twice. TIME: all of a raw's generationMs went to the first kind the priority chain tested. Measured 98.5% thinking on codex and 99.8% on delegate, where 93% of emissions carry more than one kind. OUTPUT: the first pass handed a raw's ENTIRE outputTokens to its tool blocks, and flush() then added the same whole figure to thinkingOutSum whenever the raw also carried a thinking block. The same tokens were counted twice for 93% of Delegate's emissions, inflating the cost simulator's thinking lever. Both are now apportioned by ONE content-size weight vector per raw, computed once and stored, so the two can never disagree. Weights are content size and depend on no output figure: deriving thinking as `outputTokens - toolWeight` looks natural and is always 0 when a tool is present (150 of 174 sampled emissions), which would produce the exact mirror of the bug — 100% tool, 0% thinking. `splitByWeight` puts `tool` first so it is never the remainder kind. The tool share is also computed in the first pass, and if one site rounded while the other took the remainder they disagreed at a tie and the parts over-summed by a token — the same double-count, one decimal down. A rounding sweep pins it. Single-kind emissions take an explicit path and are byte-identical to before, including per-tool figures; claude-code pages must not move. A mixed emission with nothing sizeable to weigh by lands in a new `mixedGenMs`, rendered as "unsplit" — the timeline legend already uses MIXED for "multiple block types", which is the case this cell is normally empty for. Per-kind percentages all divide by the whole so they sum to 100%; only the red thinking tint uses the attributable part. Codex's `_flush_message` no longer concentrates a generation's whole duration on its first sub-message. It splits by output-token share — a real per-spec measurement, unlike the evalboard's content-size proxy — while input and cache tokens stay on the first sub-message, because those are per-call billing figures and were never the generation's to divide. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
… sensor Only claude-code and codex had golden coverage, so the three harnesses whose timing was worst had no recorded stream at all. Antigravity, OpenCode and Pi now each have one, with the `_step` / `_FakeProcess` / event-builder helpers MOVED out of the agent test modules and imported back rather than copied — those modules' own tests are unchanged. `assert_timing_captured` is the sensor an AST rule cannot be. It replays the real reducer and asserts what static analysis cannot see: that a resolved command carries both execution bounds and a duration, and that a turn which streamed a generation reports a positive window somewhere. It runs on the UNSCRUBBED dump, because the scrubber masks values while preserving None and present-vs-absent is the whole assertion. It is a scenario-level floor rather than a per-entry rule, and that is forced by the snapshots: `claude_d_subagent_terminal` holds two content-bearing messages of which exactly one is legitimately None, so no flag could express "this one but not that one". The exemptions live in one `NO_GENERATION_WINDOW` set beside the coverage mapping, not as a field on five dissimilar dataclasses, and each names its reason. Strict is the default: a new scenario is asserted to have a window until someone says otherwise. Two of those exemptions were not in the plan's table, which was computed from snapshots where the value is scrubbed and so could not see them: `claude_i_in_loop_deadline_break` drives a scripted constant clock, and two Codex scenarios have zero-width windows by stream shape. A third candidate was fixed instead of exempted — `codex_b_command_execution` gained a reply, so it carries real generation content rather than being tool-only. Fix the fixture before weakening the sensor. Coverage is derived from `AgentKind`, excluding only NONE (agentless) and UNKNOWN (a sentinel), each with its reason — an allowlist of exclusions, so a new member fails until someone decides. The negative cases run the real check against a mutated copy rather than restating its condition. `HARNESS_PARITY.md` gains a `## Timing capture` section: where each field comes from per harness, why `generation_duration_ms` is model-generation time rather than the span between its own bounds, why Codex leaves `generation_completed_at` unset, and the two divergences left open — Antigravity's orphan-poll wait and Delegate's missing bounds — both also recorded in the deferred-work file. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The cross-cutting review caught that the change stopped at three of five
harnesses while the parity table it adds claimed all five.
OpenCode and Pi carry the identical double-count removed from Codex: both
mark a generation window at `step_start` / `turn_start` and close it at
`step_finish` / `turn_end`, and every tool call runs INSIDE that window
while also publishing its own measured duration. Replayed through the real
reducers, a 1s tool inside one step produced `Unaccounted: -99%` — in the
very cell added to catch this. Both now subtract the same union of closed
tool intervals, via the same `busy_ms`, making it four call sites for one
helper. The parity table and its prose say four harnesses interleave, not
two, and name claude-code as the one that does not need the subtraction
(it marks the end of the previous SDK event, so tool time falls between
windows rather than inside one).
The Unaccounted cell also double-counted every sub-agent on every harness.
A sub-agent's emissions carry a `parentToolUseId` and its spawning Agent
call's duration already spans the whole sub-agent run, so summing over all
messages counted its generation twice — a 140s claude-code task with a
120s Agent call containing 90s of sub-agent generation reported -57%. The
strip now sums the main thread only. A negative residual gets its own
amber tint: overlap is a different fact from a large positive residual,
and identical grey hid it.
`scopeRunTasks` was a third duration derivation that phase 1 missed, so
the Duration column used one definition unfiltered and another with a tag
filter active — and a single mature-skipped row with no duration flipped
the all-present guard, rendering "—" for a run whose executed rows were
all timed.
`assert_timing_captured` now also requires the recorded bounds to span the
window it reports. Two harnesses take the duration from a monotonic clock
and the bounds from the wall clock, so a reducer can publish a healthy
duration beside two stamps that collapsed — which is exactly the case
CE059's docstring claims this sensor covers and, until now, it did not.
The cost simulator picked its primary model by generation time, under a
comment asserting that "generation time is recorded for every emission" —
a premise this change invalidated. With every window null it weighed all
models at zero and the first one encountered won, so a Haiku sub-agent
listed before the main Opus message priced the whole task at Haiku rates.
It now falls back to output tokens, then to an equal vote.
CE058 ships five syntactic forms; CLAUDE.md and the rule's own docstring
still said four, omitting the `model_copy(update={...})` dict — the shape
the Antigravity DONE path actually writes through.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…llow-up Surfaced by the timing-capture final review but out of that change's scope (token accounting was explicitly excluded, and the validator is untouched by it). A real bug rather than a guardrail candidate: a legacy record's full-prompt input_tokens is adopted as the UNCACHED slice, so the computed total adds the cache buckets a second time. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…ity double-counting an open tool Live runs of tasks/hello_date across all five harnesses — the invariant no unit test can prove against a real SDK — found two defects. Codex published `generation_duration_ms=0.0` on a message carrying 98 output tokens, reproducibly. Its window was seeded from the item's EXECUTION stamp, so a tool-only emission's window equalled the tool's own interval and the subtraction clamped to zero, while the 2694 ms that generated the item sat in the preceding gap attributed to nothing. Only 15.8% of a 17 s turn was accounted for, which is also why clause 3 passed there: it under-measured too heavily to breach anything. Windows now tile from the previous flush's end, kept in the SDK's own clock — seeding the mark from time.time() would mix our clock with the SDK's inside a single subtraction. Three live runs: 64-86%. Antigravity broke the branch's headline invariant. Sum(generation) + Sum(command) exceeded the turn's own duration_seconds by 0.26 ms, because a tool still OPEN at flush time had its already-elapsed portion published as generation and then counted again as its duration_ms. These contiguous windows have no slack to absorb that: 5 pre-fix runs ranged -0.26 to +8.69 ms out of ~12 s, so it was a coin flip rather than a rounding artifact. Open calls are now subtracted too, bounded at the flush; when one later closes, the DONE path hands its full interval to the next window, where busy_ms clips it to the post-flush remainder, so nothing is subtracted twice. 12 post-fix runs are all positive (min +0.23 ms). This replaces the comment deferring the case to audit P2-1. Codex gets the same open-tool treatment, since tiling is what makes that double-count reachable there. Both new tests fail without their fix (Codex 0.0 vs 1900.0; Antigravity 300.0 vs 100.0). Final sweep: 5/5 harnesses pass all three clauses. Known and deliberately not papered over: Codex's remaining 14-36% is the latency before the SDK's first item stamp, which the stream gives no way to measure, and Antigravity's margin stays thin by construction because its windows tile ~100% of the turn. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
OpenCode bounded each window at `step_start`/`step_finish`, but the CLI announces a step only once it is already producing one, so the model time that PRODUCED the step landed in the gap before it and was attributed to nothing. Measured on tasks/hello_date with a live claude-haiku-4.5: gaps of 857 ms and 851 ms carrying no tool at all (the Write inside them took 7 ms). Same defect and same fix as the Codex half of 237437b — a `gen_mark` carrying the previous step's finish. The first window deliberately does NOT tile: everything before the first `step_start` is CLI process spawn, and folding it in would report Node's boot as model generation. Four live runs, before -> after: accounted 33.9% -> 57.9% inter-message gaps 1788 ms -> 0 ms That is the whole of the gap bucket, and it is all that this change claims. The remaining 42% is one bucket, `head` (3376 ms of spawn + time-to-first- token), which is real wall time that is neither model nor tool and has no home in a TurnRecord that carries only those two. So OpenCode stays above the evalboard's 25% Unaccounted threshold on a short task; closing that needs the harness-overhead bucket, not a wider window. Noted so the next reader does not mistake a partial recovery for the finished job. All three clauses still hold (headroom 2.7-5.0 s across the four runs), and both new tests fail without the fix (200.0 vs 1000.0). Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Review feedback on #164. The task page's Unaccounted residual subtracted the SUM of the per-tool durations where the identity uses their UNION, so two concurrent tools were counted twice and the cell went negative: -615ms amber on a task with two concurrent sleeps whose honest residual was +2.5s of sandbox setup and grading. `CommandTelemetry` already records `execution_started_at` / `execution_completed_at`, and the evalboard already had them in scope where it sets `durationMs`, so the fix is to carry them onto `MessageToolUse` and union the intervals. A call the harness timed but did not bound still contributes its own duration, so no run loses tool time. `busyMs` is the TypeScript twin of the harness's `busy_ms`; the two answer the same question about the same task.json, so neither owns the numbers — `tests/_fixtures/timing_union_cases.json` does, and both suites replay it. The summary strip flattened two levels into one row: five buckets that sum to the task's wall clock, beside a three-way split of one of them that sums to Generation. The split now has its own row under a `Generation split` label, and its `tool` cell is `tool args` — time the model spent WRITING a call, next to a `Tool exec` cell that is time the tool spent RUNNING. The bare word named both. OpenCode and Pi now subtract a still-open tool bounded at the window end, as Antigravity and Codex already do. The argument applies to them equally now that their windows tile: without it the part of a straddling call that ran before the boundary is published as generation while the call's own `duration_ms` counts it again. Also: the three test modules CodeQL flagged imported their agent module with both `import` and `from ... import`; the local imports are hoisted. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
uipreliga
force-pushed
the
fix/timing-capture-and-reporting
branch
from
September 12, 2026 00:17
d809c93 to
7483b67
Compare
Collaborator
Author
|
Thanks — every point landed. The five for this PR are in The stripUnaccounted flips sign when tools overlap. Confirmed and fixed. You were right that the bounds were already in reach: Two levels in one row. The per-kind split moved to its own row under a "tool" naming. Now MinorNo parity test. Added, and pointed at the root of the divergence rather than at the rendered cell: One implementation note: the helpers live in OpenCode and Pi don't subtract still-open tools. Fixed both, mirroring Antigravity and Codex. Agreed the argument applies equally now their windows tile: without it the part of a straddling call that ran before the boundary is published as generation while the call's own The collector's head/tail doesn't exclude sub-agent messages. Fixed on the Not fixedDelegate in #165 hasn't run the gating workflows. Still true while its base is a feature branch. GitHub retargets it to Also in this pushThe three CodeQL alerts (a module imported with both Verification
|
uipreliga
added a commit
that referenced
this pull request
Sep 12, 2026
The Step stream carries no message id, so every Antigravity `AssistantMessage` was recorded with `message_id: None`. The evalboard groups assistant emissions by that field and falls back to a wall-clock gap threshold when either side lacks one — and PR #164 made this harness's generation windows contiguous, so the gap is now exactly 0 ms and the fallback folds a whole turn's generations into one timeline row. Synthesize the id the way Codex does (`{turn_id}-msg-{gen_index}`), reusing the `_assistant_turns` counter that already counts appended generations, read before its increment so the first id is `-msg-0`. Totals are unaffected: the evalboard sums token buckets across a group, and the turn/generation counts come from `_assistant_turns` Python-side. Only display granularity was lost. The five regenerated goldens are the regression sensor (`message_id` is not scrubbed); the new unit assertion pins the exact id strings, so moving the increment above the append fails loudly instead of silently making the ids 1-based. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
uipreliga
added a commit
that referenced
this pull request
Sep 12, 2026
The module docstring named Antigravity and Codex as the only harnesses that interleave tool execution into a generation window. That stopped being true in the same release: #164 gave OpenCode and Pi tiled windows (so a call open at a boundary runs inside two of them), and this branch gives claude-code tool subtraction. All five now subtract, and all five subtract the union. Also names the TypeScript twin and the corpus that holds the two in step, which the docstring did not mention at all. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
uipreliga
added a commit
that referenced
this pull request
Sep 13, 2026
The Step stream carries no message id, so every Antigravity `AssistantMessage` was recorded with `message_id: None`. The evalboard groups assistant emissions by that field and falls back to a wall-clock gap threshold when either side lacks one — and PR #164 made this harness's generation windows contiguous, so the gap is now exactly 0 ms and the fallback folds a whole turn's generations into one timeline row. Synthesize the id the way Codex does (`{turn_id}-msg-{gen_index}`), reusing the `_assistant_turns` counter that already counts appended generations, read before its increment so the first id is `-msg-0`. Totals are unaffected: the evalboard sums token buckets across a group, and the turn/generation counts come from `_assistant_turns` Python-side. Only display granularity was lost. The five regenerated goldens are the regression sensor (`message_id` is not scrubbed); the new unit assertion pins the exact id strings, so moving the increment above the append fails loudly instead of silently making the ids 1-based. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
uipreliga
added a commit
that referenced
this pull request
Sep 13, 2026
The module docstring named Antigravity and Codex as the only harnesses that interleave tool execution into a generation window. That stopped being true in the same release: #164 gave OpenCode and Pi tiled windows (so a call open at a boundary runs inside two of them), and this branch gives claude-code tool subtraction. All five now subtract, and all five subtract the union. Also names the TypeScript twin and the corpus that holds the two in step, which the docstring did not mention at all. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
uipreliga
added a commit
that referenced
this pull request
Sep 13, 2026
* feat(timing): book each turn's head and tail as their own buckets
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>
* test(lint): 2/4 — widen CE058 to the turn head/tail buckets
`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>
* feat(evalboard): 3/4 — name the harness head and tail in the timeline 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>
* feat(timing): 4/4 — assert the buckets in replay, and record what they 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>
* fix: code review fixes for turn head/tail timing
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>
* docs(harness): record three guards the head/tail review could not close
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>
* docs(harness): widen the measured head/tail figures to six turns per 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>
* test(timing): unify the fixture clocks and assert the four-bucket identity
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>
* test(harness): pin why claude-code's zero head is left as a clamp
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>
* docs(harness): claude-code's generation windows are not tool-subtracted
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>
* fix(claude-code): subtract tool execution from the generation windows
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>
* fix(antigravity): 1/3 — give every generation a message_id
The Step stream carries no message id, so every Antigravity
`AssistantMessage` was recorded with `message_id: None`. The evalboard
groups assistant emissions by that field and falls back to a wall-clock
gap threshold when either side lacks one — and PR #164 made this
harness's generation windows contiguous, so the gap is now exactly 0 ms
and the fallback folds a whole turn's generations into one timeline row.
Synthesize the id the way Codex does (`{turn_id}-msg-{gen_index}`),
reusing the `_assistant_turns` counter that already counts appended
generations, read before its increment so the first id is `-msg-0`.
Totals are unaffected: the evalboard sums token buckets across a group,
and the turn/generation counts come from `_assistant_turns` Python-side.
Only display granularity was lost.
The five regenerated goldens are the regression sensor (`message_id` is
not scrubbed); the new unit assertion pins the exact id strings, so
moving the increment above the append fails loudly instead of silently
making the ids 1-based.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* test(lint): 2/3 — CE060, an AssistantMessage must declare its message_id
Antigravity omitted the kwarg and nothing failed: the field defaulted to
None on every message, the evalboard summed the collapsed group so the
totals stayed right, and the golden snapshots had ratified the null the
day they were written. A snapshot is regenerated from whatever the code
currently does, so it catches a later change and never an initial
omission — which is why the author-time rule is worth its cost and is
the only one of the three sensors that would have failed on the day this
shipped.
Unlike CE058/CE059 it derives its constructor set from each module's own
`coder_eval.models` imports rather than hardcoding the spelling. That
closes the blind spot CE058's own docstring concedes: claude_code_agent
binds only `AssistantMessage as AssistantMessageTelemetry`, so a name
list guards that file's two construction sites purely by coincidence,
and an arbitrary `as Msg` is missed outright. Widening the other two the
same way is recorded in .claude/harness-candidates.md — it changes two
shipped rules and needs its own per-rule mutation check.
Verified non-vacuous: stripping the Phase 1 kwarg yields exactly one
violation, at the site it came from; the clean tree yields zero, with no
suppression anywhere.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* docs(harness): 3/3 — message_id is what splits the timeline
Record the per-harness `message_id` source in the Timing-capture table
and give the rationale one home: the evalboard groups assistant
emissions by the field and falls back to a wall-clock gap when either
side lacks one, which cannot split windows that are contiguous by
construction. The source comment and the CE060 docstring point here
rather than restating it, and this is the only place the 100 ms numeral
is written outside runs.ts.
The table row names both synthetic sub-agent forms, since a row titled
"message_id source" that omits them reads as wrong the first time
somebody greps it. Nothing goes in Known divergences — this is a fix.
On the consumer side, tighten the existing message_id-splitting case
from a 10 ms to a 0 ms gap so the fixture matches the shape this harness
really emits. No second case: runs.ts short-circuits on the two ids
before the gap is computed, so 10 ms and 0 ms take the identical branch
and a parallel case would test nothing new.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* fix: code review fixes for antigravity-message-id
Two findings, each raised independently by both final reviewers.
CE060's rename-safety was half delivered. Deriving the constructor set
from the module's imports removes the local-BINDING spelling, but the
class's own name was still a string literal here, so renaming the model
— the likelier rename, since the alias exists only because two
AssistantMessage types collide — would have disarmed the rule exactly as
it disarms the name lists CE060 argues against. It now reads
`AssistantMessage.__name__`, the way CE056 imports IN_CONTAINER_ENV.
The import walk also traded the alias gap for an import-FORM gap that
the docstring's "one remaining blind spot" did not mention: only an
absolute `from coder_eval.models import ...` bound anything, so a
relative import went silently blind for a whole file (and agents/ does
use relative imports), as did every module-alias spelling. Both now
fire, verified case by case; the attribute spelling is matched on the
attribute alone, deliberately, because the module binding it arrives
through is the part a class-binding walk cannot see. What remains — a
re-export through an intermediate module — is now stated as such. The
attribute test was retargeted at the module-alias form, since with a
direct import beside it it had been passing for the wrong reason.
The prose in all three surfaces claimed "only granularity was lost",
which is measurably false: a grouped emission is one API call to the
evalboard's thinking-cost simulator, whose cache cascade is quadratic in
that count, so a single-shot Antigravity run had every coefficient
pinned at zero; the Messages count and the 10 s slow-generation bar were
per-turn too. All three move toward the figure they were always meant to
report, so this fix corrects them — but a trend compared across it is
not comparing like with like, and the docs now say so. Also: the table
gave OpenCode's `None` case where the CE060 docstring asserted it, so
the two surfaces in one diff disagreed, and the remaining nulls are not
legacy-only.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* docs(harness): register the message_id gaps the final review surfaced
Three candidates, all deferred with the reason stated rather than the
work done: the within-turn-only nature of a synthetic message_id (a
negative property over two languages, and the obvious assertion would
pass today while catching nothing), the absence of any evalboard test
fed by a Python golden (needs a loader and a scrub-aware timestamp
story), and the model field's claude-only description (the plan scoped
out model changes; no mechanical guard is obvious).
A fourth was attempted and dropped: a vitest case asserting that two
null-id messages at a 0 ms gap collapse. Its mutation check showed it
takes the identical `gap <= SAME_EMISSION_GAP_MS` branch as the existing
50 ms legacy case, so it could not fail for the reason it claimed —
which is what the plan's own argument against a parallel case said.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* fix(timing): bracket the head and tail on the main thread only
Review feedback on #165.
`EventCollector._overhead_ms` bracketed the turn's generation span with
every `AssistantMessage`, sub-agent emissions included — unlike its two
sibling call sites (`codex_agent._token_usage_from_messages` and
`scripts/timing/decompose_run.py`), which both filter on
`parent_tool_use_id` for the same reason.
A sub-agent's generations sit inside the spawning Agent call's own
interval, and the identity the head and tail complete sums generation over
the main thread ONLY. Letting a sub-agent message bracket the span shrinks
the head or the tail by time no bucket then claims; Codex's recovered child
messages carry the CHILD's clock, so it can move either end.
Mutation-verified: dropping the filter fails both new cases.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* docs(timing): every harness subtracts tool time now, not two
The module docstring named Antigravity and Codex as the only harnesses that
interleave tool execution into a generation window. That stopped being true
in the same release: #164 gave OpenCode and Pi tiled windows (so a call open
at a boundary runs inside two of them), and this branch gives claude-code
tool subtraction. All five now subtract, and all five subtract the union.
Also names the TypeScript twin and the corpus that holds the two in step,
which the docstring did not mention at all.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* feat(timing): 1/6 — a two-sided residual gate for the four-bucket identity
The only sensor for `Σ generation + ∪ tool + head + tail ≈ duration` is
one-sided: `_scrub.py` asserts `overshoot <= ...`, which catches a bucket
claiming MORE time than the turn contains and says nothing at all about one
claiming less. An unmeasured bucket — the defect the next four phases move
numbers to fix — passes every test in the suite today.
`--max-residual-pct` gates on `abs(share)` per turn, so both signs count. It
skips a turn on the turn's OWN `crashed` flag and head/tail pair, never on the
record's `final_status`: the orchestrator preserves a crashed partial across a
retry, so a SUCCESS record can hold a crashed turn, and an `execute` corpus
finalizes every row as NOT_GRADED, which is not a statement about timing. Both
skips are counted independently — short-circuiting left the no-window tally
reading 0 on the one corpus that contains it.
An empty gateable set exits non-zero when a threshold was asked for. A gate
that passes because it measured nothing is the failure this file exists to
remove.
Report-only on landing: nothing passes the flag.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* refactor(timing): 2/6 — one close_window() for the tiling reducers
Codex, opencode and pi each carried their own copy of the same window
arithmetic — tile from the mark, defend the start with min(), bound the
still-open calls at the boundary, subtract the UNION, clamp at zero — plus
three near-identical paragraphs explaining why subtracting an open call here
does not double-subtract it later. One helper, one docstring.
A pure refactor: the golden master passes with NO regeneration, and the three
call sites were checked argument by argument against the formulas they
replace. Codex's min() moves from the epoch-millisecond domain into the
datetime domain, which is safe because `_ms_to_dt` is strictly monotone over
ms-spaced inputs, and its `item_start` stays guarded so `_ms_to_dt(None)`
cannot fire a third `datetime.now()`.
`mark` is keyword-only with no default: a reducer cannot open a window without
stating what it tiles from. That constrains the call shape, not the value —
pi still passes its own turn start, and the docstring says so rather than
claiming the defect is already gone.
Antigravity is NOT migrated here. Its span is monotonic while its tool spans
are wall, so this signature cannot express it without either dead code or a
moved number; it migrates in 5/6, with the deletion of that split.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* fix(timing): 3/6 — a tool that closes between two windows is not model time
Both reducers cleared their tool-span list at turn/step START, which is after
the window that list feeds has already opened at the mark. A call closing in
the gap therefore had its span wiped before the next flush could subtract it,
and the window published that call's execution as model time while the call's
own duration_ms counted the same milliseconds again.
Reproduced against the real state objects, not argued: a call opening at 100,
still running when the step finishes at 1000, closing at 1500, with the next
window tiling 1000 -> 2000. OpenCode published 1000.0 for a window whose model
time was 500.0 — a 100% overstatement, and it needs the non-terminal tool path,
which is why the CLI's usual one-shot `completed` event hides it and the
measured corpus reads 0.00%.
Pi gets the same reset move AND a `gen_mark`, in one commit and in that order.
It was the last harness measuring from its own turn start, so every inter-turn
gap fell in no bucket — but it was protected from the span-reset defect BY not
tiling, so tiling it without moving the reset first would take a correct
harness and introduce the 500 ms double-count. The reset is the value here;
Pi's tiling gap measures 0.25 ms median over 25 real window pairs.
The golden corpus cannot see any of this: `_scrub.py` masks every timing value
to a placeholder, and its identity assertion is an upper bound, so
under-accounting passes it silently. So both harnesses gain an ms-exact
`generation + UNION(tool) == span` test across the boundary, and the reset move
is mutation-pinned on each.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* test(lint): 4/6 — CE061, a window must come from the shared helper
Pi shipped measuring its generation window from its own turn_start while four
sibling reducers tiled from a mark, so every inter-turn gap fell in no bucket.
Nothing caught it: the parity doc asserted the four-bucket identity, the only
sensor for that identity checks one side, and Pi's own tests were written
against Pi's own arithmetic. A sixth harness rolling its own window would
arrive the same way — with a green suite by construction.
So the rule is about PROVENANCE, not values: a module in agents/ that publishes
a measured `generation_duration_ms` must import `close_window`. Separate id
from CE058/CE059/CE060, which are about the values a message carries — one
invariant per id is what makes a noqa mean one thing.
Its weakness is stated in its own docstring rather than left to be discovered:
it proves the helper is imported, never that a given call used it. The value is
always a local, so no AST rule can trace it. The sensors for the arithmetic are
tests/test_timing_close_window.py and the per-reducer window tests.
Two suppressions, not the one the plan predicted. claude-code's is permanent —
it subtracts tool time once at finalization across every emission, a shape
`close_window` cannot take without a mode flag. Antigravity's is marked
TEMPORARY and comes out in 5/6 with its clock conversion. A test pins that
exactly these two files need suppressing, so a noqa cannot outlive its reason.
CE060 already owned the alias resolution both rules need, so it moves to a
shared `_model_ctor.py` rather than being copied: a new import spelling now
needs one fix, not two. Every behavioural CE060 test is unchanged.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* fix(timing): 5/6 — one clock basis per turn on antigravity and pi
Antigravity read its window span off time.monotonic() while unioning
wall-clock tool intervals and subtracting one from the other. That is the only
reason the window could go negative at all, and the clamp underneath it
published a 0.0 indistinguishable from a real instant generation, with a debug
line as the only trace. One basis makes the disagreement unrepresentable, so
the branch and the clamp are deleted rather than left unreachable — a test
greps the source to say so. It moves onto close_window in the same commit,
which is the only point the two could be exchanged without either dead code or
a moved number, and its temporary CE061 suppression comes out with it.
Pi's stamps were naive-LOCAL datetime.now(). A DST transition or an NTP step
inside a turn lands directly in a generation window — an hour in a field
measured in milliseconds, on nightly runs that start at 04:18 and run for
hours. A monotonic-derived stamp cannot express it.
Codex and OpenCode keep theirs: their tool spans are the CLI's own epoch
stamps, unreachable from the host, so converting only the window bounds would
put two bases inside one busy_ms subtraction — relocating the defect instead of
removing it. This narrows the hazard from five harnesses to two; the parity doc
says so rather than implying it is solved.
The clock is INJECTED into the turn-state constructors, not read from a module
global, and that is the phase's largest blast radius rather than a style
choice: a derived stamp does not read datetime.now(), so the four existing
monkeypatches would have stopped reaching the reducer and those tests would
have quietly measured the real clock and passed. Verified by hand on both
harnesses that deleting the injected fake now FAILS.
Deadlines stay on raw time.monotonic(), commented at one site per harness: a
deadline must not move when the wall clock steps.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* docs(harness): 6/6 — the timing architecture as it now stands
Corrects the Pi row, which still claimed a window opening at its own
`turn_start`, and adds two rows the table never had: which clock basis each
harness's recorded stamps come from, and which of them build their window
through the shared helper.
The identity row gets a footnote rather than a bare "yes". Its committed sensor
is one-sided — it catches a bucket claiming more time than the turn contains
and nothing about one claiming less — and it cannot see the magnitudes at all,
because the golden scrubber masks every timing value to a placeholder. A doc
that asserts an invariant should say what actually checks it.
Folds in the time-to-first-token design, which was living in an uncommitted
scratch note that had gone stale in four separate ways — including naming a
file that never existed. The design is recorded as rules with reasons (name it
`first_delta_latency_ms`, never a fifth bucket, first delta of ANY kind, never
0.0) and deliberately without a table of private attribute names, since
transcribing those is how the note died: one of them was deleted in 5/6.
Nothing is implemented here. No field, no reducer change, no model change.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* fix: code review fixes for timing-architecture-standardization
A duplicate `turn_end` / `step_finish` with no intervening start republished
the previous window in full. `close_window`'s `min(mark, item_start)` exists to
stop a backwards clock from inverting a span, but a start stamp left in place
after its turn was PUBLISHED is not a backwards clock — it is a stale value
sitting before the mark, so the guard reopened the next window back at the
previous turn's start. Reproduced by driving the real state object: 3000 ms of
generation published for a 2000 ms turn, which `decompose_run.py` would read as
a large negative residual and the evalboard would simply sum. The stamp is now
cleared at the flush alongside the mark and the span list, for the same reason
they are: it has been spent. Regression test on both harnesses.
`close_window`'s own docstring had gone stale in the way it was written to
prevent. Phase 2 wrote it, then 3/6 gave pi the mark it said pi lacked and 5/6
migrated the antigravity window it said the signature could not express — so
the shared helper disagreed with the parity doc about which harnesses use it.
The gate script now counts turns it cannot time at all. They were the one
exclusion with no tally, in a file built around not discarding evidence
silently.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* test(harness): stamp the two codex fixtures that timed themselves with now()
`c_reasoning_placeholder` and `h_no_turn_completed_crash` injected no item
stamps, so `_flush_message` took `_ms_to_dt(None)` for BOTH window bounds —
two adjacent `datetime.now()` reads. They collide at microsecond resolution
often enough that `assert_timing_captured`'s `completed_at > started_at` failed
roughly one run in twenty under parallel load, naming a different scenario each
time and giving no hint of the cause. Two separate reviewers of this branch hit
it on two different scenarios.
Real bounds fix it, at the cost of joining `FICTIONAL_DURATIONS`: integer-ms
SDK stamps cannot reconcile against a replay that runs in under a millisecond.
That trade is stated where the set is defined. It costs little — a window of
width zero reconciled trivially, so the identity check it gives up was
near-vacuous, and what replaces it is a stable bounds-span assertion.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* docs(harness): register that the golden corpus cannot see a timing value move
A whole phase of the timing plan was written expecting the golden master to go
red when generation numbers changed. It never did: the scrubber masks every
timing value, and the one assertion that reads magnitudes is one-sided. Record
what closing it would actually take, since it is more than a tolerance
constant.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
* feat(timing): 1/7 — a committed, ms-exact magnitude sensor
Nothing in the suite could see a timing VALUE move. The golden corpus masks
`generation_duration_ms`, both window bounds, both `execution_*_at` stamps and
both head/tail fields to a placeholder, and its identity check is one-sided
(`overshoot <= ...`), so an UNDERCOUNT — the defect class this area keeps
producing — passed every test. A prototype of the next phase changed published
generation figures on two harnesses and left all 5340 tests green.
`tests/test_timing_identity_contract.py` is that sensor. Each of the five
harnesses drives its own reducer off a clock the test moves by hand, then feeds
the messages and commands it produced through a real `EventCollector` — the
same seam production measures the head and tail at — and asserts
head + Σ generation + UNION(tool) + tail == the scripted span
with `pytest.approx`, an equality and so two-sided. Magnitudes are real only
where a scripted clock makes them real, which is why this cannot live in
`_scrub.py`: those replays run in ~0.3 ms of synthetic wall clock, where a
relative bound passes essentially anything. That file gains one docstring
paragraph saying where the two-sided check went and why, and no code change.
`test_the_sensor_sees_a_window_that_stops_tiling` is the gating mutation check,
committed rather than attested: it re-drives the pi case with tiling defeated —
the defect pi actually shipped — and asserts both the exact 600 ms the mutation
loses and that the identity assertion fires. `test_every_built_in_harness_has_a_case`
derives its set from `AgentKind` (not the open registry, which a third-party
plugin also populates), so a sixth built-in harness fails here rather than
shipping unmeasured.
`coder_eval.timing.union_ms` extracts the `min`/`max`/`busy_ms` tail the golden
sensor and the live residual gate had each copied. The shared corpus gains a
`union_cases` array replayed by BOTH suites — TypeScript through
`toolExecutionMs`, which derives its own extent and was the untested half.
CI gets the live two-sided gate at no infrastructure cost: the smoke-pass step
already runs a real agent and leaves real `task.json` files, so
`decompose_run.py --max-residual-pct 5` is one step against them. It covers
claude-code only (`experiments/default.yaml`), which the step name says.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* test(harness): 2/7 — OpenCode and Pi get a corpus worth replaying
They were the two newest reducers, the two that shipped the generation-mark
defect, and the two with the thinnest golden corpus: 2 scenarios each against
9 for claude and 8 for codex. OpenCode now has 5 and Pi 6.
Each gains the three shapes the older harnesses already cover — two tiled
generations with a tool between them, an orphan force-closed at finalization,
and a crash whose partial record must survive — plus, on Pi, the duplicate
`turn_end` its reducer explicitly promises to survive and that had a unit test
and no snapshot. The crash scenarios need an `expects` knob, so both scenario
dataclasses now carry the one `ClaudeScenario` already had, for the same
reason: a crash partial is a real capture path and nobody was comparing it
against a snapshot on these two harnesses.
Only `opencode_c_multi_step_tiling` is exempted from the identity check, and
the reason is structural rather than convenient: OpenCode takes its tool bounds
from the CLI payload, so every tool-resolving scenario of that harness injects
millisecond stamps into a sub-millisecond replay. Pi derives its from its own
TurnClock, so all four of its new scenarios stay inside the sensor.
Also corrects the pi fixtures' text event. `_handle_line` dispatches on the
outer `type`, and `text` is in neither the dispatch chain nor the recognized
vocabulary, so the bare `{"type": "text"}` line `a_single_text_turn` used
reached no handler: it captured nothing, and the snapshot's `agent_output` was
empty under a scenario named for text. The new `_text()` helper emits the real
`message_update` / `text_delta` shape, which is why that snapshot changes.
Two Pi defects the new snapshots make visible are CAPTURED AND ANNOTATED, not
fixed — this phase changes no `src/` file:
* `f_duplicate_turn_end` shows `turn_text_parts` / `turn_tool_ids` cleared only
in `on_turn_start`, so the second `turn_end` republishes the first turn's
text as its own assistant message. `on_turn_end`'s own comment makes exactly
this argument for the sibling `turn_started_at` reset it does perform.
* `d_orphaned_tool` shows a `duration_ms` and a subtracted span published for a
call that never returned — `_close_tool` guards on
`execution_started_at is not None` while its comment claims it guards on
"resolved", and the `execution_completed_at` is only the instant the sweep
ran. claude-code leaves that field None here on purpose.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* fix(timing): 3/7 — a naive/aware mix names the pair that disagreed
`decompose_turn` subtracts stamps it is handed. Hand it one aware and one naive
and Python raises "can't subtract offset-naive and offset-aware datetimes" from
inside the arithmetic, straight out of `EventCollector.build_turn_record`,
killing the turn with a message naming neither the field nor the harness.
`busy_ms` has the same exposure one level down, where the clipping compares
each span against the window bounds and the bare error reads "can't compare".
`_require_same_awareness` replaces both with a statement of which pair
disagreed, which side is aware, and what to do about it. One helper rather than
two inline guards, so there is one wording; a test drives all five call sites
and asserts the advice half is identical across them.
This is unreachable from this repo, and that is the point. Every stamp in
`agents/` and `streaming/` is a naive `datetime.now()` — zero `timezone.utc`,
`astimezone` or `tzinfo` hits — so the guard protects the SEAM, not a live
defect. Which is also why it is a guard and not a lint rule: the exposure that
actually matters is a third-party agent registered through the
`coder_eval.plugins` SPI, which lives outside `src/coder_eval/agents/` and which
no rule scoped to that directory could ever see. The message addresses that
reader directly, and tells them to make their stamps naive local rather than
normalizing here — so their tool spans and their window bounds keep one basis.
Only the MIX raises: all-naive and all-aware both work unchanged.
An empty span list is checked NOT AT ALL, bounds included. The comprehension
never runs, nothing is compared and nothing is subtracted, so there is no pair
for the guard to be about, and raising there would reject a call that has always
returned `0.0`. The mixed-bounds empty case is what pins this — the naive one
passes either way and cannot tell the two behaviours apart.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* feat(timing): 4/7 — one meaning for harness_startup_ms, on all five
The field answered a different question per harness. codex, opencode and pi
measured the wall clock before their CLI emitted its first event. claude-code
and antigravity measured NOTHING: both stamped their first generation window's
mark when the turn state was built, before `AgentStartEvent` was emitted, so
`decompose_turn`'s `max(..., 0.0)` produced the `0.0` they published. A clamped
inversion presented as "measured, and instant" — the exact confusion CE058
exists to prevent everywhere else — while everything those harnesses spent
before their first model output was booked as the first generation instead:
~3.6 s per turn on claude-code and ~4.7 s on antigravity, inflating every
generation figure, the Generation split and the 10 s slow-generation bar on the
two most-used harnesses.
The head is now defined once, for all five: wall clock from the turn starting
until the harness first observed model output. That instant is also where the
harness opens its first generation window, so the two buckets stay disjoint and
the four-bucket identity still closes — verified to the millisecond by
`test_timing_identity_contract.py`, which is the only thing in the suite that
could see this move. `GOLDEN_REGEN=1` produces a ZERO diff: `SCRUB_KEYS` masks
every value that changed, which is the audit's P1 demonstrated on the very
change it was written about.
Both re-seeds fire ONCE per turn. `message_start` and `Step` each arrive many
times, and re-seeding on every one would stop the windows tiling and drop the
gap before the next emission into no bucket — the defect Pi shipped with.
Neither flag needs a reset: a fresh turn state is built per `communicate()`.
Antigravity's is gated on the step SOURCE. The SDK streams SYSTEM and USER
steps as well as MODEL ones, and seeding on those would put the mark before the
model spoke and hand the remainder back to the first generation — the defect
being fixed, one layer in. An unrecognized source degrades to the old
behaviour rather than to a wrong one.
The rejection this overturns rested on claude-code being an in-process SDK. It
is not: `claude-agent-sdk` spawns the `claude` CLI over `anyio.open_process`
and `_pump_messages` calls `query()` once per `communicate()` — a fresh CLI per
turn. All 8 sites asserting otherwise are gone; the old reasoning is kept in
HARNESS_PARITY.md as labelled HISTORY rather than deleted.
Nor was antigravity the in-process counterexample it was described as. It
spawns a `localharness` binary too — once, in `start()`, held across turns. The
distinction that matters is WHEN a harness spawns its process, not whether, and
that is what the docs now say.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* refactor(timing): 5/7 — one tool-subtraction, at the collector seam
Tool execution came out of a generation window in five places: four inside
`close_window` as the reducer flushed, claude-code once at finalization. The
head and the tail were already computed ONCE, centrally, at the collector — and
that asymmetry was the complexity. Every timing defect on this branch lived in
the per-reducer bookkeeping around the subtraction rather than in the
subtraction itself: when to reset a span list (clearing it at `step_start` wiped
a span before the flush could subtract it, a 100% overstatement of that window),
when to clear a spent start stamp (a second flush with no intervening start
republished the previous span — 3000 ms of generation for a 2000 ms turn), when
to advance the mark.
`EventCollector.subtract_tool_time` now does it once, for all five. A reducer
publishes the RAW window and keeps only the genuinely harness-shaped decision,
which is where that window opens. Three span lists, their reset rules, the
bounding of still-open calls and `close_window`'s two span parameters are gone.
CE063 stops a sixth harness rebuilding them; CE061 is exemption-free, since
claude-code now calls the same shrunken helper as the other four.
Grouping is on the BOUNDS, not `message_id`. Codex splits one window into
thinking and action sub-messages that share a pair of bounds; subtracting from
each separately takes the overlap twice and the parts stop summing. OpenCode and
Pi can legitimately carry `message_id is None`, so keying on the id would
collapse a turn's id-less messages into one group instead.
Non-mutating, and the reason is aliasing rather than repeated calls: every agent
builds its terminal event as `AgentEndEvent(messages=list(...))`, which copies
the LIST and not the messages, so an in-place write would reach back into the
agent's own live state from the collector.
Two behaviour changes, each with its own named test rather than hidden in a
number:
* A call still open when a window closes is no longer subtracted at that
boundary. The collector sees every span at once, so it comes out of the
windows the call's REAL interval overlaps, once it resolves. A call that never
resolves was never timed and contributes nothing.
* claude-code's window is measured on ONE clock. Its duration was a monotonic
delta while its bounds were wall stamps — the split `TurnClock` exists to
remove — and central subtraction makes that untenable, because it clips WALL
spans against those WALL bounds. `turn_start_time` stays monotonic: the
deadline must not move when the wall clock steps.
Also fixes the P3 thread mix, and the divergence fixing it created. `_overhead_ms`
filtered its generations to the main thread and passed EVERY command, so its
claim to keep all four buckets on one thread held only because a child nests
inside the parent Agent call. Filtering there alone then made the LIVE residual
gate compute a different tool total than the harness — the worst place for a
drift, since it is the only two-sided sensor. All three implementations
(`_main_thread_tool_spans`, `_scrub.py`, `decompose_run.py`) now filter, and
`TestTheThreeToolUnionsAgree` pins them together.
`tests/_fixtures/timing_runs/` commits one scrubbed run per harness. Its README
states plainly what the plan asked it to be and what it cannot be: the script
reads STORED fields, so over a fixed corpus it prints the identical table before
and after any code change. Its own claude-code row still reconciles at -481 ms
and books a 0.0 head — both long fixed — which is the argument.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* feat(reports): 6-7/7 — the offline report carries the buckets; a TS None-vs-0 guard
**Phase 6.** `reports_html.py` is described in CLAUDE.md as the evalboard's
static twin, and it rendered only Total Latency / Turns / Avg Turn Latency — so
anyone reading the artifact rather than the dashboard got none of the wall-clock
accounting this branch added. The card now shows Startup / Generation / Tool
exec / Teardown / Unaccounted.
The arithmetic is in `reports_stats.turn_time_buckets` and the renderer only
formats, because putting the sums in `_render_generation_metrics` would make it
the fourth place these buckets are aggregated. For the same reason the
main-thread span rule is no longer restated there: `main_thread_tool_spans` moves
out of `EventCollector` to module level and both consume it. A second typed copy
of that rule is exactly how two surfaces come to publish two different tool
totals for one run.
Three None-vs-0 distinctions the first draft got wrong, each measured:
* `tool_ms` returned `0.0` for a run that recorded no bounded span at all,
rendering `0ms` — "measured and instant" — where nobody measured anything. It
is `None` unless some turn recorded a span.
* `unaccounted_ms` was computed from a `duration_seconds` that is a
non-optional float defaulting to `0.0`, so an untimed run rendered a
fabricated negative residual instead of a dash. The evalboard keeps its own
null for this case.
* The docstring claimed every bucket went `None` when nothing measured it,
while two of five could not.
Display and arithmetic differ on purpose and say so: an unmeasured bucket shows
as an em dash and sums as `0.0`, so its time surfaces in Unaccounted rather than
vanishing — the rule `decompose_run.py::_turn_buckets` already applies. The
Unaccounted label states that it includes sandbox setup and grading, so it is
not comparable with the per-turn residual.
**Phase 7.** `no-zero-coalesce.test.ts` is the TypeScript counterpart to CE058.
There is no eslint in `evalboard/`, so it is a vitest source scan. An ALLOWLIST
rather than a ban, because the residual arithmetic uses `?? 0` correctly —
subtracting only what was measured is the whole point — so a blanket ban fires
on right code.
It scans for timing names (`Ms`, `Seconds`, `duration`) rather than every
`?? 0`, and that narrowing is deliberate: a blanket scan matches 58
occurrences, about half token and cache buckets where zero is a fine answer
because tokens are counted rather than measured. An allowlist that long is one
nobody reads. Blind spots are declared in the file. Two meta-tests keep it
honest — a negative control, so the scan cannot pass by matching nothing, and an
assertion that every allowlist entry is still present, so an entry cannot
outlive its reason. Both caught real problems in the allowlist before it landed.
`AssistantMessage.message_id` no longer names one harness of five. Its census is
taken from the agents rather than from the plan, which had it off by one: three
schemes, not two — passed through on claude-code, opencode and pi; synthesized
on codex and antigravity; and claude-code synthesizes in exactly one place, the
sub-agent terminal message that is never streamed.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* fix: code review fixes for turn-timing-p0-p3
Two independent final reviews over the whole 7-phase change. No Critical and no
High: the Phase 4 x Phase 5 interaction was attacked directly (a re-seeded mark
landing inside a tool span; an open call clipped differently now that the
collector subtracts) and the algebra holds on every harness.
The findings that mattered were all the same shape — a claim that had stopped
being true:
* `tests/test_timing_identity_contract.py` was a FIFTH tool-union
implementation that disagreed with the other four. It filtered generations to
the main thread and then unioned every command, so the sensor built to police
this identity was asserting a different one. Latent only because no case has a
sub-agent command yet — the first one added would have reported a false
regression. It now calls production's own `main_thread_tool_spans`.
* CE061's docstring and violation MESSAGE still described the architecture
Phase 5 deleted: a permanent claude-code suppression that no longer exists,
and an instruction to subtract the tool union inside the reducer, which CE063
now forbids and which would recreate double subtraction. Both models flagged
it independently. It now states what it owns and points at CE063 for the rest.
* `HARNESS_PARITY.md`'s `[^identity]` footnote still said the only committed
sensor is one-sided, in the same file that gained 269 lines describing the
two-sided one. All three sensors are now named with what each can and cannot
see.
* The `opencode_c_multi_step_tiling` exemption claimed "the snapshot still
records [the tiling]". It does not: `SCRUB_KEYS` masks both bounds and the
duration, so nothing about where a window opened survives into the JSON. The
comment now says what the snapshot actually pins (structure, blocks, tokens)
and where the tiling IS asserted.
Also fixed, from the same pass: antigravity's signal is the first MODEL-source
`Step` and the table said "the first `Step`"; claude-code's seed docstring still
said "the two marks" after Phase 5 deleted the monotonic one; the seed's
degradation list did not mention that `include_partial_messages=false` reaches
it through `-D`; the TS scanner's comment-stripping blind spot was undeclared;
and two counts in `harness-candidates.md` disagreed with the file they describe.
CE062 is now documented as deliberately unused. The ids jump 061 to 063, and an
id is a permanent anchor — a suppression carrying 062 in an older branch must
never start meaning something new.
One test was removed rather than repaired.
`test_generation_and_tool_time_account_for_the_turn` asserted the buckets cover
at least half the turn, on the REAL clock. Phase 4 added the head to that sum
and kept the bound; under `-n auto` the denominator inflates while the measured
buckets do not, so it failed as a scheduler-noise detector. The share it reached
for is asserted exactly, on a scripted clock, in the contract test.
NOT fixed, deliberately: a reviewer flagged `EventCollector` retaining
`_commands` and `_turn_starts` across a retry's `AgentStartEvent` as High. It is
pre-existing and untouched here, and the claimed blast radius is wrong — the
persisted record, the reports and `max_turns` all read the agent's OWN collector,
which is fresh per `communicate()`. Only `EarlyStopWatcher`'s long-lived
collector accumulates, where carrying a turn's whole engagement across retries
is arguably what a live verdict wants. Recorded as a follow-up rather than
changed blind.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* docs(harness): register what the turn-timing run could not guard
Six entries, each with why it is not a rule today rather than just what it is.
Two are prose-vs-artifact defects a lint rule would have to parse English to
catch; one needs a decision about intent before any guard could be right; three
are code defects the golden corpus now captures but that were out of the plan's
scope to fix.
The three-way tool-union divergence this run also surfaced is NOT here: it was
guarded the same day by TestTheThreeToolUnionsAgree, which is the point of the
promote-or-defer split.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DLBDYGjbKkJ4Xg9a2QtabU
* fix(timing): a TurnClock for claude-code, and pi's two captured defects
Clears the three entries registered under "From the turn-timing P0–P3 run"
in .claude/harness-candidates.md.
claude-code now derives every wall stamp a turn records from one injected
`TurnClock`: both window bounds, the fallback tool timestamp, and the tool
span. Sharing raw `datetime.now()` had already removed the bounds-vs-span
disagreement; it left both sides naive-local, where a DST transition or an
NTP step inside a turn lands directly in a generation window — an hour-long
jump in a millisecond field, on nightly runs that start at 04:18 and last
hours. `_resolve_pending_command` takes the reading as an argument rather
than reading a clock of its own: it stamps the span that is clipped against
those bounds, so a second basis at that one call site would put two clocks
inside one subtraction. `turn_start_time` and the turn deadline stay raw
monotonic — a deadline must not move when the wall clock steps.
One raw `datetime.now()` is left deliberately, on the synthesized sub-agent
terminal message, and the code says why: those bounds are an admitted
placeholder that `subtract_tool_time` and `_overhead_ms`'s head/tail
bracket both exclude, so no arithmetic reads them and there is no basis to
share.
The clock is INJECTED, not read from a module global. That is load-bearing
for the sensor rather than cosmetic: a derived stamp escapes a
monkeypatched `datetime`, so the old patch would have left
tests/test_timing_identity_contract.py measuring the real clock and passing
by accident. It is re-pointed at the injected clock, keeps `time.monotonic`
patched (the tool duration is still monotonic-measured), and reverting the
conversion now fails it by ~10^7 ms.
pi `_close_tool` stamps `execution_completed_at` and derives `duration_ms`
only when the status is not UNRESOLVED — the guard the old comment claimed
and the code did not have (it tested `execution_started_at is not None`,
which an orphan passes). The sweep's instant is not a completion anybody
observed, and the manufactured pair read as a measured span the collector
took back out of a generation window the tool never occupied.
`execution_started_at` is kept: the CLI really did emit that start, and one
bound alone forms no span.
pi `on_turn_end` clears `turn_text_parts` / `turn_tool_ids` beside
`turn_started_at`, on the argument that comment already made — all three
have been SPENT into the message just appended. The timing half of that
reset had a unit test that stayed green while the content half republished
the previous turn's text as its own assistant message and re-listed the
same `tool_use_ids`, so the two are now asserted separately.
Both pi defects were captured in committed goldens. Regenerated with
GOLDEN_REGEN=1, and the run before it failed on exactly those two
scenarios: pi_d loses a `duration_ms` and an `execution_completed_at` to
`null`, pi_f's second message loses the republished text block. Nothing
else moved.
Registered but NOT fixed: antigravity stamps a completion on its own orphan
sweep the same way (no `duration_ms`). `timing.decompose_turn`'s docstring
reasons about that stamp landing in the tail and the antigravity_d residual
was measured against it, so it needs its own fixture re-derivation rather
than a ride-along.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FpDo37ypvLjLiWXFsEkg6k
* fix(timing): stamp the turn bracket off the turn clock (CE064)
`decompose_turn` computes the head and the tail by subtracting a generation
window bound from an AgentStart/AgentEnd timestamp, so the two have to
share a basis. The three harnesses that own a `TurnClock` derived their
window bounds from it and let the bracket fall back to
`StreamEvent.timestamp`'s `default_factory=datetime.now` — a
monotonic-derived stamp and a raw wall stamp inside one subtraction, which
is the exact split `TurnClock` exists to remove, reintroduced at the one
seam the clock did not own.
Measured, not hypothetical. Instrumenting `decompose_turn` on a live
antigravity turn printed:
PROBE tail: elapsed=-0.017000ms busy=0.000000ms raw=-0.017000ms
last_completed = 09:05:22.033099
agent_end = 09:05:22.033082
an AgentEndEvent stamped 17 us BEFORE its own last message finished, which
cannot happen: the event is constructed strictly after the final flush.
`decompose_turn` clamped the negative and published `0.0` — "measured, and
instant", the CE058 confusion reached from the other direction — for a
harness whose real tail is ~0.1 ms. After the fix the same task records
0.035 ms, a real measurement rather than a clamp.
It only showed on one harness because the drift between the two clocks is
tens of microseconds, so it can flip a sign only where the true interval is
itself that small. Antigravity is the only harness that spawns its process
once in `start()` and holds it across turns, so nothing happens between its
last flush and its AgentEndEvent; every other harness books a head of
0.2-6 s and a tail of 7-543 ms, where the drift is invisible. Invisible is
not absent, so the fix is applied at every clocked site: that is what makes
the subtraction single-basis rather than usually-close, which is not a
property a millisecond field can rest on.
Note this was widened by the previous commit. claude-code's bounds used to
be raw `datetime.now()` — the same basis as the events — so its subtraction
was single-basis until the TurnClock conversion.
CE064 keeps it fixed: in `agents/`, a module that imports `TurnClock` must
pass an explicit `timestamp=` to AgentStartEvent/AgentEndEvent. Scope is
DERIVED from that import, never a harness list — codex and opencode take
their spans from the CLI's own epoch stamps and deliberately have no clock,
so a raw `datetime.now()` bracket is consistent with their bounds and the
rule must not fire on them; the day either adopts a clock the rule starts
applying with no edit here. The rule checks presence, not spelling, because
the three harnesses reach their clock three different ways and pinning a
spelling would make it a syntax check on their internals; what it removes
is the silent case, a default nobody chose, which is the one that shipped.
Mutation-checked against the real tree.
`_model_ctor.reaches_models_module` is generalized to `reaches_module` so
CE064 reuses the binding resolver rather than copying it (the argument that
file already makes for CE060/CE061 sharing it). Its relative-import matcher
compared a single `rpartition` tail, which was right only while every
target was one segment deep and silently missed `coder_eval.streaming.events`
outright — a rule blind for a whole file rather than a near miss. It now
matches any segment-wise suffix. CE060/CE061 behaviour is unchanged.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FpDo37ypvLjLiWXFsEkg6k
* feat(timing): name the setup and grading phases; union a row's tool time
Three fixes to make the published numbers mean what they say.
1. A row's EXEC cell is the UNION of its tool calls, not their sum, and
goes through the same `toolExecutionMs` the header strip uses so the two
cannot answer one question two ways. Summing double-books concurrent
calls: one measured antigravity turn issued two `sleep 2` Bash calls
overlapping almost entirely and the cell read 4.1s for 2.1s of wall
clock — more tool time in one message than the whole task's Tool exec
cell, which is impossible on its face. The comment on that line claimed
parity with the strip; that stopped being true when `toolExecutionMs`
was changed to union and this line was not. Expanding a row still shows
each call's own wall clock, so sequential calls add up to the row total
and concurrent ones deliberately do not — which is where the
concurrency becomes visible.
2. `EvaluationResult.setup_ms` and `grading_ms`, so the evalboard's
Unaccounted cell i…
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
3 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Per-task wall clock, LLM generation time and tool-execution time were only
correct for one harness. Measured across 4
run.json+ 46task.jsonfiles:Antigravity recorded no generation time at all — the reducer read
datetime.now()once per flush and passed it as both message bounds with ahardcoded
generation_duration_ms=0.0, so every task page showed0msofgeneration and a
0%thinking/tool/text breakdown, for months, with nothingfailing. Codex discarded the millisecond timestamps its SDK already delivers
and published the SDK item's own
duration_msinstead:0.0for 70 of 211sampled commands, absent for 25 more, and no execution bounds at all, so no
Codex tool call could be placed on a timeline.
What changed
The contract.
AssistantMessage.generation_duration_msis nowfloat | None.Nonemeans never measured;0.0means measured and tookno measurable time. Every producer that used to conflate them is fixed —
including two the audit missed: Claude published a measured
0.0for everycommand force-closed without a tool result, and the simulator's trailing turn
reported
0s, halvingavg_turnin the HTML report for every simulation task.Generation time excludes tool execution. Four of five harnesses interleave
tool calls into a single generation window, so the span between a message's own
bounds legitimately contains time the model did not spend generating. All four
now subtract the union of the closed tool intervals, clipped to the window,
through one shared helper. The union matters: these harnesses run tools
concurrently, and summing durations over-subtracts by exactly the overlap —
four concurrent 400ms calls inside a 1000ms window total 1600ms and clamp
generation back to the
0.0this PR exists to remove.Attribution. A mixed-kind emission's generation time and output tokens are
apportioned by one content-size weight vector. Previously all the time went to
the first block kind a priority chain tested (98.5% thinking on codex, 99.8% on
delegate), and the same output tokens were counted twice — once to thinking,
once to the tool — for 93% of Delegate's emissions.
The page says what it cannot account for. A new
Unaccountedcell showswall clock minus generation minus tool execution, so the figures are displayed
against what they must reconcile to rather than each being individually
well-formed. The run-list
Durationcolumn now counts only rows that executed:a codex nightly rendered "1300 tasks · 15h 29m" describing 397 tasks.
Guardrails
syntactic forms, one id, including the
if x is None: x = 0.0guard where alive instance was hiding and the
model_copy(update={...})dict akeyword-only rule cannot see.
AssistantMessagemay not take one clock read as both bounds.It exempts a call that passes
generation_duration_ms=None: saying "no windowwas measurable" in the field built to say it is not a claim two stamps have to
support.
assert_timing_captured— a replay-based golden sensor. An AST rule cannotsee that an SDK returned
0.0; this runs the real reducer and asserts aresolved command carries both bounds and a duration, and that a turn which
streamed a generation reports a positive window whose stamps actually span it.
antigravity,opencodeandpihad no recorded stream at all — the three whose timing was worst. Thecoverage test derives from
AgentKindwith an allowlist of exclusions, so thenext harness cannot ship timing-blind.
Numbers that move (correct, not regressions)
smaller
thinkingMsand a no-longer-double-countedthinkingOutputTokensfeed it.
avg_command_time_ms. A Claude command force-closed without a result nowleaves both sides of the average instead of dragging it toward zero; and on
Codex,
fileChangeand generic tool calls carry a duration they previouslylacked, so the figure now covers every tool call rather than shell commands
alone.
duration_mschanged meaning — the item's lifecycle (queueing andapproval included) rather than the SDK's narrower command-run figure, which it
deliberately overrides.
docs/agents/HARNESS_PARITY.mdgains a## Timing capturesection covering allfive harnesses, and names the two divergences left open (Antigravity's
orphan-poll wait, Delegate's missing bounds — both out of tree or deliberately
deferred).
Verification
make verify— 5209 passed, coverage 92.70%make evalboard-verify— 724 passed,tsc --noEmit+next buildcleanmake lint— 555 (CE058/CE059 included)field, so no registry, merge-layer or
-Dsurface is touched.Reviewed phase by phase, then once across the whole diff. That last pass is what
caught OpenCode and Pi carrying the identical double-count — which no phase
covered and an earlier draft of the parity table wrongly denied.
🤖 Generated with Claude Code