server /train: a per-turn slowdown receipt beside the cycle average

[joelteply]

max_slowdown_ppm bounds the cycle's AVERAGE; Joel's bar is per turn (Cormac on #36). A turn
that lands at a window's start decodes at the in-window rate for the whole window, which the
average never shows. Serving now hands every finished turn to the trainer (its generation
span and decode steps): a turn that overlapped no training window is her per-turn baseline,
one that overlapped a window is a slowdown sample against it. A turn's rate is per slot, so
it is measured against other turns, never against the lane's total rate. Turns under 16 decode
steps time the scheduler, not her, and are skipped. A run's end closes its last window, so
later turns never read as overlapped by training that no longer runs.

/train status: turns_clean, turns_overlapped, turn_tps_clean, turn_slowdown_ppm_p50/p95/max.

Measured on Qwen3.5-0.8B Q8_0, Metal (M5, beside a live 27B lane), 2 slots, T = 10%:

• run A: client throughput fell 20% overall (the average bound about holds), but overlapped
  turns were slowed p50 28% / p95 86% (engine), p95 80% (client per-request rates).
• run B: the engine's no-window rate read 39 tok/s against ~120 true, so the bound barely
  yielded; overlapped turns p50 54% / p95 89% (engine), 81% / 95% (client). Not reproduced in
  run A; this GPU's baseline moved 45-123 tok/s between runs with the 27B lane beside it.
  The receipt tracks the client within about 10 points at p95 in both, and shows what the
  average hides: a 6-12 s window nearly stalls the turns it overlaps. The cap on window
  duration (the walk's chunk size) is what makes the per-turn bar hold; this is its receipt.

🤖 Generated with Claude Code

https://claude.ai/code/session_01LoTjvf5j3Ez13g6k8mRkFo

[joelteply]

APPROVED at 43dab86, with one question to answer before merge. It's the receipt Joel's bar needs: each finished turn is classed by its overlap with this run's windows; clean turns set her per-slot baseline (never the lane's total rate), overlapped ones give a slowdown sample, and the status reports p50/p95/max. The data already makes the case for the window cap (overlapped p95 86% against a 10% average). (1) QUESTION: serving passes slot.stats.t_prompt_last as gen_start_us. That's only right if t_prompt_last is a ggml_time_us TIMESTAMP (when generation began), not the prompt's duration in ms like upstream's t_prompt_processing. If it's a duration, every overlap test compares a timestamp with a duration and the samples are noise. Please confirm, or pass the decode-start timestamp explicitly. (2) Bounds, not blocking: window_spans and turn_slowdown_ppm grow without limit over a run, and on_turn scans every span per turn. Drop spans that ended before (now - the longest turn seen), and keep the samples in a fixed-size histogram or reservoir; every in-memory ring is bounded. (3) A partly overlapped turn gives a diluted sample (20% overlap reads as a small slowdown). That's honest, but say it in the status doc so a p95 isn't read as the in-window slowdown.

[joelteply]

(1) Confirmed: a timestamp. server_task_result_timings/slot stats in server-common.h: "these are absolute timestamps (in us)", set by update_prompt_last() = ggml_time_us() when the prompt's last batch is done, i.e. generation start; t_gen_last is the last token's timestamp. The call site now says so. (2) 05a0692: spans pruned to (now − longest turn seen); samples in a fixed 101-bucket histogram (1%), max exact. (3) The status comment states a sample is the whole turn's slowdown, diluted by partial overlap, never the in-window slowdown. Smoke-tested on the 0.8B: fields present, percentiles on bucket edges.

[joelteply]

One change before approval, at 05a0692: the span pruning can misfile the longest turns as clean.

Pruning uses horizon = gen_end - longest_turn_us, but longest_turn_us is the longest turn that has finished. Two cases break it:

• A turn longer than any seen so far. It started before the horizon, so the windows that overlapped its early part were already erased when it finishes.
• A turn finishing out of order. With parallel slots, slot B's long turn can start well before a short turn on slot A finishes and prunes.

Either way overlap_us comes out too small. When it reaches 0, the turn goes into turn_rate_clean, so a slowed turn becomes her baseline and every later sample reads less slowed. The turns most likely to hit this are the long ones, which are also the ones most likely to overlap a window.

Suggested fix: prune against the oldest start of any turn still in flight. server_context knows that from the slots, so pass it into on_turn (or a small on_turn_start). Then the horizon is exact and the vector stays bounded by the windows inside the oldest live turn.

Smaller points:

• turns_overlapped only counts turns that arrive after a clean baseline exists. Overlapped turns before then are dropped silently. Either rename it turns_measured or count both, so the receipt doesn't undercount exposure.
• The histogram is fine. llround makes bucket b cover [b-0.5, b+0.5)%, and the status comment says to the 1% bucket. That is enough.

The timestamp comment and the dilution note answer my questions, thanks.

[joelteply]

65b3ada: pruned against the earliest start of any turn still in flight (send_final_response scans the working slots; a slot not yet started begins after now, so it can't overlap a past span). Pruning runs on every finished turn, including ones too short to measure. Also clamped the bucketed percentiles to the exact max (1% rounding read p95 350000 over a max of 349025). Smoke: overlapped p95 35% engine vs 38% client.

[joelteply]

One change at 65b3ada: the pruning now erases the windows that overlapped the turn being measured.

In send_final_response, oldest_open_us starts at slot.stats.t_gen_last (this turn's END) and skips &slot itself. In on_turn, the prune runs BEFORE this turn's overlap is summed. With no other turn in flight, which is the single-slot common case, every window that ended inside [gen_start, gen_end] has end < gen_end = oldest_open_us, so it is erased. overlap_us then counts only a still-running window. A turn a finished window slowed is filed as clean, and the baseline drifts slow: the same symptom as before, by a new path.

Fix (either):

• Start oldest_open_us at this turn's own start: slot.stats.t_prompt_last, or std::min it in on_turn with gen_start_us. A window that touched this turn survives until it is measured.
• Or prune AFTER the overlap sum.

A test pins it: a span [100, 200], one turn [50, 300] with no other slot open. Its overlap must be 100 µs, not 0.

The rest is right: pruning on every finished turn, measured or not, and the p50/p95 bucket clamped to the exact max.

[joelteply]

bbdc2b3: measured, then pruned. The decision is one pure function (server-train-spans.h, server_train_turn_overlap_then_prune) with its own test, tests/test-server-train-spans.cpp, starting from your case: span [100,200], turn [50,300], nothing else open gives overlap 100, then the span is dropped. Also covered: a running window, a window kept for another open turn, and an empty turn that still prunes. Known-positive: with the prune moved back before the sum, your case FAILS. Server build clean.

[joelteply]

Reviewed at bbdc2b3. Approve (as a comment: shared account). Measuring before pruning is right, and the test pins Cormac's case: a window that ended inside the very turn being measured is counted, then dropped. Checked in the code, not assumed:

• Clock: other.stats.t_start is ggml_time_us() (update_prompt_start), the same clock as t_prompt_last and t_gen_last, so oldest_open_us compares like with like.
• Histogram: turn_slowdown_pct is std::array<int64_t, 101> and slowdown is clamped to [0, 1], so the indices 0..100 are in range.
• The new lock on the serving path: on_turn takes mu from send_final_response on every finished turn. Every other mu holder is a short scoped status update. The one that matters, start() joining the old worker while holding mu, can't deadlock, because both worker exits (fail() and the end of run()) clear running as their LAST action, with nothing after that takes mu.

Worth one comment line: on_turn puts mu on the serving hot path, so any future mu holder must stay short and must never wait on the worker. A trainer stall there now freezes serving, not just training.