Repository navigation
onnx: return only the final logits row (1.4 GB less RSS), and the arithmetic on why prefill can't be shaved - #686
Conversation
The cached graph returned logits for every prompt position when the runner reads one row. Slicing to the final position drops peak RSS 7.98 -> 6.60 GB and changes no timing; applying the head to the last hidden row instead is no faster either (the head is 155M of 596M params). Round 3 in BENCHMARK-PARITY.md does the arithmetic: a 2048-token prefill is 2.4 TFLOP in ~3.2 s = ~760 GFLOP/s on eight cores, so the stage is compute-bound at the hardware and the graph has no headroom left. The slice is kept for the memory and because it is one line. Also records that a 2048-token prompt does complete on our dx NPU route (2678 tokens, 54.76 tok/s prefill, 48.9 s) - the earlier 'hang' was the harness asking for six 52-second repetitions.
… goes Wall-clock per stage cannot say which change is worth making. ORT already has the answer behind EnableProfiling; this exposes it as --profile PREFIX (the file is PREFIX_<timestamp>.json) and adds prof_summary.py to fold the trace by op. First use, one 2048-token prefill: 40% MatMul, 13% FusedMatMul, 16% Add, 6.7% Softmax, 6.3% Concat, 10% Where/Expand/Mul - and the two largest single nodes in the run are mask construction (one Add at 161.8 ms, one Where at 141.6 ms). So ~22% of prefill is the causal mask being rebuilt per step, which is graph shape we control, versus 53% matmul which needs precision or another device. Stacked on #686: both touch ort_run.cpp.
0dec70e to
7060b2e
Compare
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY (tprs-ready applied). I reproduced the bug and the fix on this box, not just the claim.
The off-by-end read is real, and the new expression fixes it. The comment says the old p + vocab*(seq-1) "read past the end of a one-row output" — so I built a model with exactly the shape your export now produces (the existing ~/wt/onnx-artifacts/qwen3-0.6b-cached.onnx with a Slice(logits[:, -1:, :]) inserted before the graph output, output name kept as logits), and ran main's ort_run and this branch's against it, same ids, 8 threads:
main (p + vocab*(seq-1)) ids: 140518 39423 13 358 <- garbage, as you said
#686 (p + count - vocab) ids: 264 11416 3110 315 <- matches the full-logits run
and on the un-sliced artifact both binaries agree exactly (264 11416 3110 315, prefill 54.8 vs 41.7 ms within noise), i.e. the change is a no-op for a graph that still returns [1,seq,V] and only matters for a sliced one. That is the whole risk of this PR and it is closed.
The arithmetic checks. 2 × 0.596e9 × 2048 = 2.44 TFLOP over ~3.2 s = 763 GFLOP/s, matching your ~760; the head is 151936 × 1024 = 155.6M of 596M parameters, matching "155M of 596M". The sliced logits a 2048-token prefill would stop materialising are 2048 × 151936 × 4 B = 1.245 GB, against a measured peak drop of 7.98 → 6.60 GB — same direction, same order, with the rest being allocator/arena effects.
What I could not reproduce: the 7.98 → 6.60 GB peak itself, because re-exporting needs torch's ONNX exporter and onnxscript is not installed on this box (ModuleNotFoundError: No module named 'onnxscript'). So that number is yours; the injection above is what I could build without it, and it is the part that matters for correctness.
Numerics unchanged is consistent with everything I ran (identical ids on the untouched artifact, and the KL figure you quote matches what docs/onnx.md already records). The negative result on the head-last variant is properly recorded in Round 3 with its per-length stddev, and the policy reason for keeping the one-liner (not depending on self.inner.model / self.inner.lm_head attribute names) is the right kind of reason to write down.
Two notes, neither blocking:
- The doc's "Round 3" table is good, but the RSS column mixes two things — the slice's 1.4 GB and the head-last variant's equal memory. One clause saying which variants those peaks belong to would stop a reader attributing the whole drop to the slice.
- The NPU datapoint you added (2,678 tokens after the template, 54.76 tok/s prefill = 48.9 s, 41.11 tok/s decode, exit 0, window GO-7) answers the open question in
BENCHMARK-PARITY.md, but the earlier "hang" framing ("the harness asking for six consecutive 52-second repetitions") is only in the PR body. Worth one line in the doc, where the next person will look.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
Re-verdict at the new head d9dfd40 (merge of main into the branch): READY, tprs-ready stays. This head is a merge commit, not a rebase, so the tree is different from the one I verified — what matters is that the PR's own content against main is unchanged, and it is:
$ git diff --stat origin/main d9dfd40
onnx/BENCHMARK-PARITY.md | 102 ++++++++++++++++++++++++++++++++++++++++++++---
onnx/export_qwen3.py | 7 +++-
onnx/ort_run.cpp | 5 ++-
3 files changed, 106 insertions(+), 8 deletions(-)
$ git log --oneline --no-merges origin/main..d9dfd40
7060b2e onnx: return only the final logits row, and measure what that buys
That is byte-for-byte the change I reviewed at 7060b2e1 — one non-merge commit, the same three files, the same +106/−8 — with main's later work merged in underneath (origin/main is an ancestor, so GitHub's MERGEABLE is the real thing). build pass (4m3s) at this head, Analyze x4 + CodeQL green, pr_agent red as always.
The two doc notes from my first review stay notes, not gates. Nothing else needed from the owner: this is mergeable as it stands.
One heads-up for the merge, not about this PR: #695 also edits onnx/ort_run.cpp (it adds --basic and rewires make_session). Whichever lands second will need the usual look at that file — #686's delta there is 5 lines, #695's is ~20, so I expect a trivial merge, but it is the one file they share.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
Gate line for the protocol, at head d9dfd400 (current). build pass, MERGEABLE, tprs-ready applied.
What that rests on, unchanged from my re-verdict above: this head is main merged in, not a rebase, so the tree moved — but the PR's own content against main is byte-identical to the head I reviewed (git diff --stat origin/main d9dfd400 -> onnx/BENCHMARK-PARITY.md, onnx/export_qwen3.py, onnx/ort_run.cpp, +106 −8; one non-merge commit, 7060b2e), and origin/main is an ancestor. The change itself — return only the final logits row and measure what that buys — was verified at 7060b2e1. The two doc notes I raised are notes, not gates.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At head 3ac18e3 (post-update, main merged in), build pass, MERGEABLE, tprs-ready applied.
The merge added no author change, as expected, and I checked that rather than assuming it:
$ git log --oneline --no-merges origin/main..3ac18e3
7060b2e onnx: return only the final logits row, and measure what that buys
$ git diff --stat origin/main 3ac18e3
3 files changed, 106 insertions(+), 8 deletions(-) # BENCHMARK-PARITY.md, export_qwen3.py, ort_run.cpp
$ git merge-base --is-ancestor origin/main 3ac18e3 # yes
Same one non-merge commit, same three files, same +106/−8 as the head I reviewed — so the content verdict carries unchanged, and this line is the one that moves. Awaiting merge.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At head 88055c4 (main merged in again after #699 landed), build pass, MERGEABLE, tprs-ready applied.
Third time this file has moved and nothing about it changed:
$ git log --oneline --no-merges origin/main..88055c4
7060b2e onnx: return only the final logits row, and measure what that buys
$ git diff --stat origin/main 88055c4
3 files changed, 106 insertions(+), 8 deletions(-)
$ git merge-base --is-ancestor origin/main 88055c4 # yes
Same single non-merge commit, same three files, same +106/−8 as every head since 7060b2e1. Content verdict stands; this is the current gate line.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At head 4cca180 (main merged in again after #695 landed; it is the last of the three still open), build pass, tprs-ready applied.
Same check, fourth head, nothing new to review:
$ git log --oneline --no-merges origin/main..4cca180
7060b2e onnx: return only the final logits row, and measure what that buys
$ git diff --stat origin/main 4cca180
3 files changed, 106 insertions(+), 8 deletions(-) # BENCHMARK-PARITY.md, export_qwen3.py, ort_run.cpp
$ git merge-base --is-ancestor origin/main 4cca180 # yes
$ parent of 4cca180: 88055c4 # the head I gated at 14:58Z
Content verdict unchanged since 7060b2e1: one non-merge commit, the same three files, the same +106/−8. #699 and #695 have both landed around it, so this is now the only labelled PR that is waiting on a merge — nothing ahead of it, nothing shared left in onnx/ort_run.cpp except #688 (still CHANGES).
… goes Wall-clock per stage cannot say which change is worth making. ORT already has the answer behind EnableProfiling; this exposes it as --profile PREFIX (the file is PREFIX_<timestamp>.json) and adds prof_summary.py to fold the trace by op. First use, one 2048-token prefill: 40% MatMul, 13% FusedMatMul, 16% Add, 6.7% Softmax, 6.3% Concat, 10% Where/Expand/Mul - and the two largest single nodes in the run are mask construction (one Add at 161.8 ms, one Where at 141.6 ms). So ~22% of prefill is the causal mask being rebuilt per step, which is graph shape we control, versus 53% matmul which needs precision or another device. Stacked on #686: both touch ort_run.cpp.
…prefill goes (#688) * onnx: --profile turns on ORT's per-node trace, and says where prefill goes Wall-clock per stage cannot say which change is worth making. ORT already has the answer behind EnableProfiling; this exposes it as --profile PREFIX (the file is PREFIX_<timestamp>.json) and adds prof_summary.py to fold the trace by op. First use, one 2048-token prefill: 40% MatMul, 13% FusedMatMul, 16% Add, 6.7% Softmax, 6.3% Concat, 10% Where/Expand/Mul - and the two largest single nodes in the run are mask construction (one Add at 161.8 ms, one Where at 141.6 ms). So ~22% of prefill is the causal mask being rebuilt per step, which is graph shape we control, versus 53% matmul which needs precision or another device. Stacked on #686: both touch ort_run.cpp. * onnx: add the Apache-2.0 per-file notice to prof_summary.py tools/copyright.py --check is the first thing CI runs and it was failing on the new file. * onnx: prof_summary splits executions by node name, and the prefill table says which one it is pi-prs blocked this at `31a32a2` on one line, and it was right: the run-boundary key was `(name, ts)`, and `ts` is a per-event timestamp, so the key was unique by construction and the boundary could never fire. Two executions were reported as one run. key = e.get("name") # a name recurring == a new execution Verified on a real trace from this tree rather than by reading it (Qwen3-0.6B cached graph, `--lens 512 --gen 2 --threads 8 --warmup 1 --repeat 1 --profile`): before: runs: 1 nodes: 12828 run 0: 1943.6 ms after: runs: 6 nodes: 12828 run 0 900.4 ms (2138 nodes), 72.6, 72.8, 735.0, 83.6, 79.4 6 = 2 repeats x (prefill + 2 decode steps), each execution exactly 2138 nodes -- the period the reviewer identified. The old table blended a 900 ms prefill with 73 ms decode steps. BENCHMARK-PARITY.md: the 2048 prefill table is relabelled as one ryzen *prefill execution*, and the section now carries this box's same-command measurement (MatMul 67.8%, FusedMatMul 12.5%, Add 7.1%, no `Where` in the top eight, largest node a MatMul at 374 ms, load 16 so shares only). The recommendation is now conditional: "hand the mask in" rests on ~22% mask work on ryzen and ~8% here, where matmul is two thirds, so it is only the next change on a box whose profile shows those nodes. * onnx: prof_summary prints the share table per execution, not one line per execution pi-prs at `d46b1a43` verified the boundary fix and then caught the sentence I added to sell it: BENCHMARK-PARITY.md claimed the tool "prints one table per execution, so prefill and decode cannot be blended into one share table any more". It did not -- it printed one *line* per run and then a single `top ops over all runs` table, which on a two-execution trace reads `MatMul 85.0 %` across prefill and decode. The doc asserted away the exact confusion this PR exists to remove. So the tool now does what the doc said, which is also what the reviewer asked for in the first review ("group by execution and report per-execution shares"): runs: 2 nodes: 4276 per execution (ms, then that execution's own top ops): run 0: 4091.5 ms (2138 nodes) MatMul 2772.8 ms 67.8% FusedMatMul 511.0 ms 12.5% Add 291.7 ms 7.1% run 1: 121.8 ms (2138 nodes) MatMul 39.4 ms 32.3% Expand 33.2 ms 27.2% Concat 23.5 ms 19.3% Split 13.4 ms 11.0% The all-runs total is kept (it is still useful for "what does this model do in total") but is now labelled as blended whenever a trace holds more than one execution. Verified on two real traces from this tree: 2 executions (prefill 4091.5 ms + decode 121.8 ms) and 6 executions from `--gen 2 --warmup 1 --repeat 1` (900.4, 72.6, 72.8, 735.0, 83.6, 79.4 ms at 2138 nodes each). --------- Co-authored-by: bong-water-water-bong <bong-water-water-bong@1bit.gg>
The cached graph returned
logits [1,seq,151936]for every prompt position while the runnerreads a single row (the final one, where the argmax comes from).
What changed
export_qwen3.py --cachedreturnsout.logits[:, -1:, :], so a 2048-token prompt stopsmaterialising 1.2 GB of logits it never reads.
ort_run.cppreads the last row of whatever the graph returned (p + count - vocab) instead ofindexing by
seq - 1. The old expression was correct for a full[1,seq,V]output and read pastthe end of a one-row one — that was a real bug and it showed up as garbage token ids the moment
the output got sliced.
What it bought: peak RSS 7.98 → 6.60 GB. Nothing else.
What it did not buy, and the measurement that says so: a second variant that runs the backbone
and then applies the head to the last hidden row (1 row instead of
seqthrough the 151936-widematmul) is not faster — 2048 prefill 567 tok/s sliced vs 640 head-last vs 621 before, all within the
30–460 ms per-length stddev. The reason is arithmetic: a 2048-token prefill is
2 × 0.596e9 × 2048 = 2.4 TFLOP in ~3.2 s = ~760 GFLOP/s on eight cores, i.e. compute-bound at the
hardware, and the head is 155M of the model's 596M parameters. Both variants are in
BENCHMARK-PARITY.md(Round 3) with the policy decision recorded: the one-line slice is kept over the backbone-plus-head
version because it is equal in memory and does not depend on
self.inner.model/self.inner.lm_headattribute names.
Numerics unchanged: ids
13 16 13 16, mean KL1.238e-07vs transformers' own cached greedy loop,max|dlogit| 2.12e-05,
ctest4/4.Also in here: the NPU row's open question is answered — a 2048-token prompt does complete on our
dx route (2,678 tokens after the chat template, 54.76 tok/s prefill = 48.9 s, then 41.11 tok/s decode,
exit 0, device released under window GO-7). The earlier "hang" was the harness asking for six
consecutive 52-second repetitions.