feat(session): debug logging for chat turn timing (TTFT + total)
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.
| Field | Meaning |
|---|---|
turn_ms | Wall 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_ms | Turn 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). |
steps | Number 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.tsrecords the first reasoning/text token intoctx.firstTokenAt(two guardedDate.now()writes in thereasoning-start/text-starthandlers) and exposes it via a read-onlyHandle.firstTokenAtgetter — symmetric with the existingget message(). - The loop owns aggregation.
runLoop(prompt.ts) capturesturnStart, readshandle.firstTokenAtafter each step (first non-undefined wins → turn TTFT), and emits the oneturn.doneline on loop exit.
No schema changes, no LLM-layer changes, no new params threaded through core methods, no per-step logging.
Verification
tsgo --noEmittypecheck: clean.test/session/compaction.test.ts(exercises the fullrunLoop): 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.donedebug 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;undefinedif no tokens. - Turn timing starts when
runLoopbegins; includes tools and setup. - Measured via
Handle.firstTokenAtandHandle.requestStartAtinprocessor, aggregated inrunLoop. No schema or API changes.
- Emits one