fix(timing): account for generation and tool time on every harness - #164
Open
uipreliga wants to merge 10 commits into
Open
fix(timing): account for generation and tool time on every harness#164uipreliga wants to merge 10 commits into
uipreliga wants to merge 10 commits into
Conversation
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>
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}
|
|
||
|
|
||
| def _install_clock(monkeypatch, clock: _Clock) -> None: | ||
| import coder_eval.agents.antigravity_agent as agent_module |
| WINDOW_END = datetime(2026, 1, 1, 12, 0, 1) # a 1000ms step | ||
|
|
||
| def _finish_step(self, monkeypatch, spans): | ||
| import coder_eval.agents.opencode_agent as agent_module |
| WINDOW_END = datetime(2026, 1, 1, 12, 0, 1) # a 1000ms turn | ||
|
|
||
| def _finish_turn(self, monkeypatch, spans): | ||
| import coder_eval.agents.pi_agent as agent_module |
…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>
|
|
||
| @staticmethod | ||
| def _finish_at(monkeypatch, state, *, step_start, now): | ||
| import coder_eval.agents.opencode_agent as agent_module |
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
2 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