Skip to content

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

Closed
PierrotAWB wants to merge 2 commits into
devfrom
turn-timing-metrics
Closed

PierrotAWB wants to merge 2 commits into
devfrom
turn-timing-metrics

Conversation

@PierrotAWB

@PierrotAWB PierrotAWB commented Aug 24, 2026 •

Copy link
Copy Markdown
Collaborator

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.

Written for commit 82ad220. Summary will update on new commits.

Review in cubic

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@github-actions

Copy link
Copy Markdown

Thanks for your contribution!

This PR doesn't have a linked issue. All PRs must reference an existing issue.

Please:

  1. Open an issue describing the bug/feature (if one doesn't exist)
  2. Add Fixes #<number> or Closes #<number> to this PR description

See CONTRIBUTING.md for details.

@github-actions

github-actions Bot commented Aug 24, 2026 •

Copy link
Copy Markdown

This PR doesn't fully meet our contributing guidelines and PR template.

What needs to be fixed:

  • PR description is missing required template sections. Please use the PR template.

Please edit this PR description to address the above within 2 hours, or it will be automatically closed.

If you believe this was flagged incorrectly, please let a maintainer know.

@github-actions

Copy link
Copy Markdown

The following comment was made by an LLM, it may be inaccurate:

@cubic-dev-ai cubic-dev-ai Bot left a comment •

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All reported issues were addressed across 2 files

Reply with feedback, questions, or to request a fix.

Re-trigger cubic

Comment thread packages/opencode/src/session/prompt.ts Resolved
…ry backoff

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

@cubic-dev-ai cubic-dev-ai Bot left a comment •

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All reported issues were addressed across 3 files (changes from recent commits).

Reply with feedback, questions, or to request a fix.

Re-trigger cubic

@PierrotAWB

Copy link
Copy Markdown
Collaborator Author

Consolidated into #29 (one commit per concern there; review history for the prep_ms retry semantics is on this PR's threads).

@PierrotAWB PierrotAWB closed this Aug 24, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant