[void-mckenzie]

Closes #813. Production deployments front FreeToken with proxies and dashboards that track per-request stats, and those read prefill/decode rates and cache hits from the response itself; without this block the numbers silently go missing. Every chat completion, completion and Responses response carries a llama.cpp-shaped timings object next to usage (fields and arithmetic from server_slot_stats::to_json), so frontends like llama-swap and Open Web UI show them. On streams it rides the final finish chunk as well as the include_usage chunk, like llama.cpp.

• prompt_n counts only the tokens evaluated after the cached prefix, and decode rates divide by n_gen - 1 (the first token rides the last prompt batch), matching llama.cpp exactly, so cache_n + prompt_n reconstructs the prompt total.
• Spans match feat(server): publish cumulative prefill and decode timing on /v1/stats #553's /v1/stats cumulative timing: prefill = request start to the first output reply, decode = between output replies. The two features report identical spans for the same request.
• cache_n is unconditional (llama.cpp and stats semantics); --enable-cache-report still gates only usage.prompt_tokens_details.cached_tokens.
• Engine and scheduler untouched; capture lives in the ack-consume loops, emission in the adapters.
• Anthropic /v1/messages is left out on purpose: llama.cpp emits no timings there either (to_json_anthropic keeps the strict Anthropic schema, with the cache hit in usage.cache_read_input_tokens), and FreeToken already reports that field under --enable-cache-report. Adding an off-spec key would be looser than llama.cpp itself.

Verified

• pytest tests/server/: 627 passed, 3 new tests (llama.cpp arithmetic, edge shapes, span capture) in the existing accounting file.
• Live serving, unsloth GLM-5.3-Flash UD-IQ4_XS (RTX 5090, ft serve ... --moe-cache-size 800 --max-prefill-length 12288): a 19,008-token cold prefill reports 1727 t/s over 11.0 s (2 chunks); a 1,800-token coding decode reports 16.31 t/s / 61.29 ms per token; a repeated 1,300-token prompt reports cache_n: 1280 and prompt_n: 20, summing to the prompt total. All four surfaces (chat stream + full, completions, Responses) emit the block.

[void-mckenzie]

Works with llama-swap now. When speculative decoding is eventually added, drafted/accepted fields can also be filled in to maintain parity with llama-server stats reporting.

[void-mckenzie]

@jason-fxz Once MTP/draft token generation is done, I can wrap up this PR. Does that timeline work for you?

[jason-fxz]

MTP is in (#836, #844), so this can go ahead now. Before adding the draft fields, the spans need to come from the scheduler instead of the API handler. Today prompt_ms starts when the handler starts waiting, so it includes queue time: a request that waits 30 s and then prefills 2000 tokens in 1 s reports prompt_per_second ≈ 65 instead of ≈ 2000. The decode stamps are taken when the API drains replies, so they also pick up tokenizer batching and client read speed.

Scheduler

The scheduler should keep a small per-request ReqStats struct that records the timestamps and draft counters below. Only the resulting durations and counts need to reach the API.

Semantics

All times are wall-clock times measured in the scheduler, not in the API process.

• queue_ms: from the moment the request enters the scheduler's waiting queue until its first prefill chunk is launched. It does not include HTTP parsing, templating or tokenization.
• prompt_ms (time to first token): from the launch of the first prefill chunk until the first sampled token is back on the host. Under chunked prefill it includes the gaps between chunks and any other requests' work that runs in between, as in llama.cpp.
• predicted_ms: from the first token until the last committed token.
• cache_n: prompt tokens served from the prefix cache at admission. prompt_n: prompt tokens actually computed, so cache_n + prompt_n = usage.prompt_tokens.
• predicted_n: equal to usage.completion_tokens, i.e. tokens actually committed, including under speculative decoding. The rates use predicted_n - 1 decode steps, because the first token comes from prefill.
• draft_n: drafted tokens summed over verify steps. draft_n_accepted: accepted drafts that were actually committed, counted after EOS/stop truncation, so it never exceeds predicted_n - 1.

These spans line up with vLLM's per-request metrics: queue_time_ms, time_to_first_token_ms (from scheduled to first token) and generation_time_ms.

Output (llama.cpp b10408+ server_slot_stats::to_json)

• Fields: the nine llama.cpp fields, plus queue_ms as a FreeToken extension, plus draft_n and draft_n_accepted only when draft_n > 0. Keep queue time out of prompt_ms, because llama-swap sums prompt_ms + predicted_ms and reads prompt_per_second.
• When to emit: whenever prefill was launched, including requests with one output token, so drop the prompt_ms <= 0 → None rule. Emit nothing for errors or aborts, and don't round the values.
• Chat and completions stream: put timings on the last chunk only. That is the usage chunk when include_usage is set, otherwise the finish chunk.
• Responses stream: put it at event data.timings on response.completed / response.incomplete, not at response.timings.
• Non-stream /v1/completions with several prompts: use the first prompt's own timings. That is what llama.cpp returns (arr[0]); one clock across all prompts is not.
• Gate the whole block behind one opt-in flag, e.g. --enable-timings-report, off by default. Hiding cache_n alone isn't enough, because usage.prompt_tokens - prompt_n still reveals the prefix-cache hit. vLLM (--enable-per-request-metrics) and SGLang (--enable-metrics) are opt-in as well.
• Docs: drop the /v1/stats sentence, since feat(server): publish cumulative prefill and decode timing on /v1/stats #553 isn't merged.

timings_per_token, which puts timings on every chunk, can be a follow-up.

[agammann]

The new /v1/completions timing accumulator spans the entire for prompt in prompts loop, but this endpoint already accepts an array of prompts and processes them sequentially. With two prompts, first_output_at is set on the first prompt and last_output_at is updated on the second, so predicted_ms includes the second prompt’s prefill/queue time, while prompt_ms includes only the first prompt’s prefill even though prompt_n sums both. The reported prefill/decode rates are therefore wrong for batch completions. Could you measure each prompt separately and sum its prefill/decode spans (or document and report a distinct aggregate wall-clock metric), with a two-prompt timing test?

[void-mckenzie]

@jason-fxz @agammann all addressed in 8b78f8a, rebased onto current main.

1. Scheduler spans: new per-request ReqStats stamped in the scheduler. queue_ms = waiting queue to first prefill chunk launch, prompt_ms = first chunk to first sampled token on the host (chunk gaps and interleaved work included, as in llama.cpp), predicted_ms = first to last committed token. cache_n / prompt_n from admission, predicted_n = committed tokens. The API layer takes no timestamps any more; only durations and counts ride the terminal reply.
2. Draft counters: draft_n += k per verify step, draft_n_accepted += n - 1 with n post stop-truncation, so it never exceeds predicted_n - 1. Both emitted only when draft_n > 0.
3. Output: llama.cpp b10408+ server_slot_stats::to_json shape, unrounded, plus queue_ms; the prompt_ms <= 0 -> None rule is gone. Streams carry the block on the last chunk only (usage chunk with include_usage, else finish chunk). Responses stream puts it at event data.timings on response.completed / response.incomplete, not on the response object.
4. Multi-prompt /v1/completions: first prompt's own spans, like llama.cpp arr[0] (agammann's point), with a two-prompt timing test.
5. Flag: everything behind --enable-timings-report, off by default. /v1/messages unchanged.
6. Docs: /v1/stats sentence dropped, flag and span semantics documented.

Tests: tests/server + tests/scheduler + tests/tokenizer 861 passed. Verified live, RTX 5090:

• gpt-oss-20b UD-Q4_K_XL: a request queued 402 ms behind a 22k-token chunked prefill reports that wait in queue_ms with prompt_ms clean (20.4k tok/s on the prefill); repeat prompts report cache_n; flag off emits nothing on chat, completions or Responses.
• Qwen3.8-Flash-Next-NVFP4 (HF, --speculative-algorithm mtp, k=3): draft_n 90 over 30 verify steps, draft_n_accepted 61, never above predicted_n - 1; predicted_n equals usage.completion_tokens.

timings_per_token left as the follow-up.

[jason-fxz]

@void-mckenzie
Thanks, this matches the semantics. Two small fixes before merge:

1. draft_n_accepted should add min(n, emitted), not n - 1. A verify step hands _commit_tokens the emitted accepted drafts plus the target's own token, and n - 1 assumes the last committed token is always the target's own. That only holds when nothing stops early. If EOS, a stop string or the length limit lands on one of the drafts, every committed token is an accepted draft. For example, with drafts A B C all accepted plus the target's D, and 2 tokens of budget left, the step commits A B, so the count is 2, not 1. That is the second request in test_drain_counts_drafts_and_attaches_timings. min(n, emitted) still never exceeds predicted_n - 1.
2. Use time.perf_counter() for the four stamps; it's the more precise clock for these spans.

[void-mckenzie]

accepted drafts now count min(n, emitted) instead of n - 1, so a stop landing on a draft counts every committed token as accepted (pinned by the truncation case in test_drain_counts_drafts_and_attaches_timings), and the four ReqStats stamps use time.perf_counter().

LEt me know if this looks good! Thanks!

[jason-fxz]

LGTM, thanks!