Skip to content

perf(profiler): make the ragged-admission branch measurable — three channels on the front-alignment path - #113

Closed
heydryft wants to merge 3 commits into
feat/batch-admission-raggedfrom
perf/profile-ragged-padding
Closed

heydryft wants to merge 3 commits into
feat/batch-admission-raggedfrom
perf/profile-ragged-padding

Conversation

@heydryft

@heydryft heydryft commented Aug 17, 2026 •

Copy link
Copy Markdown
Contributor

feat/batch-admission-ragged branched before PR #78 merged, so it carries no
profiler at all
— and the question it now has to answer is exactly the one a
wall-clock timer cannot: the measured +155.6 ms per forward at K=32 (and
+0.0 ms at K=1, mean_batch identical across arms) is either GPU-busy,
host-blocked-on-GPU, or host-busy-while-the-GPU-idles. Those three look
identical from outside and have completely different fixes. Separating them is
the entire reason PR #78 exists.

Why not merge master

Tried first, rejected. git merge origin/master textually auto-merges but
compiles to 7 errors: master's scalar XsRollingCache::trim_tail_to and
this branch's per-row base/tokens are the same design decision made twice,
and reconciling them is a change to someone else's workstream, not
instrumentation. So arc-profiler/ is taken verbatim from master and the
spans are re-placed by hand at this branch's own call sites.

What is instrumented, and why each choice

Site Span Why
normal.rs attach_device / maybe_selftest / set_meta Without attach_device every device span resolves to nothing, and a device column of zeros reads exactly like "the GPU was idle"
engine/mod.rs step root, decode, prompt, scheduler.lock, scheduler.schedule, pipeline.lock, pipeline.step Decode and prefill are separate subtrees: a prefill step is orders of magnitude larger and averaging them hides the decode cost being hunted
kv_cache/mod.rs clone_in_cache, clone_out_cache, clone_in.alloc, clone_in.slice_set The batched-buffer rebuild — candidate mechanism B
kv_cache/mod.rs cache.front_align (device), kv.front_pad_grow (host) The per-slot padding — candidate mechanism A
deepseek4.rs model_forward (device) The denominator: 156 ms of host overhead means something different against a 100 ms forward than against a 700 ms one

kv.front_pad_grow wraps only front_pad_single's padding branch, so its
calls is literally how many row × slot × half buffers were re-materialised
this step
— the count that separates "thousands of tiny allocations" from "one
large copy" without any timing argument.

It is a host span on purpose: it runs up to rows × 43 × 2 times per step,
and two cudaEventRecords per call would be a device-side cost of the same
order as the thing being measured. The region's stream time is taken once,
at front_align_batch, so device_ns there is the GPU time of all the padding
and wall − sync − device is the host time spent issuing it.

Off-state cost is unchanged at ~2.9 ns per call site; nothing here runs unless
ARC_PROFILE=1.

Provenance

Measured with arc-tools-style gating: the package that produces the binary is
the package built (-p mistralrs-cli → mistralrs), the path comes from
cargo's own artifact stream rather than target/release/<guess>, the binary is
asserted to carry the built SHA, and the running server must report that same
git revision before any cell is driven
.


Measured on an H200 (2026-08-17), qtip2b UQFF, MTP depth 3, --max-seqs 256

The instrument first, because a profiler reporting from dark instrumentation
is this project's worst recurring fault.
Every cell below carries
device selftest: ... ratio=24.6x–44.2x — PASS: CUDA events are measuring execution, not launches, unresolved_device_spans: 0, violations: [],
misnested_spans: 0. Cost of running it: 58.266 tok/s profiled vs 58.348
unprofiled
at K=32, i.e. −0.14%.

Where a decode step goes (uniform lengths, admission OFF)

B step model_forward (device) host self sync device ÷ wall, whole run
32 716.6 ms 622.6 ms (87%) 109.8 ms 5.6 ms 91.6%
128 2,373.8 ms 2,259.5 ms (95%) 179.3 ms 18.0 ms 94.5%

This regime is GPU-bound, not host-bound. Fitting the two rows gives
step ≈ 165 ms + 17.3 ms × B, which predicts the independently-measured b=12
cell (372 vs 355 ms) and b=25 cell (596 vs 629 ms). The marginal cost of one
more sequence is 17.3 ms of GPU stream time; the host adds 0.7 ms.

What the two candidate mechanisms actually cost (mixed lengths, K=32)

node per step device host self calls/step
clone_in_cache (mechanism B) 28.3 ms 27.8 ms 0.9 ms 84 alloc + 84 slice_set
cache.front_align (mechanism A) 9.3 ms 9.3 ms 0.26 ms 1,313 front_pad_grow @ 6.9 µs

Both are real, both engage exactly as predicted — front_pad_grow rises
from 133 calls/step on uniform lengths to 1,313 on mixed, so calls tracks
raggedness — and both are GPU stream time, not host allocation stalls.
Together they are 37.6 ms against a 629 ms step (6%), ~97% of it device.

What ragged admission is worth here

workload mean_batch, OFF mean_batch, ON aggregate
uniform lengths 32.0 32.0 58.348 → 58.351 tok/s (0.0%)
mixed lengths 12.0 25.0 25.6 → 31.5 tok/s (+23%)

On a uniform workload at temperature 0 every row decodes the identical
trajectory, so nothing is ragged, the grant costs nothing and buys nothing —
the two arms produce bit-identical MTP telemetry. On mixed lengths the
refused arm runs 12 of 32 admitted sequences per step, which is the
bucket-shattering law measured on hardware.

Prefill is the larger term, and it is not a K=128 phenomenon

cell prompt steps prompt wall share of window
uniform K=32 1 43.2 s 50.3%
mixed K=32 4 42.7 s 67.6%
uniform K=128 — ~120 s before the first decode step the client saw 0 tokens in a 70 s window

12,160 prompt tokens in 43.2 s is ~281 tok/s of prefill. There is no chunked
prefill, so admitting K prompts blocks every running sequence for
K × prompt_len ÷ ~300 seconds.

What actually grows with B (uniform lengths, one bucket, admission OFF)

Same binary, same instrument, same step count, one run:

B step model_forward dev mla_attn dev moe dev host self sync
1 113.4 ms 104.9 58.0 29.1 9.2 0.5
8 288.5 ms 253.0 152.3 72.0 39.2 1.9
32 714.9 ms 622.3 398.9 157.9 107.8 5.8
128 2,373.8 ms 2,259.5 — — 179.3 18.0

Marginal cost of one more sequence, fitted over B=1→32: 19.4 ms/step, split

  • mla_attn 11.0 ms — 57%, device time;
  • moe 4.2 ms — 21%, device time;
  • host 3.2 ms — 16%;
  • sync 0.2 ms — 1%.

Extrapolated fixed cost at B→0 is ~94 ms, so ~87% of a B=32 decode step is
work proportional to B
, and 84% of that is on the GPU. The step-rate gain
from B=1 to B=8 is 3.1×, and B=1 to B=32 is 5.1×.

clone_in_cache does not appear in the uniform decode path at all: with a
stable cohort the engine issues CacheInstruction::Nothing, so the 86
allocations per step are never made. It costs 28.3 ms/step (4% of a B=32 step)
only when the cohort changes, or when ragged admission forces re-assembly every
step. That is what the fix for it is worth — measured, not assumed.

heydryft and others added 2 commits August 17, 2026 21:14
…c-profiler onto it, and instrument the front-alignment path

`feat/batch-admission-ragged` branched before PR #78 merged, so it carries no
profiler at all. The question it now has to answer — is the +155.6 ms per
forward at K=32 GPU-busy, host-blocked-on-GPU, or host-busy-while-the-GPU-idles
— is precisely the one a wall-clock timer cannot answer and the one #78's three
channels exist for.

Merging master in was tried first and rejected: it compiles to 7 errors because
master's scalar `XsRollingCache::trim_tail_to` and this branch's per-row
`base`/`tokens` are the same design decision made twice, and resolving that is
a change to someone else's workstream, not instrumentation. So the crate is
taken verbatim (`arc-profiler/`, unmodified) and the spans are re-placed by
hand at this branch's own call sites.

What is instrumented, and why each choice:

* `normal.rs` — `attach_device`/`maybe_selftest`/`set_meta`. Without
  `attach_device` every device span resolves to nothing, and a device column of
  zeros reads exactly like "the GPU was idle".
* `engine/mod.rs` — `step` root, `decode` and `prompt` as separate subtrees
  (a prefill step is orders of magnitude larger; averaging them hides the
  decode cost), `scheduler.lock`/`scheduler.schedule`, `pipeline.lock`,
  `pipeline.step`.
* `kv_cache/mod.rs` — `clone_in_cache`/`clone_out_cache`,
  `clone_in.alloc`/`clone_in.slice_set` (device), and the two that discriminate
  the candidate mechanisms: `cache.front_align` (ONE device span over the whole
  front-alignment region) and `kv.front_pad_grow` (a HOST span on
  `front_pad_single`'s padding branch only, so `calls` is literally how many
  row x slot x half buffers were re-materialised this step).
* `deepseek4.rs` — `model_forward`, one device span over the whole forward, as
  the denominator every host-side cost has to be read against.

`front_pad_grow` is a host span on purpose: it runs up to `rows*43*2` times per
step, and two `cudaEventRecord`s per call would be a device-side cost of the
same order as the thing being measured. The region's stream time is taken once,
at `front_align_batch`.

Off-state cost is unchanged at ~2.9 ns per call site; nothing here runs unless
`ARC_PROFILE=1`.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…t CUDA device

`device::timer_for` refused to attach a CUDA event timer whenever
`cu_stream()` returned NULL:

    let stream = dev.cuda_stream().cu_stream() as *mut c_void;
    if !stream.is_null() { return Box::new(CudaTimer::new(stream)); }

A NULL `CUstream` is **not** "no stream". It is CUDA's legacy default stream,
and cudarc says so in as many words at `CudaContext::default_stream` — *"the
default stream for this context (the null ptr stream)"* — constructed with
`cu_stream: std::ptr::null_mut()`. A candle device that was never handed an
explicit stream returns exactly that, which is the ordinary configuration.

So the guard rejected the common case, fell through to `NullTimer`, and every
device span in the run recorded nothing. Measured on an H200 tonight, on a V4
profile built `--features "cuda flash-attn"` against a device the report itself
names `Cuda(CudaDevice(DeviceId(1)))`:

    note: device selftest: NOT RUN (no CUDA event timer attached)
    unresolved_device_spans: 10200
    device_ns: 0.0 ms   sync_ns: 0.0 ms

⇒ **the three-channel separation PR #78 exists for has never produced a number
on this fork.** wall was real; device and sync were structurally unmeasurable.
The report was honest about it ("unmeasured, not zero", per D18) — which is why
this was findable at all — but it attributed the failure to a missing timer
rather than to a guard that refused a valid stream.

`cudaEventRecord(ev, 0)` is valid and records on the default stream, so the
handle needs no validation. The runtime does, so it is now asked rather than
assumed: probe once with a real `record()`, keep the timer if the event was
created and recorded, and only then fall back to `NullTimer`.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@github-actions

Copy link
Copy Markdown
Code Metrics Report
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
 Language              Files        Lines         Code     Comments       Blanks
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
 C Header                  5          305          210           52           43
 CSS                       2         1181         1036           34          111
 CUDA                     72        24328        17592         4018         2718
 Dockerfile                1           39           22            8            9
 JavaScript               16         3546         2676          482          388
 Jinja2                    7          694          656            5           33
 JSON                     74         4600         4597            0            3
 Makefile                  1            6            5            0            1
 Metal Shading Lan|       33        12224         9431         1142         1651
 PowerShell                1          300          227           30           43
 Python                  143        14830        12217          797         1816
 Shell                    23         5756         3964         1412          380
 Plain Text                4         3801            0         2479         1322
 TOML                     33         1485         1292           43          150
 YAML                      3           25           23            2            0
─────────────────────────────────────────────────────────────────────────────────
 HTML                      4         2687         2604           43           40
 |- CSS                    2          543          479           37           27
 |- JavaScript             1         1233         1215           12            6
 (Total)                             4463         4298           92           73
─────────────────────────────────────────────────────────────────────────────────
 Jupyter Notebooks         4          122           83           23           16
 |- Markdown               1           60           30           22            8
 |- Python                 1          122          113            1            8
 (Total)                              304          226           46           32
─────────────────────────────────────────────────────────────────────────────────
 Markdown                189        37703            0        28931         8772
 |- BASH                  70         1618         1189          313          116
 |- C                      2           12           12            0            0
 |- CUDA                   2           84           56           16           12
 |- JSON                  18          708          708            0            0
 |- PowerShell             1            1            1            0            0
 |- Python                23         1008          787          113          108
 |- Rust                  65         2048         1713           77          258
 |- TOML                   6          207          164            0           43
 |- YAML                   4           38           33            5            0
 (Total)                            43427         4663        29455         9309
─────────────────────────────────────────────────────────────────────────────────
 Rust                    662       307804       266560        13893        27351
 |- Markdown             477        22853          471        19669         2713
 (Total)                           330657       267031        33562        30064
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
 Total                  1277       451971       330166        73659        48146
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

…regated

Two device spans in `forward_4d` — `mla_attn` around `self.attn.forward` and
`moe` around `self.moe_or_mlp.forward` — aggregated across all layers.

Enough to answer the question actually being asked (what fraction of a decode
step grows with B); deliberately NOT the fourteen MLA sub-spans master carries,
which this branch predates and which would each fire 43x per step.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@heydryft

Copy link
Copy Markdown
Contributor Author

ArcGate: HELD — parked above #104, and the reason is now specific rather than open-ended.

Full analysis on #104. Short form: #104 and #122 (landed as master 006657e05) are two mutually exclusive designs for ragged decode, and they contend on the clone_in_cache cadence —

#122 (on master) #104
dead prefix masked via RAGGED_LEAD_PAD stripped via drop_dead_prefix
clone_in membership change only every step

#104's issues_cache_in forces clone_in_cache every step; #122's deferred strip lives inside clone_in_cache and exists precisely to avoid that (O(B × layers × 2) device copies per token — ~2,200/token at B=47, commit 3adb69477). Land both and those copies come back silently: nothing errors, no test fails, throughput just returns to the pre-#122 number.

Two things that are not true, both checked rather than assumed:

This is scope, not a verdict. Nothing here is ranked down or closeable; the blocker is now one A/B measurement — does #104's design buy anything #122's does not, priced against its per-step rebuild.

Also note: this PR currently shows 1 check, the comment bot — zero CI lanes have ever run on it, because it predates the stacked-PR trigger fix that is now on master. Any push starts the full 16 lanes.

Nothing deleted; branch untouched.

@heydryft

Copy link
Copy Markdown
Contributor Author

Already landed on master (superseded, in a strictly richer form) — this PR should be closed.

Checked the actual content, not the branch names:

  1. 66a61259d ("the device and sync channels were dead on every default CUDA device") is already upstream by git patch-id — git cherry -v origin/master origin/perf/profile-ragged-padding ab42c4508 marks it -.
  2. 583fda6ac ("port arc-profiler onto it, and instrument the front-alignment path") — the whole arc-profiler crate is on master (workspace member, mistralrs-core dep, arc-profiler/cuda feature) and so is every wiring site this commit adds: engine/mod.rs (step_scope/scheduler.lock/pipeline.step), kv_cache/mod.rs (clone_in_cache/clone_out_cache), pipeline/normal.rs (attach_device / maybe_selftest / set_meta, at normal.rs:1432-1437). git diff 583fda6ac origin/master -- arc-profiler/ is +370 / −4: master's copy is a superset.
  3. 30cdb6c3b ("split the V4 decode layer into attention and MoE") — master already has device_span("mla_attn") (deepseek4.rs:3256) and device_span("moe") (deepseek4.rs:3294), plus ~40 further spans. The commit message itself anticipates this: "not a substitute for the fourteen MLA sub-spans on master, which this branch predates."

Rebasing onto master produces add/add conflicts across the entire arc-profiler crate plus content conflicts in all four wiring files — the signature of content that arrived by another route. No rebase was forced.

The only thing left on this branch that is not on master is its inherited base commit ab42c4508, which belongs to #104.

@heydryft

Copy link
Copy Markdown
Contributor Author

Closing: superseded — this content is already on master, by another route.

This PR was one of five based on another PR's branch (feat/batch-admission-ragged, #104), so it triggered zero CI lanes and displayed only comment. That is what prompted the audit; #164 adds a lane that makes the state red instead of blank.

On inspection it does not need a rebase — it needs closing.

arc-profiler is already on master, and master's copy is newer:

master  arc-profiler/src/lib.rs   999 lines
#113    arc-profiler/src/lib.rs   977 lines

arc-profiler/ exists on master as a full crate (Cargo.toml, src/, tests/).

The second commit's content is on master too. 30cdb6c3b splits the V4 decode layer into mla_attn and moe spans; both span names are present in origin/master:mistralrs-core/src/models/deepseek4.rs.

git cherry still lists the two commits as unmerged only because they landed on master under different SHAs, not because the content is missing.

The remaining + commits in this branch (ab42c4508 — "admit ragged cohorts") belong to #104, which is still open. Closing this PR does not lose them.

Reopen if any of the above is wrong — nothing here is deleted.

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