Repository navigation
fix(ArcLab/ArcQuant): make prefill measurable, then ship the two kernels it proves were switched off - #196
Conversation
Code Metrics Report━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Language Files Lines Code Comments Blanks ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ C Header 5 305 210 52 43 CSS 2 1181 1036 34 111 CUDA 81 29475 20161 6275 3039 Dockerfile 1 39 22 8 9 JavaScript 16 3546 2676 482 388 Jinja2 7 694 656 5 33 JSON 75 4896 4893 0 3 Makefile 1 6 5 0 1 Metal Shading Lan| 33 12224 9431 1142 1651 PowerShell 1 300 227 30 43 Python 147 15371 12677 824 1870 Shell 42 10304 6858 2769 677 Plain Text 4 3801 0 2479 1322 TOML 33 1498 1294 54 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 213 48932 0 38081 10851 |- BASH 72 1655 1203 331 121 |- C 4 19 19 0 0 |- CUDA 2 84 56 16 12 |- JSON 19 779 779 0 0 |- PowerShell 1 1 1 0 0 |- Python 23 1008 787 113 108 |- Rust 68 2063 1727 78 258 |- TOML 6 207 164 0 43 |- YAML 5 41 36 5 0 (Total) 54789 4772 38624 11393 ───────────────────────────────────────────────────────────────────────────────── Rust 681 340988 293252 18096 29640 |- Markdown 504 32562 471 28063 4028 (Total) 373550 293723 46159 33668 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Total 1353 516771 363188 99077 54506 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ |
af638ca to
cd34ec4
Compare
Added: the CLI bench could still fabricate a number (
|
🔴 STOP-EVERYTHING: the fused head_dim=512 flash-sinks path computes something different from the reference, and it is ON by defaultFound while scoping the attention port. This is a correctness bug in V4 serving today, not a performance item, and it outranks everything else in this PR. The mechanism (static, confirmed by reading)
return mistralrs_paged_attn::flash_attn_sinks(q, k, v, Some(sinks), sdpa_params.softmax_scale, window_size);There is no mask argument. V4 builds a dense The codebase predicted this exactly, at
That kernel has landed ( The measurement (H200,
|
| leg | arcflash log |
output |
|---|---|---|
ARC_FLASH_512=1 (default) |
sinks path is FUSED |
'orem, etc. etc. etc. etc. etc. etc. etc. …' |
ARC_FLASH_512=0 (reference) |
sinks path is UNFUSED |
'> \n> #+end_src\n> \n> * Footnote\n> \n> Think about how to assign the letters to the numbers.\n> \n> My previous approach was to use the first letter of the english name of each number' |
485 prompt tokens — they differ here too, so this is not confined to long context:
| leg | output |
|---|---|
| FUSED (default) | '…\n\n## 2.2.2.2.2.2.2.2.2.2.2.2.2.2.2.2.2.2.2' |
| UNFUSED (reference) | '. \ncinder . cinder . cinder . cinder . cinder …' |
What this does and does not establish
Established: the two paths do not agree, at either length, at temperature 0, with the arm proved from the runtime log on both legs. At 6,649 tokens the reference produces coherent English and the default produces pure repetition.
Not established: that the unfused path is correct. I proved disagreement, not which side is right — though the unfused path is the reference the mask was written for, and it is the one producing coherent text. A F32 logit bit-compare is the next instrument; the text diff is only what I could get in the time I had.
Consequence for this PR's numbers: the prefill throughput measurements are A/B comparisons where both arms ran the same attention path, so the relative results (variant 0 vs 2, GEMV vs grouped) stand. But the absolute rates — the 8192 row especially — are rates for a kernel that is computing the wrong thing, and should not be quoted as product numbers until this is resolved.
Reproduce
mistralrs serve -p 8123 -m <V4_SRC> --from-uqff <UQFF>/qtip2b-0.uqff # default = FUSED
ARC_FLASH_512=0 mistralrs serve -p 8123 -m <V4_SRC> --from-uqff <UQFF>/qtip2b-0.uqff # UNFUSED
# same prompt, temperature 0, /v1/completions; grep the server log for "sinks path is"Suggested immediate action
Default flash_512_enabled() to off until the fused path takes the mask, and give flash_attn_sinks a custom-mask argument (FlashInfer's MaskMode::kCustom, not kCausal — causality here is raw sliding-window ∧ compressed block-causality ∧ caller padding, which a relative-distance window cannot express). I have not made that change in this PR because it is a serving-behaviour change that deserves its own review, not a rider on a benchmark fix.
✅ Settled, fixed, and verified — and there was no correctness/speed tradeoff to make1. Direction: the fused path is the wrong oneCompared by magnitude, not bit-equality — two implementations of the same math never agree bit-for-bit, so bit-inequality proves nothing. (My first attempt used bit-exact F32 and produced an uninformative "63,853/65,536 words differ"; that was my instrument error, corrected.) Control is a 1-ULP perturbation of the OUTPUT; a shared-input perturbation moves both paths together and can never fire. H200,
The fused result sits 60.3× closer to the unmasked reference, and its error against the masked reference (0.7749) is the same size as the mask's whole effect (0.7720). The mask is not approximated — it is discarded. The fused path computes plain causal attention; the reference is right. 2. Fixed at the interface, not at the caller
Three GPU regression gates, all passing:
End to end with the fused path enabled ( 3. The default decision makes itself — correct is also faster
No flag flip is needed. The gate is now correctness-driven rather than a default anyone has to remember: whenever a mask is present the fused arm declines, and for V4's CSA/HCA that is always. 4. GSM8K 96.0% is not voidMeasured 2026-08-15. The fused 512 path first became reachable 2026-08-17 23:24 ( |
The B=256 decode profile — the operating point nobody had ever profiledH200, DeepSeek-V4-Flash Achieved concurrency: 1. 🔑 Host vs device — the step is DEVICE-bound
Two independent instruments agree. That said, there was a large per-sequence host cost, and it was partly hidden behind the GPU rather than absent. See below. 2. Kernel shares at B=256 decode (
|
| share | ms/step | launches/step | kernel |
|---|---|---|---|
| 66.01% | 467.3 | 288 | fp8_gemm::fp8_matmul_tiled<bf16,32,32,32> |
| 8.69% | 61.5 | 129 | qtip2b_grouped_gemm_kernel |
| 8.41% | 59.5 | 1 | sm90_xmma_gemm (lm_head) |
| 4.32% | 30.6 | 898 | ucopy_bf16 |
| 2.70% | 19.1 | 12 | cutlass bf16 gemm |
| 1.11% | 7.8 | 3,295 | copy2d_bf16 |
fp8-45% / qtip-25% shares do not reproduce. I measure fp8 66.0% / qtip-grouped 8.7%. I also could not find those numbers anywhere in FACTS.md, so I cannot identify their provenance. The only ARC_TIME_DECODE component profile in the tree (FACTS.md:1382) is a different decomposition (mla_attn 49% / mhc 16% / 16% / moe 16%) and its own header says cudnn build — RE-MEASURE on no-cudnn — so it is compromised twice over: sync-serialised and built with cudnn, which is −62% on decode. Please stop quoting the 45/25 split.
fp8_matmul_tiled at 66% is where the next session's money goes.
3. The per-sequence term, located and removed
Same defect as PR #198, found independently here from the profile: layers.rs gated RoPE's batched path on seqlen_offsets.len() == 1 — the length of the vector, where the property needed is the distinctness of its values.
Before the fix, mla_attn.qk_norm_rope.rope alone spent 728.6 ms/step of HOST time against 163.5 ms/step of device time — 67% of a 1082 ms step, 16.9 ms per layer per step. forward_inverse_tail carried the identical bug.
per_sequence == 0 is confirmed, by a different route. I did not need the counter: that the fix produces any speedup at all proves the offsets were uniform. If they were ragged, uniform_seqlen_offset returns None, the loop still runs, and nothing changes. It changed by 1.36×.
Measured, not predicted: 1082.3 → 794.0 ms/step, 473.0 → 644.8 tok/s (1.36×). That exceeds the 19.9% the author scoped; 26.6% of wall came back.
On the launch-count prediction: rope_i_bf16 is now 156/step against 129 predicted — essentially confirmed. uneg_bf16 collapsed to 50/step from the predicted 11,008. But total launches are ~8,916/step, not 301 — the rope family is fixed; the remainder is dominated by copy2d_bf16 (3,295/step) and ucopy_bf16 (898/step), which are data movement and untouched by this fix.
4. MoE arm A/B at B=256 decode
Arm proved from the engagement log (grouped engaged: 1 vs 0):
| wall/step | aggregate | |
|---|---|---|
| grouped GEMM (default after the gate retraction) | 794.0 ms | 644.8 tok/s |
GEMV arm pinned (ARC_QTIP_ONDEVICE_MOE_MAX_TOKENS) |
1596.0 ms | 320.8 tok/s |
Grouped is 2.01× at decode B=256. This also reconciles the peer's B=1 result of 0.47×: at B=1, n_tokens = 1 ≤ DECODE_REGIME_MAX_TOKENS, so the GEMV arm runs regardless and the gate retraction does not apply. The two findings do not conflict.
Caveats
- The nsys trace covers the whole process; with
-p 0the single prefill step is ~1,024 tokens and decode dominates, but the shares carry a small prefill contamination. t(B) = 159 ms + 8.33 ms·Bdoes not describe this binary — it predicts 2,292 ms/step at B=256 and I measure 794 ms. The shape (a per-sequence cost) was right and is now located; the constants are not portable across the fixes in this branch.
17597e6 to
d665956
Compare
e6b0ccf to
b2805d2
Compare
Rebased onto
|
…rdown Three defects, all on the path that makes prefill measurable at all. 1. `pp N` reported `0.000±0.000` for every prompt benchmark. A prefill-only request (`max_len = 1`) finishes *during* the prompt step: `pipeline/sampling.rs` calls `seq.update_time_info()`, builds `group.get_usage()` and dispatches `Response::Done` from inside `step()`. But the default (non-paged) scheduler arm stamped `prompt_timestamp` and `total_prompt_time` only AFTER `step()` returned. So at the moment the usage was built `prompt_timestamp` was still `None`, `update_time_info` skipped `group.total_prompt_time`, and `get_usage` took its `== 0` branch and returned `avg_prompt_tok_per_sec: 0.0`. The PagedAttention arm already stamps before `step()`, with a comment saying exactly why. The fix was simply never applied to the arm that serves -- PagedAttention is banned here (it shadows the graph arm and measures zero tokens). Stamp on the default arm too. 2. The harness printed that zero into a results table and exited 0. A zero is not a measurement. Every row now has to carry evidence the engine processed the tokens the row claims to be about -- non-zero prompt tokens, the count actually asked for, a non-zero timed prefill, and a finite positive rate. A row that cannot exits 2 (environment failure, never 1) and prints no table. Adds a second, engine-independent instrument: wall-clock seconds and wall-clock prompt tok/s, so the engine's own numbers are only believed when an outside clock agrees. Also stops reusing one request id for every concurrent copy and repetition: `next_request_id()` was called once and the request cloned, so `concurrency * repetitions` sequences were in flight sharing one engine handle. 3. The binary aborted at teardown AFTER printing valid results. `Request::Terminate` only asks; nothing waited. `engine_handler` had no `.join()` anywhere in the workspace, so `main` returned while the engine thread was still releasing device memory and CUDA objects, and libc `exit()` ran CUDA's atexit handler concurrently with it -- a textbook `corrupted double-linked list` / SIGSEGV. `Drop for MistralRs` now joins each engine thread with a bounded 30s timeout, and says so loudly if it has to detach instead. Second half of the same race: `DedicatedDecodePath::new` binds the CUDA primary context and warns that skipping it gives "a SEGV in libcuda MOVAPS ... no error code, just a fault". Its `Drop` then made the same class of raw calls (`cuGraphExecDestroy`, many `cudaFree`) with no bind at all, made legal on a foreign thread by `unsafe impl Send`/`Sync`. It now binds exactly as `new()` does. This matters beyond tidiness: the abort libelled good runs. One chain already discarded an expensive valid measurement because its harness gated on rc==0. Parent system: ArcLab (harness) / ArcInfer (engine timing, teardown).
`grouped.rs` already states the rule: "a harness that reports a per-variant timing MUST show this counter advancing on the variant it claims to have measured, and NOT advancing on the others, or the number describes some other kernel." The counters existed and were public. Nothing in the workspace ever read them, so every grouped-vs-GEMV and variant-vs-variant comparison this harness could produce was unproven by construction. The bench now prints `grouped_launch_counts()` and the selected variant next to every results table, and says so explicitly when the total is zero -- which is the common case, because the grouped GEMM declines to run below its tile-fill boundary (~683 tokens at V4's top-6-of-256 routing) and the measurement is then the per-pair gather GEMV, not the kernel the reader will assume. Parent system: ArcLab.
…9.5% prefill)
The trellis grouped GEMM has three variants compiled into every binary. The
tuned ones were measured long ago at +39.4% (v1) and +41.6% (v2) per m-tile,
bit-identical in output, and then left unreachable: `grouped_variant()` fell
back to `QTIP_GROUPED_VARIANT_BASELINE` whenever `ARC_QTIP_GROUPED_VARIANT` was
unset, and the only callers of `set_grouped_variant` in the entire workspace are
inside `examples/qtip_grouped_curve.rs`. So every production prefill since the
variants landed has run variant 0, and the faster kernels existed only for a
benchmark nobody ran in serving.
✅ MEASURED END-TO-END, H200, DeepSeek-V4-Flash qtip2b, pp2048 b=1,
--no-paged-attn, on `arc-prefill`:
variant 0 (was default): 561.7 prompt tok/s | 1.780 ms/tok | TTFT 3.675 s
variant 2 (now default): 671.3 prompt tok/s | 1.490 ms/tok | TTFT 3.080 s
=> +19.5% prefill throughput, -16.2% TTFT
The arm is proved from the runtime launch counters, not from the build:
[129,0,0] on the control against [0,0,129] on the variant -- 43 layers x 3
expert matrices, and zero launches on the arms not under test. An
engine-independent wall clock agrees (557.2 -> 664.9 tok/s, +19.3%).
The end-to-end gain is smaller than the kernel gain because the expert gather is
~56% of a 2048-token prefill step; backing +41.6% on that share out of a measured
+19.5% overall is consistent.
Also: an unrecognised env value used to fall through to the baseline. With the
baseline now the slow arm, a typo would silently cost ~20% of prefill, so
unknown values warn and keep the default, and `baseline`/`0` is now an explicit
arm so the A/B knob still selects the control.
Parent system: ArcQuant / QTIP.
b2805d2 to
a2937ff
Compare
1 participant
Prefill was unmeasurable:
pp Nprinted0.000±0.000into a results table and exited 0. This makes it measurable, then uses the measurements to switch on two things that were already built, already correct, and shipping disabled.Three premises this PR retracts, with evidence
1. "TTFT ≈ 24 s / 11.8 ms per prompt token" does not reproduce. Measured at
d7742670abefore any change here: TTFT 3.675 s, 1.780 ms/prompt-token (pp2048, b=1, H200,--no-paged-attn). The 24 s figure is stale by many commits.2. "71.3% of the prefill step is the QTIP MoE expert gather" is no longer true. nsys (
--cuda-graph-trace=node, collection started at process start) at pp2048 with the grouped GEMM engaged:flash_attn_sinks_kernelqtip2b_grouped_gemm_kernelucopy_bf16GPU-busy is 99.4% (3.106 s kernel / 3.126 s wall). Attention is the prefill bottleneck now, not the MoE gather.
3. The reported
rc=139SIGSEGV did not reproduce in ~26 process exits — pre-patch binary, post-patch, under nsys, and the CLImistralrs benchpath, allrc=0. The teardown fix here is implemented from the existing static diagnosis inmemory/mission/BACKLOG.md, but it is not claimed to have cured anything, because the symptom never appeared.The 0.000, root-caused and proven
A prefill-only request (
max_len = 1) finishes insidestep():pipeline/sampling.rscallsupdate_time_info(), buildsgroup.get_usage()and dispatchesResponse::Donethere. The default scheduler arm stampedprompt_timestamp/total_prompt_timeonly afterstep()returned, so usage was built withprompt_timestamp == None,update_time_infoskippedtotal_prompt_time, andget_usagetook its== 0branch. The PagedAttention arm already stamps beforestep()with a comment explaining exactly this — it was never applied to the arm that serves (PagedAttention is banned here: it shadows the graph arm).Proof, same box, same model, same prompt, one commit apart:
The harness now exits 2 (environment failure, never 1) on any zero-token / zero-rate / zero-time row and prints no table; carries a second engine-independent wall clock (agrees with the engine to 0.8%); stops reusing one request id across every concurrent copy and repetition; and prints the grouped-GEMM launch counters, which nothing in the workspace read — so every prior kernel comparison this harness could produce was unproven by construction.
Two things that were built, correct, and switched off
Tuned grouped-GEMM kernel was unreachable.
grouped_variant()fell back toQTIP_GROUPED_VARIANT_BASELINEwith no env var set, and the only callers ofset_grouped_variantin the workspace are inexamples/qtip_grouped_curve.rs. Every production prefill ran variant 0.The tile-fill gate refused the grouped GEMM below 683 tokens. Both arms pinned to variant 2 so the only difference is which kernel runs, each arm proved from runtime launch counters (
[0,0,0]GEMV vs[0,0,129]= 43 layers × 3 expert matrices):The gate's justifying A/B — "1.00× at N=128 and N=512, 2.41× at N=1024" — does not reproduce. Grouped wins at every length measured, the margin grows monotonically, and it never inverts, including at 7.5% tile fill, two orders of magnitude below the amortization the gate was protecting. A gate defended by a measurement nobody can reproduce is worse than no gate.
Tile fill cannot be the deciding quantity, and the mechanism says why: the grouped kernel stages each woken expert's packed bytes once per m-tile instead of once per (token, expert) pair, and computes on tensor cores where the GEMV is scalar. Padding an under-full tile is cheap against both; fill only bounds the wasted mma, which is the smaller term.
DECODE_REGIME_MAX_TOKENSstays as a floor (the RUN-161 graph-capture safety rule, not a performance claim), andARC_QTIP_ONDEVICE_MOE_MAX_TOKENSstill pins the GEMV arm so the A/B stays runnable. Scope is theqtip2brung only — the LUT rung inmod.rskeeps its own boundary, unmeasured here.A peer measured forced-grouped in decode and saw 0.47× at B=1. Consistent with this: the only genuinely bad point is n=1. The threshold should be ~16, not 683 and not 128.
Net effect (H200, b=1,
--no-paged-attn, shipped defaults, zero env vars)b=8 aggregate (pre-change): 1080 / 990 / 588 / 224 prompt tok/s at 128 / 512 / 2048 / 8192. Prefill batches enormously at short prompts (128: 1080 vs 163 = 6.6×) and barely at long ones (2048: +5%), and the engagement log shows why — eight 128-token prompts land in one 1024-token step, which crossed the old kernel-switch boundary. The dead zone was per-step tokens, not per-request tokens.
Follow-ups found, not fixed here
mistralrs-cli/src/commands/bench.rs:136still rates tokens requested (prompt_len / elapsed), so the CLI can print a high number for a zero-token run. Thefix/bench-counts-produced-tokensfix never reached it.mistralrs-quant/src/qtip/mod.rs:3653(LUT rung) carries the same tile-fill gate retracted here, unmeasured — flagged deliberately, not changed blind.flash_attn_sinks_kernelat 60.3% with noprefill.cuhin the tree is now the largest single item in prefill.🤖 Generated with Claude Code