Where an agent round's time went

A round's elapsed time — CompletedAt − Timestamp on the assistant cell — says how long the user waited and nothing about why. On 2026-09-09 an Executive Assistant round took 3 min 11 s to answer a question that needed nine cheap tool calls; the thread showed Reasoning… (36s) ticking, then a batch of tool calls landing within the same second, then more reasoning. Was that the model, the mesh, or the mail API? The node could not say. Now it can.

The ledger

Every assistant cell that reaches a terminal state (Completed, Cancelled and Error alike) carries ThreadMessage.Timing, a RoundTiming:

A ModelCallTiming records startedAt, firstOutputMs (time to the first update that carries output), durationMs, the model the provider reported, the call's own inputTokens / outputTokens, and an outcome — Completed, Cancelled, Stalled (the stall guard abandoned it) or Faulted. A ToolCallTiming records name, startedAt, durationMs, timedOut, and the callId when the function invoker supplied one, which correlates it with the rendered ToolCallEntry.

The same numbers go to the log: one [ModelCall] line per provider call and one [RoundTiming] line per round, both at Information, so a portal that "feels slow" can be read from Loki without opening a thread.

Why the seams matter more than the numbers

The provider seam is below the function invoker. The stream ThreadExecution consumes is the OUTPUT of FunctionInvokingChatClient, which runs the tools BETWEEN the provider calls it forwards. A stopwatch there would time tool execution and the loop's own scheduling under the heading "model time" — a fiction that would then be believed. ProviderCallTimingChatClient wraps the provider client itself, the same layer as the stall guard, so what it times is one HTTP round-trip to the model endpoint and nothing else. It wraps OUTSIDE the guard so a stalled call is recorded with the duration it actually held the round, and named as stalled.

The first token is the first OUTPUT. An OpenAI-wire stream opens with an envelope chunk — {"delta":{"role":"assistant","content":""}} — almost immediately, before the model has produced anything. Counting it would make every reasoning model's thinking phase read as zero. The ledger uses the stall guard's definition (CarriesOutput): text with length, a function call, usage, any non-empty content.

The tool seam is the wrapper, not the stream. The rendered ToolCallEntry is stamped by the streaming loop when the function-call and function-result contents pass through; the gap between those two stamps includes the tail of the model turn that requested the call. AccessContextAIFunction is the one place every tool body runs, so its stopwatch covers the body and nothing else. It starts AFTER the argument pre-check — a call the model got wrong and that never ran is not timed as if it had — and stops in a finally, so a return, a throw and the wrapper's own timeout all report once.

Reading it

The chat footer shows the split next to the elapsed time: 3:11 · 🧠 2:58 ×4 · 🔧 1.2s ×9 — model time over the number of provider calls, tool time over the number of tool bodies. Glyphs and numbers only, so it reads the same in every language; the span's tooltip names it.

Reading a slow round starts with modelCalls[].firstOutputMs. A large first-output gap with a short remainder is the endpoint thinking: prompt processing on a long context, a reasoning model, gateway queueing. A small gap with a long duration is generation throughput. Many short calls is a long tool loop — look at toolCalls[] and at what the agent chose to call.

A cell has no ledger (timing is null) in three cases: it is still streaming, it was written before the ledger existed, or its round ended before the first provider call — no usable model, a history-load failure, a credit refusal, nothing to send. There was nothing to time; the cell's own text names the reason.

Two cautions. Sums are not wall time: tools may run concurrently within one iteration, so toolMs can exceed the wall-clock the tools occupied, and the round's own work — history load, cell writes, the summary pass — is in neither list; the remainder against CompletedAt − Timestamp is the engine's. And a CLI-harness round (Claude Code, Copilot) records an empty modelCalls list, not a wrong one: the harness brings its own client and runs its own tools, so the provider seam is not on its path.

The round that prompted this

Four provider calls on z-ai/glm-5.3, roughly 24k input tokens each, 74 s to the first output token of the first — the model, not the mesh. Before the ledger that was reconstructed by hand from tool-call timestamps and thread versions; now it is four rows on the cell.

Related

• Stall detection at the same seam, and the shared definition of "first output": StreamStallGuardChatClient.
• Token accounting per model: Model usage & bill.
• The thread's live heartbeat, Reasoning… (Ns), is the same signal at a coarser grain — it tells you the model is thinking NOW; the ledger tells you how long it thought, afterwards.