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

.claude/harness-candidates.md

@@ -551,3 +551,62 @@ divergences, so the deferred-work record is one place. Measurements in
   candidate — a real bug needing its own change, with a decision about
   whether legacy records can be distinguished from current ones at all.
   Caught in: timing-capture final review (gpt-5.6-sol).
+
+- [x] ~~No golden-corpus assertion of the four-bucket identity.~~ **DONE.** The
+  fixture clocks were unified (`_rebase_notifications` / `_rebase_lines` shift
+  codex's 2027 base and opencode's month-old base onto the replay's own clock,
+  keeping every derived duration exact) and `assert_timing_captured` now
+  asserts `Σ generation + ∪ tool + head + tail` against `duration_seconds`.
+  Mutation-verified: reintroducing the defect fails
+  `test_antigravity_golden[d_orphaned_tool]`, which previously passed.
+  22 of 27 scenarios are checked. The remaining 5 are exempt via
+  `FICTIONAL_DURATIONS` for a reason rebasing cannot fix: they inject SDK
+  stamps in integer MILLISECONDS (17-900 ms of declared item time) while the
+  replay runs in well under one, so closing that last gap needs the agent's
+  own clock faked, not the fixtures' rebased.
+
+- [ ] **No TypeScript counterpart to CE058.** `evalboard/lib/runs.ts` and
+  `_sections.tsx` carry the same None-vs-0 contract as the Python side, and
+  `sumMeasured` implements it correctly, but nothing stops the next author
+  writing `?? 0` where an unmeasured value must stay null. Not a simple lint
+  rule: the residual arithmetic in `_sections.tsx` uses `?? 0` *correctly*
+  (subtract only what was measured), so a blanket ban fires on right code and
+  the rule needs a way to tell "publishing a value" from "consuming one".
+  Caught in: turn head/tail timing final review.
+
+- [ ] **`timing.py::decompose_turn` raises an uncaught `TypeError` on a
+  naive/aware datetime mix**, straight out of `EventCollector.build_turn_record`,
+  killing the turn. Unreachable today — every stamp in `agents/` and
+  `streaming/` is a naive `datetime.now()` (verified by grep: zero hits for
+  `timezone.utc` / `utcnow` / `astimezone`) — but nothing pins that invariant,
+  so the first agent to record an aware stamp discovers it at runtime.
+  Caught in: turn head/tail timing final review.
+
+- [x] ~~**`claude-code` does not subtract tool execution from its generation
+  windows.**~~ **FIXED** in `_ClaudeTurnState._subtract_tool_time_from_windows`,
+  which runs at finalization (it cannot run at flush time — a tool issued by an
+  earlier emission is still running when the next window closes). Re-measured
+  on the same task: 481 ms / 2.691% -> **1.4 ms / 0.006%** over four turns that
+  all carried overlapping tool calls. Original report kept below for the
+  reasoning.
+
+  ORIGINAL: The other four
+  harnesses subtract the union (`timing.py::busy_ms`); claude-code is exempted
+  on the reasoning that it "marks the end of the previous SDK event and reads
+  again when the next message arrives, so a tool's execution falls between two
+  windows rather than inside one". 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 live on a task with five parallel writes, five reads and two
+  concurrent `Bash` calls: the generation/tool overlap was **482 ms and 340 ms**
+  on two ~18-25 s turns, and the four-bucket residual came out at exactly
+  `-481 ms` / `-339 ms` — the overlap accounts for it to within 1.4 ms. The
+  other four harnesses overlapped by ~2.0-2.3 s on the same task and reconciled
+  to within 1.2 ms. Two claude-code turns with <1 ms of overlap reconciled to
+  within 0.1 ms, so the fault is precisely the missing subtraction.
+  Fix is to apply `busy_ms` in `on_assistant_message` as the other four do, but
+  it changes a PUBLISHED `generation_duration_ms` on the most-used harness, so
+  it needs its own golden regeneration and live pass. NOT introduced by the
+  head/tail work — generation-vs-tool timing predates it — but that work's
+  four-bucket identity is what made it visible.
+  Caught in: post-merge live verification of the head/tail buckets.

docs/agents/HARNESS_PARITY.md

@@ -25,21 +25,25 @@ wall clock its numbers account for.
 | Field | claude-code | codex | antigravity | opencode | pi |
 |---|---|---|---|---|---|
 | `generation_duration_ms` source | harness clock: previous SDK event → this message | SDK item stamps, minus tool execution inside the window | harness clock: previous flush → this flush, minus tool execution inside the window | harness clock per CLI step, minus tool execution inside the step | harness clock per CLI turn, minus tool execution inside the turn |
+| what the **first** window covers | turn start → msg0, so dispatch + TTFT are INSIDE it | the first SDK item's own start, so CLI boot + TTFT are OUTSIDE it | turn start → first flush, so dispatch + TTFT are INSIDE it | the first `step_start`, so CLI boot + TTFT are OUTSIDE it | the first `turn_start`, so CLI boot + TTFT are OUTSIDE it |
+| `harness_startup_ms` (turn head) | 0.0 — the window above already covers it | ~3.1 s — CLI boot fused with TTFT | 0.0 — the window above already covers it | ~2.5 s — CLI boot fused with TTFT | ~0.23 s — CLI boot fused with TTFT |
+| `harness_teardown_ms` (turn tail) | ~1.3 s | ~13 ms | ~7 ms | ~26 ms | ~19 ms |
 | tool `duration_ms` source | measured around the tool result | SDK `completed_at_ms − started_at_ms`; the item's own `duration_ms` only as a fallback | measured ACTIVE → DONE | measured around the tool event | measured around the tool event |
 | `execution_started_at` / `execution_completed_at` | derived from the measured duration | SDK stamps (both, or neither) | measured at ACTIVE / DONE | measured | measured |
 | `generation_completed_at` | set | `None` — see below | `None` | `None` | `None` |
-| `Σ generation + Σ tool ≈ turn duration` | yes | yes | yes | yes | yes |
+| `Σ generation + ∪ tool + head + tail ≈ turn duration` | yes | yes | yes | yes | yes |
 
 **`generation_duration_ms` is model-generation time, not `completed_at − started_at`.**
-Four of the five harnesses interleave tool execution into a single generation
-window. Antigravity reports a `Step` for the tool and only a later
+All five harnesses can have tool execution inside a generation window, and all
+five subtract it. Four interleave it structurally: Antigravity reports a `Step`
+for the tool and only a later
 `usage_metadata` `Step` cuts the message; Codex's message window is seeded from
 the first item's start and extended to the last item's completion; OpenCode
 opens its window at `step_start` and closes it at `step_finish`, and Pi at
-`turn_start` / `turn_end`, with every tool call running inside. In all four the
+`turn_start` / `turn_end`, with every tool call running inside. In each the
 span between the recorded bounds legitimately CONTAINS tool time that the model
-did not spend generating, so all four subtract it — the **union** of the closed tool intervals
-clipped to the window (`agents/_timing.py::busy_ms`), never the sum, because
+did not spend generating, so each subtracts it — the **union** of the closed tool intervals
+clipped to the window (`coder_eval/timing.py::busy_ms`), never the sum, because
 tool calls overlap: Antigravity resolves several from one `Step` and backgrounds
 anything over ten seconds, and Codex spawns collab agents concurrently. Summing
 them over-subtracts by exactly the overlap and, with enough concurrency, drives
@@ -48,10 +52,78 @@ the result to a clamped zero.
 The consequence worth knowing: on an emission that carries *only* a tool call,
 the whole measured window was that tool running, so the recorded generation
 time is legitimately `0.0`. That is a measurement, not a placeholder — `None`
-is what "never measured" looks like. Only `claude-code` does not need the
-subtraction: it marks the end of the previous SDK event and reads again when
-the next message arrives, so a tool's execution falls between two windows
-rather than inside one.
+is what "never measured" looks like.
+
+**`claude-code` subtracts at finalization, not as it flushes.** It was once
+exempt entirely, on the premise 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 rather than inside one. Measured, that premise does
+not hold: 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. On a task issuing five
+parallel writes, five reads and two concurrent `Bash` calls the overlap was
+482 ms and 340 ms on two ~18-25 s turns, and the four-bucket residual came out
+at exactly `-481 ms` and `-339 ms`; the other four overlapped by ~2.0-2.3 s on
+the same task and still reconciled to within 1.2 ms, because they subtract it.
+
+It cannot subtract while flushing, because a tool issued by an earlier emission
+is still running when the next window closes and its interval does not exist
+yet. `_ClaudeTurnState._subtract_tool_time_from_windows` therefore runs once at
+finalization, when every span is known. After it, the same task reconciles to
+**1.4 ms (0.006% of wall)** over four turns that all carried overlapping tool
+calls.
+
+**The head and tail are measured, not normalized.** Generation and tool are
+only two of the four buckets. The turn's **head** (turn start → first
+generation window) and **tail** (last window → turn end) are booked as
+`TurnRecord.harness_startup_ms` / `harness_teardown_ms`, computed once at the
+`EventCollector` seam by `coder_eval/timing.py::decompose_turn`. The tool term
+is the **union** of the command intervals, for the same reason the subtraction
+above is — Pi resolved a `Write` and a `Bash` overlapping by 18.4 ms in one
+measured turn, and summing their durations books that overlap twice. The head
+and tail exclude tool execution by that same rule and that same helper, which
+is what keeps the four buckets disjoint: a tool is not confined to a
+generation window (Antigravity force-closes an orphan at finalization, inside
+the tail, and backgrounds anything over ten seconds), so a span that escapes
+one would otherwise be counted both as tool and as head or tail. With all
+four buckets and the union, six live turns per harness reconcile to within
+1.7 ms of `duration_seconds` (worst case 0.014% of wall clock; the residual is
+clock skew, since head and tail are measured between wall-clock event stamps
+while `duration_seconds` is the agent's own monotonic span, and its sign flips
+between harnesses). `scripts/timing/decompose_run.py` reproduces the table. The head and tail
+figures in the table above are means of six live `tasks/hello_date` turns per
+harness and move with CLI cache warmth, so read their ORDER OF MAGNITUDE, not
+the digits.
+
+What the head CONTAINS differs per harness and is deliberately **not**
+decomposed, because the divergence is real and unfixable in both directions:
+
+- On an **in-process SDK** (claude-code, antigravity) the first generation
+  window starts at turn entry, so dispatch and time-to-first-token are already
+  inside it. Excluding them is not possible — neither harness stamps a
+  per-message arrival to fall back to, and `started_at == completed_at` would
+  be the CE059 defect. **Read their `0.0` head as "nothing is left over", not
+  as a measured interval**: the window actually opens marginally BEFORE the
+  `AgentStartEvent` stamp (claude-code builds its turn state, then
+  `_build_claude_query`, and only then emits the event), so the raw figure is
+  negative and clamps. The setup between those two points is therefore booked
+  as generation — **measured at 0.03 ms, and 0.10 ms with four plugin roots**,
+  so it is the sub-millisecond skew the clamp exists for rather than hidden
+  overhead. Emitting the event earlier would make the `0.0` a measurement
+  instead of a clamp but would not change it, since the window's start stamp
+  also precedes the build; only re-seeding the window after the build would
+  surface that time, and that is the seeding change ruled out above.
+  `TestClaudeHeadIsStructurallyZero` pins the build cost so this stays true.
+- On a **subprocess harness** (codex, opencode, pi) the first window cannot
+  start before the first event the CLI emits, so the head is one opaque
+  interval fusing CLI boot, provider resolution, dispatch and TTFT. Measured on
+  OpenCode: the process spawns in ~3 ms and its first `step_start` lands at
+  ~3.9 s, with no marker in between.
+
+So the fields are named for the **interval they measure**, never for what they
+contain. Do not rename them `cli_boot_ms` or `ttft_ms` — that would claim a
+split nobody performed. A measured `0.0` head is an answer; `None` is what
+"never measured" looks like (a turn that produced no assistant message).
 
 **Why Codex leaves `generation_completed_at` as `None`.** It means "when the
 model finished emitting the `tool_use` block". Codex's stream does not carry
@@ -82,7 +154,19 @@ tool call rather than shell commands alone.
   records `execution_completed_at` while leaving `duration_ms` as `None`
   (audit P2-1).
 
-Both are deliberately deferred; see `c/time-bugs-audit.md` for the measurements.
+- **`TurnStartEvent` is emitted at inconsistent points.** Antigravity and Codex
+  fire it at turn entry, before the pump; claude-code, OpenCode and Pi fire it
+  when a generation begins. Nothing in the timing accounting reads it — the
+  head and tail are measured from the first and last `AssistantMessage`
+  instead, which is uniform across all five — so this is recorded rather than
+  fixed. It is NOT a `max_turns` hazard: `EventCollector.visible_turn_count` is
+  `len(self._commands)`, derived from `ToolEndEvent`, and `_turn_starts` feeds
+  only `assistant_turn_count` on the no-`AgentEndEvent` fallback path. The real
+  cost of normalizing it is that the event drives the live renderers, so moving
+  it changes the turn boundaries users watch during a run.
+
+All three are deliberately deferred; see `c/time-bugs-audit.md` for the
+measurements.
 
 ## `max_turns` counts visible turns on Codex and Antigravity
 

evalboard/app/runs/[id]/[...task]/__tests__/message-timeline.test.tsx

@@ -621,6 +621,143 @@ describe("MessageTimelineSection — Unaccounted cell", () => {
     });
 });
 
+describe("MessageTimelineSection — Startup and Teardown cells", () => {
+    function cell(label: string): HTMLElement {
+        const parent = screen.getByText(label).parentElement as HTMLElement;
+        return parent.children[1] as HTMLElement;
+    }
+
+    // Same 4s generation + 1s tool exec fixture the Unaccounted block uses, so
+    // the two blocks' numbers are directly comparable.
+    function renderStrip(props: {
+        taskDurationSeconds?: number | null;
+        harnessStartupMs?: number | null;
+        harnessTeardownMs?: number | null;
+    }) {
+        const m = makeMessage({
+            generationMs: 4000,
+            textMs: 4000,
+            toolUses: [
+                {
+                    toolName: "Bash",
+                    toolUseId: "tu_1",
+                    summary: "ls",
+                    argText: "ls",
+                    description: null,
+                    genMs: null,
+                    durationMs: 1000,
+                    isError: false,
+                    resultPreview: null,
+                    outputTokens: null,
+                    resultTokens: null,
+                },
+            ],
+        });
+        return render(<MessageTimelineSection messages={[m]} {...props} />);
+    }
+
+    test("both buckets render their measured value", () => {
+        renderStrip({
+            taskDurationSeconds: 10,
+            harnessStartupMs: 3000,
+            harnessTeardownMs: 1500,
+        });
+        expect(cell("Startup").textContent).toBe("3.0s");
+        expect(cell("Teardown").textContent).toBe("1.5s");
+    });
+
+    test("a measured zero renders as 0ms, not as an em-dash", () => {
+        // claude-code and antigravity really do measure ~0 here — their first
+        // generation window already covers dispatch. "—" would report that
+        // honest measurement as a missing one.
+        renderStrip({
+            taskDurationSeconds: 10,
+            harnessStartupMs: 0,
+            harnessTeardownMs: 834.7,
+        });
+        expect(cell("Startup").textContent).toBe("0ms");
+        expect(cell("Teardown").textContent).toBe("835ms");
+    });
+
+    test("Unaccounted shrinks by exactly startup + teardown", () => {
+        // 10s − 4s gen − 1s tool = 5s before; minus 3s + 1.5s = 500ms after.
+        renderStrip({
+            taskDurationSeconds: 10,
+            harnessStartupMs: 3000,
+            harnessTeardownMs: 1500,
+        });
+        expect(cell("Unaccounted").textContent).toBe("500ms (5%)");
+    });
+
+    test("a corrected residual still above 25% stays red", () => {
+        // The other direction: naming the buckets must not disable the tint,
+        // only move the number it reads. 20s − 4s gen − 1s tool − 3s − 1s
+        // = 11s, still 55% unexplained.
+        renderStrip({
+            taskDurationSeconds: 20,
+            harnessStartupMs: 3000,
+            harnessTeardownMs: 1000,
+        });
+        expect(cell("Unaccounted").textContent).toBe("11.0s (55%)");
+        expect(cell("Unaccounted").className).toContain("text-red-700");
+    });
+
+    test("a residual that was red goes grey once the buckets are named", () => {
+        // The 25% threshold applies to the CORRECTED residual: 50% before,
+        // 5% after, so the red tint must follow the correction.
+        renderStrip({
+            taskDurationSeconds: 10,
+            harnessStartupMs: 3000,
+            harnessTeardownMs: 1500,
+        });
+        expect(cell("Unaccounted").className).not.toContain("text-red-700");
+    });
+
+    test("an older run with neither field renders — and today's residual", () => {
+        const { container } = renderStrip({ taskDurationSeconds: 10 });
+        expect(cell("Startup").textContent).toBe("—");
+        expect(cell("Teardown").textContent).toBe("—");
+        // Byte-identical to the pre-existing Unaccounted expectation.
+        expect(cell("Unaccounted").textContent).toBe("5.0s (50%)");
+        expect(cell("Unaccounted").className).toContain("text-red-700");
+        expect(container.textContent).not.toContain("NaN");
+    });
+
+    test("only the present bucket is subtracted", () => {
+        renderStrip({ taskDurationSeconds: 10, harnessStartupMs: 3000 });
+        expect(cell("Startup").textContent).toBe("3.0s");
+        expect(cell("Teardown").textContent).toBe("—");
+        expect(cell("Unaccounted").textContent).toBe("2.0s (20%)");
+    });
+
+    test("the residual still goes negative and stays amber", () => {
+        // Naming the buckets does not clamp the overlap signal.
+        renderStrip({
+            taskDurationSeconds: 5,
+            harnessStartupMs: 1000,
+            harnessTeardownMs: 500,
+        });
+        expect(cell("Unaccounted").textContent).toBe("-1.5s (-30%)");
+        expect(cell("Unaccounted").className).toContain("text-amber-700");
+    });
+
+    test("each bucket says what it measures and that it is not decomposed", () => {
+        renderStrip({
+            taskDurationSeconds: 10,
+            harnessStartupMs: 3000,
+            harnessTeardownMs: 1500,
+        });
+        expect(screen.getByText("Startup").parentElement).toHaveAttribute(
+            "title",
+            expect.stringContaining("time-to-first-token"),
+        );
+        expect(screen.getByText("Teardown").parentElement).toHaveAttribute(
+            "title",
+            expect.stringContaining("teardown"),
+        );
+    });
+});
+
 // A mixed-kind emission's per-kind split is apportioned by content size, so
 // the page must say so and must not let the unattributable part distort the
 // thinking share.