feat(session): debug logging for chat turn timing (TTFT + total)

Merged
PI
4mo ago
+36-0

What

Adds a single debug-level turn.done log line per chat turn so we can measure how long turns take and get a read on opencode's internal time-to-first-token (TTFT). Intended as raw signal to iterate on downstream.

turn.done { session.id, turn_ms, ttft_ms, steps }

How "turn time" is defined

A turn = one user message → the agentic loop finishes. That loop is usually multiple model steps (LLM → tool(s) → LLM → … → final text), so a turn is not one model call.

FieldMeaning
turn_msWall time from turn start (when runLoop begins processing, just after the user message is created) to loop exit. Includes all steps + tool execution + server setup.
ttft_msTurn start → first model output token across all steps (first reasoning or text token, whichever comes first — so thinking models count their first reasoning token). undefined if the turn produced no reasoning/text (e.g. a tool-only turn).
stepsNumber of model steps in the turn.

Tool time is derivable downstream (turn_ms − model time). Per-step lines were deliberately not emitted — too noisy.

Architecture

Kept deliberately minimal and clean:

  • Processor owns the measurement. processor.ts records the first reasoning/text token into ctx.firstTokenAt (two guarded Date.now() writes in the reasoning-start / text-start handlers) and exposes it via a read-only Handle.firstTokenAt getter — symmetric with the existing get message().
  • The loop owns aggregation. runLoop (prompt.ts) captures turnStart, reads handle.firstTokenAt after each step (first non-undefined wins → turn TTFT), and emits the one turn.done line on loop exit.

No schema changes, no LLM-layer changes, no new params threaded through core methods, no per-step logging.

Verification

  • tsgo --noEmit typecheck: clean.
  • test/session/compaction.test.ts (exercises the full runLoop): 52 pass / 1 skip.
  • Runtime emission against a live model not exercised here (debug-level, low risk) — the log path runs in the loop tests without error. Enable debug logs to see it downstream.

🤖 Generated with Claude Code


Summary by cubic

Adds a single debug log per chat turn to measure total turn time, internal TTFT, and provider-only TTFT. Helps spot latency in the agent loop and separate setup from model latency.

  • New Features
    • Emits one turn.done debug log with: session.id, ttft_ms, provider_ttft_ms, turn_ms, steps.
    • TTFT = first reasoning or text token across steps; provider_ttft_ms = first token − request dispatch; undefined if no tokens.
    • Turn timing starts when runLoop begins; includes tools and setup.
    • Measured via Handle.firstTokenAt and Handle.requestStartAt in processor, aggregated in runLoop. No schema or API changes.