Commit 6166b1e
feat(timing): book each turn's head and tail as their own buckets (#165)
* 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…1 parent 587f2e3 commit 6166b1e
104 files changed
Lines changed: 11932 additions & 529 deletions
File tree
- .claude
- .github/workflows
- docs/agents
- evalboard
- app/runs/[id]/[...task]
- __tests__
- lib
- __tests__
- scripts/timing
- corpus
- src/coder_eval
- agents
- evaluation
- models
- streaming
- tests
- _fixtures
- golden_streams
- expected
- report_snapshots
- lint
- rules
Some content is hidden
Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.
Large diffs are not rendered by default.
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
593 | 593 | | |
594 | 594 | | |
595 | 595 | | |
| 596 | + | |
| 597 | + | |
| 598 | + | |
| 599 | + | |
| 600 | + | |
| 601 | + | |
| 602 | + | |
| 603 | + | |
| 604 | + | |
| 605 | + | |
| 606 | + | |
| 607 | + | |
| 608 | + | |
| 609 | + | |
| 610 | + | |
596 | 611 | | |
597 | 612 | | |
598 | 613 | | |
| |||
Large diffs are not rendered by default.
Large diffs are not rendered by default.
Lines changed: 333 additions & 10 deletions
Large diffs are not rendered by default.
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
13 | 13 | | |
14 | 14 | | |
15 | 15 | | |
16 | | - | |
| 16 | + | |
17 | 17 | | |
18 | 18 | | |
19 | 19 | | |
| |||
318 | 318 | | |
319 | 319 | | |
320 | 320 | | |
| 321 | + | |
| 322 | + | |
| 323 | + | |
| 324 | + | |
| 325 | + | |
321 | 326 | | |
322 | 327 | | |
323 | 328 | | |
| |||
332 | 337 | | |
333 | 338 | | |
334 | 339 | | |
| 340 | + | |
| 341 | + | |
| 342 | + | |
| 343 | + | |
| 344 | + | |
| 345 | + | |
| 346 | + | |
| 347 | + | |
| 348 | + | |
| 349 | + | |
| 350 | + | |
| 351 | + | |
| 352 | + | |
| 353 | + | |
| 354 | + | |
| 355 | + | |
| 356 | + | |
| 357 | + | |
| 358 | + | |
| 359 | + | |
| 360 | + | |
| 361 | + | |
| 362 | + | |
| 363 | + | |
| 364 | + | |
335 | 365 | | |
336 | 366 | | |
337 | 367 | | |
| |||
381 | 411 | | |
382 | 412 | | |
383 | 413 | | |
384 | | - | |
| 414 | + | |
| 415 | + | |
| 416 | + | |
| 417 | + | |
| 418 | + | |
| 419 | + | |
| 420 | + | |
| 421 | + | |
| 422 | + | |
| 423 | + | |
| 424 | + | |
385 | 425 | | |
386 | 426 | | |
387 | 427 | | |
| |||
398 | 438 | | |
399 | 439 | | |
400 | 440 | | |
401 | | - | |
402 | | - | |
| 441 | + | |
| 442 | + | |
| 443 | + | |
| 444 | + | |
| 445 | + | |
| 446 | + | |
| 447 | + | |
403 | 448 | | |
404 | 449 | | |
405 | | - | |
| 450 | + | |
| 451 | + | |
| 452 | + | |
| 453 | + | |
| 454 | + | |
| 455 | + | |
| 456 | + | |
| 457 | + | |
| 458 | + | |
| 459 | + | |
406 | 460 | | |
407 | 461 | | |
408 | 462 | | |
| |||
419 | 473 | | |
420 | 474 | | |
421 | 475 | | |
422 | | - | |
423 | | - | |
424 | | - | |
425 | | - | |
426 | | - | |
| 476 | + | |
| 477 | + | |
| 478 | + | |
| 479 | + | |
| 480 | + | |
| 481 | + | |
427 | 482 | | |
428 | | - | |
| 483 | + | |
429 | 484 | | |
430 | 485 | | |
431 | 486 | | |
432 | 487 | | |
433 | 488 | | |
434 | 489 | | |
| 490 | + | |
| 491 | + | |
| 492 | + | |
| 493 | + | |
| 494 | + | |
| 495 | + | |
| 496 | + | |
| 497 | + | |
| 498 | + | |
| 499 | + | |
| 500 | + | |
| 501 | + | |
| 502 | + | |
| 503 | + | |
| 504 | + | |
| 505 | + | |
435 | 506 | | |
436 | 507 | | |
437 | 508 | | |
| |||
445 | 516 | | |
446 | 517 | | |
447 | 518 | | |
448 | | - | |
| 519 | + | |
| 520 | + | |
| 521 | + | |
| 522 | + | |
| 523 | + | |
| 524 | + | |
| 525 | + | |
| 526 | + | |
| 527 | + | |
| 528 | + | |
| 529 | + | |
| 530 | + | |
| 531 | + | |
| 532 | + | |
| 533 | + | |
| 534 | + | |
| 535 | + | |
449 | 536 | | |
450 | 537 | | |
451 | | - | |
| 538 | + | |
452 | 539 | | |
453 | 540 | | |
454 | 541 | | |
| |||
771 | 858 | | |
772 | 859 | | |
773 | 860 | | |
| 861 | + | |
| 862 | + | |
| 863 | + | |
| 864 | + | |
| 865 | + | |
774 | 866 | | |
775 | 867 | | |
776 | 868 | | |
777 | 869 | | |
778 | 870 | | |
779 | 871 | | |
780 | 872 | | |
| 873 | + | |
| 874 | + | |
| 875 | + | |
| 876 | + | |
| 877 | + | |
| 878 | + | |
| 879 | + | |
| 880 | + | |
781 | 881 | | |
782 | 882 | | |
783 | 883 | | |
| |||
816 | 916 | | |
817 | 917 | | |
818 | 918 | | |
| 919 | + | |
| 920 | + | |
| 921 | + | |
| 922 | + | |
| 923 | + | |
819 | 924 | | |
820 | 925 | | |
821 | 926 | | |
| |||
1445 | 1550 | | |
1446 | 1551 | | |
1447 | 1552 | | |
1448 | | - | |
1449 | | - | |
1450 | | - | |
| 1553 | + | |
| 1554 | + | |
| 1555 | + | |
| 1556 | + | |
| 1557 | + | |
| 1558 | + | |
| 1559 | + | |
| 1560 | + | |
| 1561 | + | |
| 1562 | + | |
| 1563 | + | |
| 1564 | + | |
| 1565 | + | |
| 1566 | + | |
| 1567 | + | |
| 1568 | + | |
1451 | 1569 | | |
1452 | 1570 | | |
1453 | 1571 | | |
| |||
1492 | 1610 | | |
1493 | 1611 | | |
1494 | 1612 | | |
1495 | | - | |
| 1613 | + | |
1496 | 1614 | | |
1497 | 1615 | | |
1498 | 1616 | | |
| |||
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
365 | 365 | | |
366 | 366 | | |
367 | 367 | | |
| 368 | + | |
| 369 | + | |
| 370 | + | |
| 371 | + | |
| 372 | + | |
368 | 373 | | |
369 | 374 | | |
370 | 375 | | |
| |||
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
| 1 | + | |
| 2 | + | |
| 3 | + | |
| 4 | + | |
| 5 | + | |
| 6 | + | |
| 7 | + | |
| 8 | + | |
| 9 | + | |
| 10 | + | |
| 11 | + | |
| 12 | + | |
| 13 | + | |
| 14 | + | |
| 15 | + | |
| 16 | + | |
| 17 | + | |
| 18 | + | |
| 19 | + | |
| 20 | + | |
| 21 | + | |
| 22 | + | |
| 23 | + | |
| 24 | + | |
| 25 | + | |
| 26 | + | |
| 27 | + | |
| 28 | + | |
| 29 | + | |
| 30 | + | |
| 31 | + | |
| 32 | + | |
| 33 | + | |
| 34 | + | |
| 35 | + | |
| 36 | + | |
| 37 | + | |
| 38 | + | |
| 39 | + | |
| 40 | + | |
| 41 | + | |
| 42 | + | |
| 43 | + | |
| 44 | + | |
| 45 | + | |
| 46 | + | |
| 47 | + | |
| 48 | + | |
| 49 | + | |
| 50 | + | |
| 51 | + | |
| 52 | + | |
| 53 | + | |
| 54 | + | |
| 55 | + | |
| 56 | + | |
| 57 | + | |
| 58 | + | |
| 59 | + | |
| 60 | + | |
| 61 | + | |
| 62 | + | |
| 63 | + | |
| 64 | + | |
| 65 | + | |
| 66 | + | |
| 67 | + | |
| 68 | + | |
| 69 | + | |
| 70 | + | |
| 71 | + | |
| 72 | + | |
| 73 | + | |
| 74 | + | |
| 75 | + | |
| 76 | + | |
| 77 | + | |
| 78 | + | |
| 79 | + | |
| 80 | + | |
0 commit comments