feat(tui): show where a turn's time went, not just how long it took

[kovtcharov]

The TUI already tells you a turn took 34 seconds. It has never been able to tell you why, and the reason is a number nothing measured: the system prompt plus tool schemas re-sent on every single LLM call. On this machine Lemonade prefills at roughly 390 tok/s, so a 17k fixed prefill is ~44 seconds of every turn before the model writes a word — invisible behind an elapsed-time figure that looks like the model is just slow. This adds an opt-in per-turn record that measures it, and shows it.

What this adds beyond today's stats line

Today --dev prints 12.0s · ttft 11.9s · 1 steps. Every one of those describes the outcome; none decomposes it. New:

• Fixed prefill size on that same line — … · 1 steps · 17.0k prefill. One number, and it is usually the answer.
• Cached vs new input tokens per call, so you can see whether the KV-cache prefix was actually reused between steps or the whole prompt was re-read. prefill tok/s next to it shows which.
• Where the seconds went — model vs tools vs agent overhead, split.
• Absolute timestamps on the turn and every call, so a session lines up against Lemonade's own log or a screen recording.
• A per-step table, because a turn is slow due to one step re-reading the prompt and an aggregate hides which.
• A JSONL log (GAIA_TURN_LOG), append-only, so a session is greppable and two builds are diffable.

With GAIA_TURN_LOG unset none of this exists: the recorder is never constructed and the wire payload is byte-identical to before (asserted by a json.dumps equality test including key order).

34.5s · ttft 2.1s · 210 tokens · 6.5 tok/s · 2 steps · 1 tools · 17.0k prefill
  turn a3f1c2  22:47:35Z → 22:48:09Z  34.5s total
  model 28.4s · tools 4.8s · overhead 1.3s
  in 51,204 tok (38,110 cached, 13,094 new · 74% hit) · out 210 tok
  prefill 17.0k fixed · 66 tools · skills: gaia-voice
  model id Gemma-4-E4B-it-GGUF
  step 1   12.8s  ttft  4.9s  in 17,204 (0 cached)  3511 tok/s prefill
          └ run_shell_command 2.1s
  step 2    9.1s  ttft  0.4s  in 17,260 (17,204 cached)

⚠️ Required gate NOT run: gaia eval agent

This touches src/gaia/agents/base/agent.py, so CLAUDE.md requires an agent eval before merge. It has not been run. Lemonade is banned on the machine this was developed on (it crashes the host), and no query was sent to any local backend during this work.

The change is structurally low-risk for LLM behaviour — it adds no prompt text, changes no tool schema, and touches no prompt-assembly code — but that is an argument, not an eval. Someone with a working Lemonade box needs to run gaia eval agent against the committed baseline before this merges.

🔍 Bug found while instrumenting, NOT fixed here

In a Claude session the agent logs [PARSE] tool_call_path=native model_id=Gemma-4-E4B-it-GGUF while every request goes to api.anthropic.com. Agent.model_id keeps the configured local id under --use-claude; the substitution happens later, in AgentSDK.effective_model.

That stale id feeds is_tool_calling_model(), which selects the tool-call parsing strategy — so on Claude it currently picks Gemma's strategy and happens to work. That is luck, not design, and it will break the first time the two strategies diverge.

I fixed only the part inside this change: the turn record and the model id line above report AgentSDK.effective_model, the model actually used. The parsing-strategy selection is untouched and still wrong — it reaches into call sites this PR has no business editing, and deserves its own issue.

Conflicts with other open PRs

• tui/internal/ui/chat/model.go, tui/internal/ui/chat/canonical.go — also touched by fix(tui): stop --use-claude from starting Lemonade, and name the Claude model #3005 (model picker) and feat(tui): lay out to the real terminal width #3006 (responsive width). Branched from main @ 9c89cb4 and not rebased. My edits here are small and additive: two lines appended inside answerStats, one call added in renderMessage, one struct field set in the CanonicalFinalEvent case. Whoever lands second should get a clean textual merge; if not, mine is the hunk to re-apply by hand.
• src/gaia/agents/base/agent.py — four PRs on this file (fix(agent): bill tool-approval time to the human, not the tool #3007, feat(skills): let a gh write ask instead of fail #3009, feat(skills): load the right skill without the user knowing its name #3010, this one). Functions I touch, so the reviewer can sequence them: process_query (wrapped its body in try/finally), _execute_tool (now a timing wrapper; its original body moved verbatim to a new _execute_tool_impl), _process_query_impl (four added lines), and four new methods that nothing else calls — _begin_turn_record, _finish_turn_record, _publish_turn_metrics, _recorded_model_id. I did not touch _compose_system_prompt, _get_mixin_prompts, or any prompt text.
• The _execute_tool → _execute_tool_impl rename is the one thing that can break a caller outside this diff. Nothing calls the impl directly; one test (test_skill_binary_grants.py) cherry-picks base methods onto a stub agent and needed the new name added, which is included here.

Test plan

# Go — build, vet, and the full suite including the ~4min integration tier
cd tui && go build ./... && go vet ./... && go test ./...

# Python — the wire path, both directions of the env gate
python -m pytest tests/unit/test_turn_metrics_wire.py -q

# The files that exercise every module this touches
python -m pytest tests/unit/test_sse_narration.py tests/unit/test_streaming_tool_calls.py \
  tests/unit/test_skill_binary_grants.py tests/unit/test_agent_token_usage.py -q

• go build ./... && go vet ./... && go test ./... under tui/ — green (integration tier included)
• pytest tests/unit/test_turn_metrics_wire.py — 19 pass
• The 41 unit-test files touching the changed modules produce an identical failure set to a stashed clean tree (verified locally: same failures, +19 passing). tests/unit as a whole has ~600 failures on main on this machine that are unrelated to this change.
• gaia eval agent — NOT RUN, see above. Blocks merge.
• Eyeball the dev block: GAIA_TURN_LOG=~/.gaia/turns.jsonl gaia --dev, ask anything, confirm the block appears and jq . ~/.gaia/turns.jsonl parses
• Confirm the quiet path is untouched: run without GAIA_TURN_LOG and check the footnote is exactly what it was

Reviewer notes

Four timing defects were found in review and fixed here, each with a test that fails without its fix (verified by reintroducing the defect): a cancelled turn abandoned its open LLM call and charged those seconds to overhead; _process_query_impl re-raises on the wrong-ctx reload and left the recorder attached to fold the retry's calls into the abandoned turn; every non-streaming call charged its /stats HTTP round-trip to model time; and nested tool calls (CodeAgent's orchestration does this) were timed twice while a tool that raised recorded as ok: true.

The cached/new token counts come from a client-side estimator (tiktoken when installed), not the model's own tokenizer — they are honest as ratios and deltas, not as exact model token counts. out is the backend's own number. This is stated in the docs and in the module docstring rather than left for someone to discover.

src/gaia/agents/base/turn_metrics.py swallows its own failures by design — a metrics bug must never be able to fail a user's turn. That exception is documented in the module docstring and is deliberately narrow: it covers recording only, never the agent's own work.

[github-actions]

Verdict: Approve with suggestions

This adds an opt-in per-turn performance record — where a turn's seconds went, how big the fixed prefill is, and how much of the input the KV cache could reuse — written to a JSONL file and drawn under the answer in --dev. Off by default, and the tests actually prove "off" means byte-identical output rather than merely metrics-free, which is the right thing to have pinned.

One thing to fix before merge: the Agent UI SSE contract spec still lists the five fields a final event's usage object can carry, and this PR adds a sixth. The spec is the doc a client author reads to know what can show up on the wire, so it needs the new field named there alongside the code.

The rest are small and optional:

• On the non-streaming path, closing the record reaches for backend stats even when the request just failed — including on a cancel. The streaming path deliberately avoids exactly that, so the two paths should agree.
• The --dev breakdown hangs each tool under its step. A tool recorded against a step that has no backend call of its own vanishes from the display, even though its seconds still count in the totals.
• The log file records each turn's full prompt text. Worth one line in the dev docs so nobody is surprised by what lands on disk.

Real-world evidence

No evidence-bundle.md was produced for this run, and the environment this review ran in had no working shell, so I could not read the PR description to check whether the author attached evidence there. Treat the verdict as resting on static review plus the committed tests.

For the record, the surface here is the TUI's --dev breakdown plus a new field on the Agent UI answer/final event. The unit tests cover both ends of that wire (the Python emitter and the Go decoder, including a malformed record), but no capture of the real block rendered under a real answer is present. A terminal capture of gaia --dev with GAIA_TURN_LOG set, and a peek at one line of the resulting JSONL, would close that gap — not a blocker, but it is the one artifact that would show the numbers are right rather than merely well-plumbed.

🔍 Technical details

Issues

🟡 The canonical SSE contract spec doesn't know about usage.metrics (docs/spec/agent-ui-query-sse-contract.md:263, :417)

The spec enumerates the final event's usage payload as // optional {steps?, tools_used?, elapsed?, tokens?, ttft?}, and §6.1's transform table spells out the answer → final mapping as elapsed/steps/tools_used/tokens/ttft → usage. sse_translation.py:387 now adds a sixth pair, and sse_handler.py:846 adds metrics to the source answer event. Per CLAUDE.md ("a functional change must update EVERY doc that describes it"), both spots need the new field, with a note that it is present only when GAIA_TURN_LOG is set so a client treats absence as normal — which is exactly what canonical.go's doc comment already tells Go callers.

    "usage":  { "type": "object" }   // optional {steps?, tools_used?, elapsed?, tokens?, ttft?, metrics?}

🟢 Non-streaming close fetches /stats on the failure path (src/gaia/chat/sdk.py:339-345)

_recorder_end() with no argument falls through to self.get_stats(), which on Lemonade is a live HTTP round-trip. In the finally it fires even when llm_client.chat just raised, and when config.show_stats is on it fires twice per call (again at line 345). The streaming path takes the opposite position on purpose — _recorder_end(stats={}) with the comment "a cancel must start no HTTP request". Worth making the two agree; passing the already-fetched dict on the success path and {} on the exception path costs nothing.

🟢 Tool rows with no matching backend call are dropped from the breakdown (tui/internal/ui/chat/turnmetrics.go:52-77)

stepLines iterates t.LLMCalls and prints toolsByStep[c.Step]. Any tool recorded at a step with no llm_call of the same index — an agent whose chat is None, so _execute_tool stamps step=0, or a tool that ran outside the step loop — never renders, while its seconds still land in Totals.ToolS. That reads as unexplained tool time. A trailing "unattributed" row, or keying off the union of both step sets, would close it.

🟢 _publish_turn_metrics is skipped on the cancelled-turn path (src/gaia/agents/base/agent.py:6343)

The cancel branch seals the record (so the JSONL line is written) but returns before publishing, so a cancelled turn's breakdown never reaches a console. Probably intended — cancel emits no answer event for it to ride — but the asymmetry with line 6276-6279 isn't stated anywhere and the comment above it only explains the seal.

🟢 Dev docs don't say the log captures prompt text (docs/reference/dev.mdx:341-346)

TurnRecorder.finish stores "query": query verbatim (answers are reduced to answer_chars, which is the careful choice), and end_llm_call stores the backend's stats_raw unfiltered. The docs describe the record as sizes and timings. One line — "the record includes the turn's prompt text" — saves a developer from discovering that when they paste the file into an issue.

Strengths

• The negative test is the one that matters, and it's the strongest test here. test_off_by_default_payload_is_unchanged compares serialized JSON rather than asserting "metrics" not in event, so a reordered or null-placeholder key fails it; test_a_stashed_record_alone_does_not_leak pins that the env var, not the record's presence, is the gate.
• The Go decoder isolates the blast radius correctly. Keeping the record as json.RawMessage in usageWire means a record whose inner shape drifts costs only the breakdown, not steps/tokens/ttft — and turnmetrics_test.go has the malformed-record case to prove it.
• The unhappy timing paths are genuinely handled, not just claimed. mark_llm_call_end stopping the clock before the /stats round-trip, the nested-tool depth guard, the abandoned-generator finally, and the idempotent seal each have a test that fails if the guard is removed — including one that fails loudly if a cancelled turn reaches for stats.

[github-actions]

Verdict: Approve

Clean implementation of opt-in per-turn performance recording. The zero-overhead default (recorder never constructed unless GAIA_TURN_LOG is set) is the right design for a developer diagnostic, and the code is careful about every exit path: finally blocks in _execute_tool, send_messages_stream, and process_query all guarantee the recorder is detached, and _finish_turn_record is idempotent so double-calls are harmless. No correctness issues found.

The test suite is thorough where it matters — the negative cases (an ordinary turn's payload is byte-identical to before, a stashed record doesn't leak without the env var) and the unhappy paths (abandoned streams, nested tool calls counted once, raising turns that still seal their record) are all covered.

🔍 Technical details

One observation worth noting for future readers: _common_prefix_len in turn_metrics.py:431 does a character-by-character scan over the rendered prompt (potentially 50 k+ chars) on every LLM call. Since this only runs when GAIA_TURN_LOG is set it is not a prod concern, but a os.path.commonprefix-style byte comparison or a zip-based short-circuit would be faster if the rendered prompts grow.

The json:"-" tag on CanonicalUsage.Metrics in canonical.go:1339 is intentional — the field is in-memory only and must not be re-marshalled — but it means any future json.Marshal(usage) call silently drops the metrics. Worth a comment if that path ever opens up.

Neither of these is a blocker.

[github-actions]

Verdict: Approve

Per-turn performance recording is a well-designed opt-in developer feature. Several things stand out as correctly handled: the gate on GAIA_TURN_LOG means ordinary turns pay zero cost; the two-stage Go decode (usageWire / CanonicalTurnStats) isolates a malformed record so it can't erase the step/token counts the user sees on every turn; the _tool_timing_depth guard prevents double-counting nested tool calls; and the idempotent seal covers all exit paths — normal answer, early-exit, max-steps, and raised exceptions without a seal.

Test coverage is unusually thorough: cancelled streams, nested tools, raising tools, broken console hooks, stale-record-into-next-turn, and the ordering invariant (seal before print_final_answer) are all exercised with the right level of source-reading tests.

One 🟢 nit on the Go side: CanonicalTurnTotals.OutputTokensServer and CanonicalTurnCall.OutputTokens are declared float64, but token counts from the Python record are always integers. The render path converts back with int(...), which works, but storing a count as a float is a latent footgun if someone adds arithmetic against those fields later.

🟡 Real-world evidence: The --dev TUI metrics block is a user-visible surface (rendered to the terminal). Per the project's evidence policy, a CLI-visible change should include the real command output alongside the change. The docs show the expected output, and the rendering is unit-tested, but if the PR description lacks a real gaia --dev run showing the block, that's the one artifact worth adding.

🔍 Technical details

Float vs int token fields in Go (tui/internal/event/canonical.go:1449, tui/internal/event/canonical.go:1427):

// current
OutputTokensServer float64 `json:"output_tokens_server"`
// suggestion
OutputTokensServer int `json:"output_tokens_server"`

Same for CanonicalTurnCall.OutputTokens. JSON integers unmarshal to both float64 and int cleanly; the only downside of float64 is that future callers may not know to round before arithmetic.

Evidence gap (conditional): If the PR description already includes a gaia --dev session showing the metrics block, this is not a flag. The rubric asks for "the real gaia <subcommand> and its output" for CLI-visible changes. TestTurnMetricsBlockShowsTheBreakdown is a strong proxy but not a substitute.

Everything else reviewed and clean:

• _execute_tool timing wrapper: correct — ok=False default propagates through exceptions, finally records, exception re-raises.
• Idempotent _finish_turn_record: second call sees _turn_recorder is None (cleared by the first call) and returns None immediately. One write per turn confirmed by test_finish_is_idempotent.
• _recorder_end called twice (normal path + finally): second call sees _open_call is None (cleared by end_llm_call) and is a no-op. Confirmed by test_closing_twice_records_one_call.
• clockOf with fractional-second ISO timestamps: Go's time.Parse accepts fractional seconds even when the layout (time.RFC3339) doesn't declare them — the parser is more permissive than the format.
• devPayloadStyle in turnmetrics.go: defined at model.go:101, pre-existing.
• The # noqa: BLE001 exception pattern: deliberately broad but narrowly scoped to diagnostics, logged with context, and documented in the module docstring. Not the same as the pre-existing silent pass blocks.

[kovtcharov-amd]

Closing as superseded: the per-turn timing breakdown is already live on main (landed via #3026) and now carries more fields than this PR did — the one genuine remainder, a turn log that records the local model id under --use-claude, will be filed separately rather than held behind 1,680 lines.