Skip to content

Commit b38f5e6

Browse files
authored
fix(tui): anchor TTFT on first inference token, use real token counts (#2911)
Closes #2899 ## Why this matters The TUI's per-query stats line was untrustworthy: a triage query that took a minute showed `ttft 0.1s` (impossible) and a token count guessed from the answer string's character length, not what the model actually generated. Both fixes are needed together — a client-side character-count guess was never going to be right regardless of what the answer text contained. - **TTFT** now measures from query submit to the first real inference token, not the first SSE frame of any kind (previously a turn-start status ping arriving in milliseconds). - ⚠️ **The first attempt at this shipped a TTFT that never rendered at all.** Re-anchoring on the token event was correct, but that event never fires for this agent: `EmailAgentConfig.streaming` defaults `False`, and even flipping it changes nothing because `LemonadeProvider.chat()` forces `effective_stream = stream and not (tool_capable and tools)` — and the agent attaches its tool schema every step. Live capture showed `ttft` **absent** from all four queries, so the follow-up commit sources it from Lemonade's own per-step `time_to_first_token` (already polled for token accounting, previously discarded) and carries it on the same `usage` channel as tokens. - It reads the **earliest** token-generating step, not the last. A last-step reading times only the final LLM call and would land near ~1-2s on a ~69s turn — reproducing the exact defect this issue was opened for. Returns nothing rather than a fabricated `0` when unavailable. - **Token count** is now the real total generated across the run, plumbed from the agent loop through the SSE wire contract into the TUI — replacing the `len(answer)/4` guess. A tool that makes its own internal LLM calls (email triage's per-message classification fan-out) now has its usage folded into the same total instead of being stranded on the tool's own return value. - Step and tool counts are unchanged — they were already accurate. ⚠️ **Breaking change for custom `OutputHandler` subclasses.** `print_final_answer` now always receives `total_tokens=` and `ttft_seconds=` keyword arguments from the agent loop. An out-of-tree subclass with the old two-argument signature (`answer`, `streaming`) will raise `TypeError` on its first answer. All in-repo subclasses (`AgentConsole`, `SilentConsole`, `SSEOutputHandler`) are updated; `docs/spec/console.mdx` now documents the new signature too. This break is intentional rather than shimmed with a compatibility fallback — the alternative (inspecting the target's signature at the call site, or swallowing the `TypeError` and retrying without the new kwargs) is exactly the kind of silent-fallback behavior this repo's conventions rule out. <!-- BEFORE/AFTER STATS: placeholder, filled by the orchestrator's evidence agent --> **Known, separately-tracked gaps (not this PR):** - Duration also under-reports true wall-clock (4-28% measured on a live baseline) — tracked in #2909. Requires moving where the terminal SSE event fires relative to post-answer server work; out of scope here. - BuilderAgent has its own loop override and doesn't wire the new `total_tokens` param — its stats line will show no token count after this change. Not the flow this issue reports on (email triage), and out of this PR's file boundary. ## Test plan - [x] `cd tui && go build ./... && go vet ./... && go test ./...` — all packages pass, including new tests for the warm-query TTFT regression and the real-token render path. - [x] `python -m pytest tests/unit/ -q` — 10278 passed, 159 skipped. 10 pre-existing failures (CLI-binary-on-PATH, a Claude-judge missing-API-key artifact, hub-installer wheel installs, VLM PDF extraction) are all in files untouched by this diff — confirmed via `git diff origin/main --stat`. - [x] `python -m pytest hub/agents/email/python/tests/ -q` — 1870 passed. Two pre-existing failures in `test_email_sidecar_relay.py` (expect a `render` card on `pre_scan_inbox` that current code deliberately no longer draws — unrelated to this change, confirmed identical to origin/main). - [x] `python util/lint.py --all` — all quality checks passed. - [ ] Real triage-run verification (AC5) — owned by a separate evidence-capture agent, not this PR's author; before/after stats will be added once captured. Whichever of this PR and #2901 (stacked on this branch, touches the same `sendQuery`/`canonical.go` regions) merges second should re-run the Go suite against the post-merge tree — a hand-resolved conflict here could silently drop a one-line change without failing either branch's own CI.
1 parent 779d7b0 commit b38f5e6

18 files changed

Lines changed: 966 additions & 54 deletions

File tree

docs/sdk/sdks/agent-ui.mdx

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -662,7 +662,7 @@ class AttachDocumentRequest(BaseModel):
662662
| Event type | Fields | Description |
663663
|------------|--------|-------------|
664664
| `chunk` | `content` (string) | Incremental text fragment of the response, streamed as the LLM generates tokens. Raw tool-call JSON is automatically filtered out. |
665-
| `answer` | `content` (string), `elapsed` (number), `steps` (int), `tools_used` (int) | Final complete answer from the agent. `elapsed` is wall-clock seconds. `steps` and `tools_used` are execution totals. Double-escaped newlines/tabs from LLM output are automatically corrected. |
665+
| `answer` | `content` (string), `elapsed` (number), `steps` (int), `tools_used` (int), `tokens` (int, optional), `ttft` (number, optional) | Final complete answer from the agent. `elapsed` is wall-clock seconds. `steps` and `tools_used` are execution totals. `tokens` is the real output-token count and `ttft` the real time-to-first-token for the run, in seconds -- both omitted entirely (never a fake `0`) when no real value was recorded. Double-escaped newlines/tabs from LLM output are automatically corrected. |
666666
| `agent_error` | `content` (string) | Error message from the agent. |
667667

668668
**Stream Termination**
@@ -682,7 +682,7 @@ class AttachDocumentRequest(BaseModel):
682682
data: {"type": "chunk", "content": "This function"}
683683
data: {"type": "chunk", "content": " initializes"}
684684
data: {"type": "chunk", "content": " the database..."}
685-
data: {"type": "answer", "content": "This function initializes the database...", "elapsed": 3.45, "steps": 1, "tools_used": 1}
685+
data: {"type": "answer", "content": "This function initializes the database...", "elapsed": 3.45, "steps": 1, "tools_used": 1, "tokens": 42, "ttft": 0.81}
686686
data: {"type": "status", "status": "complete", "message": "Completed in 1 steps", "steps": 1, "elapsed": 3.45}
687687
data: {"type": "done", "message_id": 42, "content": "This function initializes the database..."}
688688
```

docs/spec/agent-ui-query-sse-contract.md

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -260,7 +260,7 @@ indistinguishable from a dead one.
260260
"properties": {
261261
"type": { "const": "final" },
262262
"answer": { "type": "string" },
263-
"usage": { "type": "object" } // optional {steps?, tools_used?, elapsed?, tokens?}
263+
"usage": { "type": "object" } // optional {steps?, tools_used?, elapsed?, tokens?, ttft?}
264264
} }
265265

266266
// error
@@ -414,7 +414,7 @@ truth:** [`src/gaia/ui/sse_handler.py`](../../src/gaia/ui/sse_handler.py) on
414414
|---|---|---|
415415
| `tool_start` | `tool_call` | Rename; carry `tool`. `args` filled from the paired `tool_args` (§6.3). `detail`/`mcp_server` dropped (host derives its own label). |
416416
| `chunk` | `token` | `content``delta`. |
417-
| `answer` | `final` | `content``answer`; `elapsed`/`steps`/`tools_used``usage`. |
417+
| `answer` | `final` | `content``answer`; `elapsed`/`steps`/`tools_used`/`tokens`/`ttft``usage`. |
418418
| `permission_request` | `needs_confirmation` | `tool``action`; render `args` as `summary`; carry `run_id`; `confirm_url` per §5. |
419419

420420
### 6.2 Every remaining top-level source event

docs/spec/console.mdx

Lines changed: 20 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -159,8 +159,19 @@ class OutputHandler(ABC):
159159
# === Completion Methods (Required) ===
160160

161161
@abstractmethod
162-
def print_final_answer(self, answer: str):
163-
"""Print final answer/result."""
162+
def print_final_answer(
163+
self,
164+
answer: str,
165+
total_tokens: Optional[int] = None,
166+
ttft_seconds: Optional[float] = None,
167+
):
168+
"""Print final answer/result.
169+
170+
total_tokens: real output-token count generated across the run, if
171+
known. ttft_seconds: real time-to-first-token for the LLM call that
172+
produced this answer, if known. Both None when no real value is
173+
available — never a substituted estimate.
174+
"""
164175
...
165176

166177
@abstractmethod
@@ -364,7 +375,13 @@ class SilentConsole(TerminalConfirmationMixin, OutputHandler):
364375
self.silence_final_answer = silence_final_answer
365376
self.auto_approve_gated_tools = auto_approve_gated_tools
366377

367-
def print_final_answer(self, answer: str, streaming: bool = True) -> None:
378+
def print_final_answer(
379+
self,
380+
answer: str,
381+
streaming: bool = True,
382+
total_tokens: Optional[int] = None,
383+
ttft_seconds: Optional[float] = None,
384+
) -> None:
368385
"""
369386
Print the final answer.
370387
Only suppressed if silence_final_answer is True.

hub/agents/email/npm/src/types.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1046,6 +1046,8 @@ export interface QueryUsage {
10461046
elapsed?: number;
10471047
/** Token counts, when the backend reports them. */
10481048
tokens?: number;
1049+
/** Time to first inference token, in seconds, when the backend reports it. */
1050+
ttft?: number;
10491051
[key: string]: unknown;
10501052
}
10511053

hub/agents/email/python/gaia_agent_email/sse_translation.py

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -238,6 +238,8 @@ def _on_answer(self, event: Dict[str, Any]) -> List[Dict[str, Any]]:
238238
("steps", "steps"),
239239
("tools_used", "tools_used"),
240240
("elapsed", "elapsed"),
241+
("tokens", "tokens"),
242+
("ttft", "ttft"),
241243
):
242244
if event.get(src) is not None:
243245
usage[dst] = event[src]

hub/agents/email/python/tests/test_sse_translation.py

Lines changed: 58 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,9 @@
55
These assert the translation map is TOTAL — every top-level event type
66
``sse_handler.py`` emits has an explicit canonical mapping — and that the
77
``tool_start`` + ``tool_args`` → one ``tool_call`` buffering (spec §6.3) is exact.
8-
Dependency-light: no Lemonade, Gmail, or ``gaia.ui`` needed.
8+
Dependency-light by default: no Lemonade or Gmail needed. A handful of tests
9+
that guard the producer/translator boundary (see ``_real_answer_event``)
10+
import ``gaia.ui.sse_handler`` — a deliberate, narrow exception; see #2911.
911
"""
1012

1113
from __future__ import annotations
@@ -24,6 +26,27 @@ def _types(events):
2426
return [e["type"] for e in events]
2527

2628

29+
def _real_answer_event(**print_final_answer_kwargs) -> dict:
30+
"""Drive the REAL producer — ``SSEOutputHandler.print_final_answer`` —
31+
and return the ``answer`` event it actually emits, instead of a
32+
hand-typed guess of its shape.
33+
34+
#2911 review: a synthetic ``{"type": "answer", ...}`` dict that simply
35+
omits a key (e.g. "tokens") passes against the translator's mapping
36+
logic even when the real producer emits that key with a fake `0`
37+
instead of leaving it off — the translator was never wrong, so the
38+
hand-built input can't catch a producer-side regression. Importing
39+
``gaia.ui`` here is a deliberate, narrow exception to this file's
40+
dependency-light default, scoped to the tests that specifically guard
41+
the producer/translator boundary.
42+
"""
43+
from gaia.ui.sse_handler import SSEOutputHandler
44+
45+
handler = SSEOutputHandler()
46+
handler.print_final_answer("Done.", **print_final_answer_kwargs)
47+
return handler.event_queue.get_nowait()
48+
49+
2750
# ---------------------------------------------------------------------------
2851
# The four clean maps (spec §6.1)
2952
# ---------------------------------------------------------------------------
@@ -49,6 +72,40 @@ def test_answer_maps_to_final_with_usage():
4972
assert out[0]["usage"] == {"steps": 3, "tools_used": 2, "elapsed": 1.2}
5073

5174

75+
def test_answer_maps_tokens_into_usage():
76+
# #2899: the real generated-token count, when the source event carries
77+
# one, must reach usage.tokens — the TUI reads it in place of its old
78+
# char-count guess. Driven off the real producer (see
79+
# ``_real_answer_event``) so this fails if the wire key ever changes.
80+
out = _tr().translate(_real_answer_event(total_tokens=42))
81+
assert out[0]["usage"]["tokens"] == 42
82+
83+
84+
def test_answer_omits_tokens_when_source_has_none():
85+
# No real count available -> omitted entirely, never a fake 0 (#2899).
86+
# Regression guard for #2911: the producer used to always pass an int
87+
# (0 when no per-step stats existed), so this event legitimately carried
88+
# `tokens: 0` on the wire until the producer-side guard was fixed to
89+
# match ttft's. A hand-built dict without the "tokens" key can't catch
90+
# that — it has to come from the real producer.
91+
out = _tr().translate(_real_answer_event(total_tokens=0))
92+
assert "tokens" not in out[0]["usage"]
93+
94+
95+
def test_answer_maps_ttft_into_usage():
96+
# #2899 follow-up: real ttft was never reaching the TUI at all on the
97+
# non-streaming daemon path (every native tool-calling model's normal
98+
# path) -- when the source event carries one, it must reach usage.ttft.
99+
out = _tr().translate(_real_answer_event(total_tokens=72, ttft_seconds=9.4))
100+
assert out[0]["usage"]["ttft"] == 9.4
101+
102+
103+
def test_answer_omits_ttft_when_source_has_none():
104+
# No real value available -> omitted entirely, never a fake 0.
105+
out = _tr().translate(_real_answer_event(total_tokens=0))
106+
assert "ttft" not in out[0]["usage"]
107+
108+
52109
def test_answer_is_terminal():
53110
out = _tr().translate({"type": "answer", "content": "Done."})
54111
assert out[0]["type"] in TERMINAL_TYPES

src/gaia/agents/base/agent.py

Lines changed: 155 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
import inspect
1414
import json
1515
import logging
16+
import math
1617
import os
1718
import re
1819
import subprocess
@@ -300,6 +301,113 @@ def _find_matching_close_paren(text: str, open_pos: int) -> Optional[int]:
300301
return None
301302

302303

304+
def _safe_number(value: Any) -> int:
305+
"""Coerce a usage-stat value to a non-negative int; anything else
306+
(string, None, nested structure, bool) is untrusted input and yields 0
307+
rather than raising — a malformed stat must never break the run that
308+
carries it."""
309+
if isinstance(value, bool):
310+
return 0
311+
if isinstance(value, (int, float)) and value >= 0:
312+
return int(value)
313+
return 0
314+
315+
316+
def _sum_conversation_tokens(
317+
conversation: List[Dict[str, Any]],
318+
tool_usage_entries: Optional[List[Dict[str, Any]]] = None,
319+
) -> Tuple[int, int]:
320+
"""Sum input/output tokens from per-step 'stats' entries already appended
321+
to conversation, plus any tool-reported usage folded in separately (see
322+
``_extract_tool_usage``). Returns (total_input, total_output)."""
323+
total_input = 0
324+
total_output = 0
325+
for entry in conversation:
326+
if entry.get("role") == "system" and isinstance(entry.get("content"), dict):
327+
content = entry["content"]
328+
if content.get("type") == "stats" and "performance_stats" in content:
329+
stats = content["performance_stats"]
330+
total_input += _safe_number(stats.get("input_tokens"))
331+
total_output += _safe_number(stats.get("output_tokens"))
332+
for usage in tool_usage_entries or []:
333+
total_input += _safe_number(
334+
usage.get("prompt_tokens") or usage.get("input_tokens")
335+
)
336+
total_output += _safe_number(
337+
usage.get("completion_tokens") or usage.get("output_tokens")
338+
)
339+
return total_input, total_output
340+
341+
342+
def _query_ttft_seconds(conversation: List[Dict[str, Any]]) -> Optional[float]:
343+
"""Turn's ttft = the FIRST step's own time_to_first_token; a later step's
344+
value would drop all earlier tool-decision latency. None when step 1 has
345+
no positive value — never a fabricated 0.0."""
346+
for entry in conversation:
347+
if entry.get("role") == "system" and isinstance(entry.get("content"), dict):
348+
content = entry["content"]
349+
if content.get("type") == "stats" and "performance_stats" in content:
350+
if content.get("step") != 1:
351+
# Step 1's own poll failed/was skipped — never misattribute
352+
# a later step's latency as the turn's ttft.
353+
return None
354+
stats = content["performance_stats"]
355+
ttft = (
356+
stats.get("time_to_first_token")
357+
if isinstance(stats, dict)
358+
else None
359+
)
360+
if (
361+
isinstance(ttft, (int, float))
362+
and not isinstance(ttft, bool)
363+
and math.isfinite(ttft)
364+
and ttft > 0
365+
):
366+
return float(ttft)
367+
return None
368+
return None
369+
370+
371+
# Only these field names are ever accepted from a tool's self-reported
372+
# ``usage`` dict — deliberately narrower than "any dict under a `usage` key",
373+
# so a tool with an unrelated `usage` value (rate-limit/quota/disk usage, not
374+
# LLM tokens) is never misread as token accounting (#2899).
375+
_TOOL_USAGE_TOKEN_FIELDS = (
376+
"prompt_tokens",
377+
"completion_tokens",
378+
"input_tokens",
379+
"output_tokens",
380+
)
381+
382+
383+
def _extract_tool_usage(tool_result: Any) -> Optional[Dict[str, Any]]:
384+
"""Pull a tool-reported usage dict off a tool's own return payload, if
385+
present and shaped like real token accounting. Some tools make their own
386+
internal LLM calls outside the normal per-step chat-completion accounting
387+
(e.g. a triage tool that classifies many items with its own client calls)
388+
and report the aggregate on their own return value instead of through the
389+
per-step stats path. Never raises — a malformed payload (bad JSON, wrong
390+
shape, non-numeric fields) yields ``None``, the same as "no usage to
391+
report"."""
392+
try:
393+
payload = tool_result
394+
if isinstance(payload, str):
395+
payload = json.loads(payload)
396+
if not isinstance(payload, dict):
397+
return None
398+
usage = payload.get("usage")
399+
if not isinstance(usage, dict):
400+
return None
401+
has_real_token_field = any(
402+
isinstance(usage.get(f), (int, float))
403+
and not isinstance(usage.get(f), bool)
404+
for f in _TOOL_USAGE_TOKEN_FIELDS
405+
)
406+
return usage if has_real_token_field else None
407+
except (ValueError, TypeError):
408+
return None
409+
410+
303411
# Suffix appended to the last tool-result message when ``single_tool_per_turn``
304412
# agents have completed their one tool call. The model sees this and emits a
305413
# short final reply instead of calling another tool. Greppable for fixtures
@@ -533,6 +641,10 @@ def __init__(
533641
# post-registration skill-set load both see the explicit request.
534642
self._requested_skill_set = skill_set
535643
self.error_history = [] # Store error history for learning
644+
# Safe default so _execute_tool -> _fold_tool_usage never AttributeErrors
645+
# if called outside the normal process_query loop (e.g. directly in a
646+
# test); _process_query_impl resets this per-turn (#2899).
647+
self._tool_reported_usage: List[Dict[str, Any]] = []
536648
self.conversation_history = (
537649
[]
538650
) # Store conversation history for session persistence
@@ -2653,6 +2765,22 @@ def _tool_requires_confirmation(self, tool_name: str) -> bool:
26532765
return bool(flag)
26542766
return tool_name.startswith("mcp_")
26552767

2768+
def _fold_tool_usage(self, tool_name: str, tool_result: Any) -> None:
2769+
"""Record a tool's self-reported LLM usage (see ``_extract_tool_usage``)
2770+
against this turn's running total. Called from the single success path
2771+
inside ``_execute_tool`` so every caller is covered uniformly. Never
2772+
raises — extraction failures are already swallowed by
2773+
``_extract_tool_usage``; this method only appends.
2774+
2775+
A tool whose internal LLM calls already route through ``self.chat``
2776+
would double-count here — a constraint on future tools, not a live one.
2777+
"""
2778+
usage = _extract_tool_usage(tool_result)
2779+
if usage is None:
2780+
return
2781+
logger.debug("Tool '%s' reported its own LLM usage: %s", tool_name, usage)
2782+
self._tool_reported_usage.append(usage)
2783+
26562784
def _execute_tool(self, tool_name: str, tool_args: Dict[str, Any]) -> Any:
26572785
"""
26582786
Execute a tool by name with the provided arguments.
@@ -2796,6 +2924,7 @@ def _execute_tool(self, tool_name: str, tool_args: Dict[str, Any]) -> Any:
27962924
try:
27972925
result = self._call_tool_bounded(tool, tool_args, tool_name)
27982926
logger.debug(f"Tool execution result: {result}")
2927+
self._fold_tool_usage(tool_name, result)
27992928
return result
28002929
except ToolExecutionTimeout as e:
28012930
# Bounded-execution guard fired: the tool body blocked past its
@@ -3666,6 +3795,10 @@ def _process_query_impl(
36663795
self.current_step = 0
36673796
self.total_plan_steps = 0
36683797
self.plan_iterations = 0 # Reset plan iteration counter
3798+
# Tool-reported LLM usage this turn (see _fold_tool_usage / #2899) —
3799+
# reset per-turn since an Agent instance persists across queries in
3800+
# an interactive session.
3801+
self._tool_reported_usage: List[Dict[str, Any]] = []
36693802

36703803
# Add user query to the conversation history
36713804
conversation.append({"role": "user", "content": user_input})
@@ -5538,7 +5671,20 @@ def _process_query_impl(
55385671

55395672
final_answer = self.finalize_answer(answer_candidate, conversation)
55405673
self.execution_state = self.STATE_COMPLETION
5541-
self.console.print_final_answer(final_answer, streaming=self.streaming)
5674+
# Compute the real token total BEFORE printing the answer so it
5675+
# can ride the same event, instead of the post-loop aggregation
5676+
# below which runs after print_final_answer already fired
5677+
# (#2899). Output tokens only — "tokens actually generated",
5678+
# matching the tok/s calc downstream which is also output-only.
5679+
_pre_input_tokens, pre_output_tokens = _sum_conversation_tokens(
5680+
conversation, self._tool_reported_usage
5681+
)
5682+
self.console.print_final_answer(
5683+
final_answer,
5684+
streaming=self.streaming,
5685+
total_tokens=pre_output_tokens,
5686+
ttft_seconds=_query_ttft_seconds(conversation),
5687+
)
55425688
break
55435689

55445690
# Check if we're at the limit and ask user if they want to continue
@@ -5603,18 +5749,14 @@ def _process_query_impl(
56035749
# Calculate total duration
56045750
total_duration = time.time() - start_time
56055751

5606-
# Aggregate token counts from conversation stats
5607-
total_input_tokens = 0
5608-
total_output_tokens = 0
5609-
for entry in conversation:
5610-
if entry.get("role") == "system" and isinstance(entry.get("content"), dict):
5611-
content = entry["content"]
5612-
if content.get("type") == "stats" and "performance_stats" in content:
5613-
stats = content["performance_stats"]
5614-
if stats.get("input_tokens") is not None:
5615-
total_input_tokens += stats["input_tokens"]
5616-
if stats.get("output_tokens") is not None:
5617-
total_output_tokens += stats["output_tokens"]
5752+
# Aggregate token counts from conversation stats, plus any usage a
5753+
# tool self-reported (e.g. a triage tool's internal per-message LLM
5754+
# calls, #2899) — same helper the pre-answer computation above uses,
5755+
# reading identical inputs since nothing mutates conversation or
5756+
# self._tool_reported_usage between the two calls.
5757+
total_input_tokens, total_output_tokens = _sum_conversation_tokens(
5758+
conversation, self._tool_reported_usage
5759+
)
56185760

56195761
# Return the result
56205762
has_errors = len(self.error_history) > 0

0 commit comments

Comments
 (0)