Skip to content

scheduler: time each request's decode per tick, not per delivered event - #51

Open
IsuraManchanayake wants to merge 2 commits into
basecompute:rc-0.1.6from
IsuraManchanayake:upstream/decode-rate-accounting
Open

IsuraManchanayake wants to merge 2 commits into
basecompute:rc-0.1.6from
IsuraManchanayake:upstream/decode-rate-accounting

Conversation

@IsuraManchanayake

Copy link
Copy Markdown
Collaborator

Supersedes #27, which was closed automatically on 2026-10-22 when its base, rc-0.1.3, was deleted after v0.1.3 merged into main; it was never reviewed. This is the same head branch and the same two commits, now against rc-0.1.6. The merge base is still d92e06e and a trial merge into rc-0.1.6 is clean.

The Linux ROCm staff bundle (0.4.0-rocm.20261020.0e453513, built with basecompute/baseRT-internal#754's tooling) ships a superfluid built from this head (ddfdeae), so its benchmark figures and first-token latency depend on this change; no release carries it yet.


What changed

  • Per-request decode is timed per tick. The scheduler stamps each lane once per tick, after the engine returns, with the tokens it has produced. A request's decode is then the tokens after its first tick, over the time from that tick's end to the last tick's end. This is the event-based figure's definition, measured once per tick instead of once per delivered Generated event. The first tick also ran the prefill, so it only opens the span. A preempted lane closes its span and the requeued one opens a new one. LaneEvent::Done and GenerateOutcome carry the result as decode: (tokens, seconds), and access_log uses it; the event-based span stays as the fallback.
  • The decode-cost estimate (decode_round_secs) counts only decode rounds. When a lane's prefill ends in the same tick, its first token comes from the prefill's logits and is not counted as a round.

ttft= and prefill= in the access log mean what they meant before. GenerateOutcome gains a public field.

Why

A tick hands a lane all its tokens at once. When the output changes channel (reasoning tags), the tick's tokens are committed as several events. The request side started its span at the first event, so the rest of the first tick counted against the next tick's time. On Qwen3.6-35B-A3B Q4, 128 tokens after a 4096-token prompt, --max-batch 1, baseRT on an AMD Strix Point (gfx1150, ROCm 10), three requests with the same 7.6 s wall logged -, 116.7 and 37.6 tok/s. The engine decoded at about 37.8 throughout. The session log shows the first tick of the 116.7 request committed as 19 text tokens, then 79 reasoning tokens 9 ms later; the next tick added 30 tokens in 0.79 s. llama.cpp b11681 (Vulkan) through the same server logged 31.3 for one request, against about 25.

The - came from the estimate. A prefill-only request (max_tokens 1) ends with a one-token "round", but that round only samples. It costs about 1 ms on baseRT, against 26 ms for a real round, and 0.45 s on llama.cpp's Vulkan backend, whose prefill runs on after its prefill timer stops. A run of such requests taught baseRT's estimate about 1 ms per round. The next tick that ended a prompt was then granted the 256-round cap beside it, so the whole generation landed in the prefill's tick: no decode rate, and a client got its first token at 7.5 s instead of 5.0 s.

The engine's own phase timers are not used to time decode, for the same Vulkan reason. In the tick that ends a prompt, gemma-4-E2B Q4_K_M charged 35.8 ms per decode round, against 22.1 ms in pure decode ticks. A first version of this change used them, and it put llama.cpp at 38–40 tok/s against 44 on the client's clock.

How it was tested

  • cargo clippy --all-targets -- -D warnings: clean.

  • cargo test: 1503 passed, 0 failed, 8 ignored. The real-model suites skip without their model environment variables.

  • New tests:

    • two in access_log_rate_tests: a tick split by a channel change, and a generation delivered in one tick, which has no rate;
    • measured_decode_adds_up_over_choices_and_ignores_empty_ones;
    • daemon_core::a_generation_reports_its_decode_after_its_first_tick, on the mock engine: the tokens counted are exactly those after the first tick.
  • On the box above, superfluid 0.1.3 (c5d0c56) with these commits applied (the files they touch match rc-0.1.3 except one line). Each run was a fresh server, SUPERFLUID_DEBUG_TICK=1: two 4096-token prefill-only requests, then 4096 + 128 requests. The client's figure is (128 − 1) / (request time − a prefill-only request's time).

    engine, model before (logged tok/s) after (logged tok/s) client
    baseRT, Qwen3.6-35B-A3B Q4 -, -, 38.0, 38.0 (sweep reps: -, 116.7, 137.4) 37.8, 37.9, 37.9 38.1
    llama.cpp, gemma-4-E2B Q4_K_M 44–46 46.4, 44.2, 42.0 46.5, 43.5, 41.6
    llama.cpp, Qwen3.6-35B-A3B UD-Q4_K_M 31.3 on a split tick 25.5, 25.1, 25.1, 24.7 25.4
    • baseRT's first prompt-ending tick now gets the 32-round floor (no estimate yet) and learns 27 ms per round; later ones get 44 rounds. ttft went from 7.5 s to 5.0–5.5 s.
  • cargo clippy --all-targets -- -D warnings

  • cargo test

  • Changes a wire protocol, the WAL format or the tick ABI: no. LaneEvent, RunJobResult and GenerateOutcome are daemon-side types.

🤖 Generated with Claude Code

…gs, and a prompt's first token is no decode round

The access log timed decode from when a request's Generated events arrived:
tokens after the first event over the time from the first event to the last.
A tick hands all of its tokens over at once, and the tick that ends a
prompt also decodes, so the rate was missing whenever that tick produced
the whole generation, and inflated when a channel change (Qwen3.6's
reasoning tags) split one tick into several events: the rest of the first
tick then counted against the next tick's time. Qwen3.6-35B-A3B, 128 tokens
after a 4096-token prompt, max-batch 1, on strix-point-1 (gfx1150): reps
logged "-", 116.7 and 37.6 tok/s at the same 7.6 s wall; the engine decoded
at 37.8 throughout.

The scheduler now adds up each lane's decode: per tick, the lane's share of
the tick's decode time (the engine's own when it times the phases apart, the
whole tick when it only decoded) and the tokens it decoded after its first.
Done carries it to the request, and the access log uses it when present.

A lane whose prefill ends in a tick takes its first token from the prefill's
logits, at no decode cost (about 1 ms of sampling against ~26 ms per round
on that model). The decode-cost estimate counted that token as a round, so
a run of prefill-only requests taught it ~1 ms per round, and the next tick
that ended a prompt was granted the 256-round maximum beside it: the whole
generation landed in the prefill's tick and the client saw its first token
only at the end. The estimate now counts only decode rounds.
…he engine's phase timers

The previous commit took each tick's decode time from the engine's own
decode_ns. llama.cpp's Vulkan backend runs the prefill asynchronously, so its
prefill timer stops before the GPU is done and the rest lands in the decode
phase: a prefill-only tick reported 0.45 s of decode for its one sampled
token, and the tick that ends a prompt charged 35.8 ms per round against
22.1 ms in pure decode ticks (gemma-4-E2B Q4_K_M, strix-point-1). That
put llama.cpp's per-request rate at 38-40 tok/s against 44 by the client's
clock.

The scheduler now stamps each lane once per tick, after the engine returns,
with the tokens it has produced, and the rate is the tokens after the
request's first tick over the time from that tick's end to the last one's
(the event-based figure's definition, measured once per tick, so a tick
split into several events by a channel change no longer counts its rest
against the next tick). The first tick also ran the prefill, so it only
opens the span. A preempted lane closes its span and the requeued one opens
a new one. The decode-cost estimate keeps the previous commit's fix: a
prompt's first token is no decode round.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant