fix(opencode): log prep_ms and ttft_step on turn.done

Closed
PI
2mo ago
+60-1

The turn.done metric's derived overhead (ttft_ms − provider_ttft_ms) is only valid when both timestamps come from the same step, but firstTokenAt is set only on reasoning-start/text-start — never tool-input-start — and the processor handle resets per step. On tool-first turns the pair captures from a later step and the subtraction silently absorbs tool execution wall-clock. Production sample (n=282): single-step turns show overhead p90 1.97s; multi-step turns show p90 59.8s with a worst case of 192.2s "overhead" on a 217.9s turn (88% of wall clock). 20% of turns report a bogus overhead >10s.

This is additive — no existing field changes:

  • prep_ms: turnStart → the turn's FIRST provider request start, captured unconditionally (not gated on a token arriving). The harness-prep metric, correct by construction; undefined if no request ever started.
  • ttft_step: the 1-based step index the ttft pair was captured from, so consumers can detect and discard cross-step pairs.

Follow-up worth a product decision, not implemented here: setting firstTokenAt on tool-input-start would redefine ttft_ms as "time to first thing the user sees" — arguably more correct, but it changes an existing metric's meaning.

Test: scripted two-step turn (tool-only step 1 → text step 2) through the TestLLMServer harness, asserting ttft_step === 2 and prep_ms present and ≤ ttft_ms via a capture logger at Debug level. Fail-first: both fields are absent on dev.

Verified: bun run typecheck clean, bun run lint 0 errors, packages/opencode suite 3129 pass / 1 flake (pty + truncate tests, pass 2/2 in isolation, unrelated surfaces), prompt.test.ts 61/61.

🤖 Generated with Claude Code

Summary by cubic

Log prep_ms and ttft_step on turn.done so TTFT-derived overhead is accurate on tool-first and multi-step turns, and stamp the first provider request start once so prep_ms excludes retry backoff. Previously the TTFT pair could come from a later step, inflating overhead with tool wall-clock.

  • prep_ms: turn start → first provider request start; captured unconditionally; undefined if no request started. Uses firstRequestStartAt, which is set once and not overwritten by retries.
  • ttft_step: 1-based step index where the TTFT pair was captured; lets consumers detect and discard cross-step pairs.
  • Add firstRequestStartAt to the Handle and processor context; expose via handle.firstRequestStartAt.
  • Additive only; existing fields and meanings unchanged.
  • Tests: new two-step scenario asserts ttft_step === 2 and prep_ms ≤ ttft_ms; update test fakes to include firstRequestStartAt.