Repository navigation
onnx: --profile turns on ORT's per-node trace, and says where a 2048 prefill goes - #688
Conversation
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES (posted as a comment; no tprs-ready). One blocker, same class as #687: build is red on the copyright step.
build / Copyright notice on every file FAILURE
missing copyright notice: onnx/prof_summary.py
tools/copyright.py:fix adds the three-part notice it wants (copyright line, SPDX, "Licensed under the Apache License, Version 2.0", all within the first 20 lines).
The rest looks right:
ort_run --profile PREFIXis the smallest useful thing:EnableProfilingon the session options, ORT writes<prefix>_<timestamp>.jsonwhen the session is destroyed, andprof_summary.pyfolds it by op. That is the right instrument for "which change is worth making", and it costs nothing when the flag is absent (if (!st && profile) …).- The numbers it reports are labelled with the box, threads and dtype ("One 2048-token prefill on
ryzen, 8 threads, fp32"), which is the standard the rest ofBENCHMARK-PARITY.mdholds itself to. - It is stacked on #686 (both touch
onnx/ort_run.cpp), as the body says. #686 is READY now, so merge #686 first and rebase this onto it; the--profileflag should then land on top of thep + count - vocabindexing without conflict.
One suggestion while you are in there: have prof_summary.py print the trace's model_loading/session_initialization events separately from the op totals if it does not already — ORT's first-run JSON includes session-init time, and folding that into an op's total is how a one-off becomes a "hot" op in a summary.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES — the flag works and the copyright blocker is fixed, but the new summariser miscounts executions (reproducible, 2x) and the doc's share table does not reproduce on this box. Both are small.
Fixed and green: onnx/prof_summary.py has the Apache-2.0 notice (43a7e5e), tools/copyright.py --check rc 0, CI build pass.
--profile works: 1bit ort-run --model …/qwen3-0.6b-cached.onnx --cached --bench --lens 2048 --gen 1 --threads 8 --profile /tmp/tp.json writes tp.json_2026-10-31_10-54-37.json (8.4 MB) and prof_summary.py folds it. Good tool, right shape of output.
Blocker — prof_summary.py counts more than one execution as one run. With the default --warmup 1 the trace holds two executions of the graph, and the summary says one run and sums both:
--warmup 1: runs: 1 nodes: 8552 run 0: 6532.1 ms MatMul 58.0 % Add 10.3 % FusedMatMul 14.2 %
--warmup 0: runs: 1 nodes: 4276 run 0: 4120.6 ms MatMul 66.4 % Add 7.1 % FusedMatMul 12.1 %
The node count doubles and the total goes 4120 -> 6532 ms, while ort-run reports ~3.99 s of wall prefill — so the single-execution number is the right one and the 8552-node report is two runs labelled as one. Since --warmup 1 is the default way anyone will use the flag, the tool either has to group by execution and report per-execution shares, or refuse a trace with more than one. node_linear_196 appearing twice at 382.4 and 380.5 ms is the visible symptom.
The doc table does not reproduce here. Single execution, 2048 prefill, on this box (8 threads, load ~10 from the NPU serve, so a different box from your ryzen): MatMul 66.4 % (yours 40.1 %), FusedMatMul 12.1 % (12.9 %), Add 7.1 % (16.0 %), Softmax 3.7 % (6.7 %), Concat 2.2 % (6.3 %), and no Where anywhere in the top eight (Transpose and Expand are 1.0 % and 1.8 %), where your table has Mul/Where/Expand at 10.0 % combined and "the single largest node in the whole run is one Add at 161.8 ms and one Where at 141.6 ms". Mine: largest node 382 ms, and it is a MatMul.
That matters because the section ends by recommending the next graph change — "hand the mask in as a dtype-correct input" — on the strength of "~22 % is mask and broadcast elementwise work". On this box that work is ~9 % (Add + Expand) and the matmuls are two thirds. Either re-take the profile on an idle box before the next change is chosen on it, or label the table as one ryzen run and keep the recommendation conditional. The observation that FusedMatMul and Softmax shares are stable across both boxes (12–14 %, 4–7 %) is a good sign the tool is measuring the same thing.
Everything else in the diff is right: EnableProfiling before threads are set, const char * default null and null-checked, the usage line unchanged apart from the flag, and the doc says where the JSON goes.
… 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.
tools/copyright.py --check is the first thing CI runs and it was failing on the new file.
43a7e5e to
98be42b
Compare
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES — the copyright fix is in and green, but the summariser still reports N executions as one run: the new run-splitting block cannot ever fire, so the blocker I raised at 43a7e5e is not fixed.
Fixed: 98be42b onnx: add the Apache-2.0 per-file notice to prof_summary.py. tools/copyright.py --check rc 0; CI build SUCCESS, Analyze (c-cpp)/(python)/(actions)/(rust) SUCCESS, hw_gate SKIPPED, pr_agent FAILURE (coder-llm off). Rebuilt at this head with ninja 1bit (ONEBIT_ORT=ON, ORT 1.23.2), so the runs below are this code.
The boundary test is a no-op. It keys on (name, ts):
key = (e.get("name"), e.get("ts"))
if key in seen: run += 1 ...ts is a per-event timestamp, so the key is unique by construction — no event can ever match an earlier one, and runs stays 0. Two traces, both real:
| run | node events | distinct (name, ts) |
boundary hits | what the tool printed |
|---|---|---|---|---|
--warmup 0 |
21380 | 21380 | 0 | runs: 1 nodes: 21380, run 0: 281910.7 ms |
--warmup 1 |
25656 | 25656 | 0 | runs: 1 nodes: 25656, run 0: 404604.7 ms |
Those two traces hold 10 and 12 graph executions, not one: --lens 2048 --gen 1 runs prefill and one decode step per repeat, and ort-run itself reported n: 5 for the repeat loop. The executions are trivially separable by the sequence alone — node_Shape_1_kernel_time recurs at events 0, 2138, 4276, 6414, 8552, ... i.e. a period of 2138 — so the name repeating is the correct boundary marker, exactly as the comment above the code says it is; the extra ts in the tuple defeats it.
Why it matters, beyond the count: prefill and decode have different profiles and the tool blends them into one share table. Split by the 2138 period, the same trace gives:
execution 0 (prefill, 52881 ms node time) execution 1 (decode, 473.6 ms node time)
MatMul 72.6% MatMul 31.9%
Mul 10.9% Concat 20.6%
FusedMatMul 7.0% Expand 20.5%
Add 3.2% Split 13.7%
Softmax 1.6% FusedMatMul 9.4%
The headline MatMul 70.3 % the tool printed for the 10-execution trace is a blend of both shapes. Fixing the boundary turns every number in the doc section into something a reader can reproduce with one command; leaving it means the tool is one flag away from the ten-execution answer that made me open this.
The doc table still does not reproduce here. Prefill execution, 8 threads: MatMul 72.6 % (yours 40.1 %), FusedMatMul 7.0 % (12.9 %), Add 3.2 % (16.0 %), Softmax 1.6 % (6.7 %), Concat 0.8 % (6.3 %), no Where in the top eight, and the largest node in the run is a MatMul at 5450 ms — not the Add at 161.8 ms and Where at 141.6 ms. Caveat, in fairness to the table: this box was thermal-throttling for the whole measurement (Tctl 78-83 °C, the thermal guard freezing the scope every ~20 s), so I compare shares, not absolutes; an earlier quieter run here gave MatMul 66.4 % and the same absence of Where. Wherever it comes from, it is not this tree's profile, and the section's recommendation ("~22 % is mask and broadcast elementwise work ... hand the mask in as a dtype-correct input") rests on it. Either re-take the table with the fixed tool on an idle box and say which execution it is, or label it as one ryzen prefill and make the recommendation conditional.
The rest of the diff is right and I would keep it: EnableProfiling before the thread setting, const char* default null and null-checked, the flag absent costs nothing, and per-execution printing already exists — only the detection is wrong.
Housekeeping: branch is 2 commits behind main (merge base 6fba3d3), no conflict. Fix the boundary key and this is one step from READY.
|
VERDICT: CHANGES Fresh verdict at the same head, as asked — but the premise needs correcting: my verdict at this head never said the copyright was missing. My review at 23:03Z opens "the copyright fix is in and green" and lists The blocker is key = (e.get("name"), e.get("ts"))
if key in seen: run += 1 ...
Those hold 10 and 12 graph executions ( Suggested fix (one line, and it makes the comment true): key = e.get("name") # a name recurring == a new executionwith the usual caveat to confirm no node name recurs within one execution on your trace before trusting it. Why it matters beyond the count: prefill and decode have different shapes and the tool blends them. Split by the 2138 period, the same trace gives execution 0 (prefill) The doc table still does not reproduce here (prefill execution, 8 threads): Everything else in the diff is right and I would keep it: Rebase note: main is now |
|
VERDICT: CHANGES At the new head CI at this head was still Unchanged blocker: the run-boundary key includes key = (e.get("name"), e.get("ts"))
if key in seen: run += 1 ...Measured on real
That is 10 and 12 executions reported as one. They separate cleanly on the name alone — The fix is one line: key = e.get("name") # a name recurring == a new execution(confirm on your own trace that no node name recurs within one execution first; if one does, use the periodic reset on the first node name instead.) It matters beyond the count: prefill and decode have different shapes and the tool blends them into one share table — prefill The doc table also still does not reproduce here ( Everything else in the diff is right and stays: |
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES
Not the copyright. It is green at this head and I re-verified it just now: tools/copyright.py --check rc 0 with onnx/prof_summary.py from 31a32a26 in the tree, and CI build + CodeQL + Analyze ×4 are all completed success here. My verdict has never been about the notice.
What the blocker is. The rebase moved the base only — the summariser is byte-identical to the one I reviewed:
git diff 98be42bc:onnx/prof_summary.py 31a32a26:onnx/prof_summary.py -> 0 lines
so the run-boundary key still includes ts, which is unique per event and can never repeat:
key = (e.get("name"), e.get("ts"))
if key in seen: run += 1 ...Measured on real --profile traces from this tree (Qwen3-0.6B, --lens 2048 --gen 1): --warmup 0 -> 21380 node events, 21380 distinct keys, 0 boundary hits, printed runs: 1 / run 0: 281910.7 ms; --warmup 1 -> 25656 events, 25656 distinct, 0 hits, runs: 1 / run 0: 404604.7 ms. Those traces hold 10 and 12 executions (ort-run printed n: 5 for the repeat loop, one prefill plus one decode step each). They separate cleanly on the name alone — node_Shape_1_kernel_time at events 0, 2138, 4276, 6414, … — which is what the comment above that code already says.
The fix is one line:
key = e.get("name") # a name recurring == a new executionIt matters beyond the count: prefill and decode have different shapes and the tool folds them into one table — prefill MatMul 72.6 % / Mul 10.9 % / FusedMatMul 7.0 % / Add 3.2 % against decode MatMul 31.9 % / Concat 20.6 % / Expand 20.5 % / Split 13.7 %, versus the printed MatMul 70.3 %. Until the boundary works, the doc's "share of 4182 ms" is not reproducible with the flag anyone will actually pass.
Separately, the doc table still does not reproduce here (MatMul 72.6 % vs 40.1 %, no Where in the top eight, largest node a MatMul at 5450 ms rather than the Add at 161.8 ms and Where at 141.6 ms) — fair caveat that this box was thermal-throttling (Tctl 78-83 °C) throughout so I compare shares only, and an earlier quieter run gave 66.4 %. Label it as one ryzen prefill execution, or re-take it with the fixed tool.
tprs-ready is deliberately not on this PR, so the waiter cannot merge it. One line and I re-verdict immediately — everything else in the diff (EnableProfiling placement, null-checked const char*, per-execution printing) is right and stays.
…ble 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.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES
At d46b1a43. The code fix is right and verified — key = e.get("name"), with a comment that names the trap. What is left is one false sentence in the doc, about that same fix.
Verified on a real trace (ort-run --model qwen3-0.6b-cached.onnx --cached --bench --lens 64 --gen 1 --threads 8 --warmup 0 --repeat 1 --profile, 2 executions in the file), old script against new:
OLD (31a32a26): runs: 1 nodes: 4276 run 0: 2134.2 ms (4276 nodes)
NEW (d46b1a43): runs: 2 nodes: 4276 run 0: 1730.0 ms (2138 nodes)
run 1: 404.2 ms (2138 nodes)
So the boundary now fires, the execution count is real, and prefill (1730 ms) is no longer blended into decode (404 ms). That was the blocker and it is closed.
What is not true is the sentence that sells it. BENCHMARK-PARITY.md now says:
--profileplusprof_summary.pynow prints one table per execution, so prefill and decode cannot be blended into one share table any more.
The tool prints one line per execution (total ms and node count), then a single aggregate table — top ops over all runs (share of N ms of node time) — and top individual nodes is likewise sorted across all runs. On my 2-execution trace the aggregate table reads MatMul 85.0 % over both, i.e. prefill and decode are still blended in the share table. Anyone following the default --warmup 1 gets exactly that, which is the confusion I opened this PR about, now asserted away in the doc instead of fixed.
Two ways to close it, both small, your choice:
-
Either make the sentence true — print a table per run (about six lines inside the existing loop over
runs):for r in sorted(runs): c = collections.Counter() for e in runs[r]: c[e.get("args", {}).get("op_name", "?")] += e.get("dur", 0) g = sum(c.values()) or 1 print(f"\nrun {r} ({g/1000.0:.0f} ms):") for op, us in c.most_common(a.top): print(f" {op:<22} {us/1000.0:9.1f} ms {100.0*us/g:5.1f}%")
-
Or reword it to what the tool does: "prints one line per execution, so a blended run is visible; the op table below sums all runs — profile a single execution (
--warmup 0 --repeat 1) for a stage's own shares."
The added strixhalo table and the conditional recommendation are good and I would keep them as written: "worth doing only if a profile on the box you care about shows those mask nodes" is the right conclusion, and FusedMatMul (12-13 %) / Softmax (4-7 %) agreeing across boxes is the right reason to trust the instrument. The tables are labelled "one 2048-token prefill execution", which makes them reproducible — that part is exactly right.
CI at this head: build, CodeQL, Analyze ×4 completed success; tools/copyright.py --check rc 0. Fix that sentence (or the table loop) and tprs-ready goes on immediately — this is the only thing left.
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES
At 32b85060 (rebased onto 4968bb29 after #687 merged). The author patch is unchanged — patch-id 3b62eccd1cf6 at the head I reviewed and at this one — so the one remaining item is exactly as before, and the code fix I verified still stands.
Verified earlier on a real trace (--lens 64 --gen 1 --warmup 0 --repeat 1): old script runs: 1 / 2134.2 ms over 4276 nodes; new script runs: 2 / 1730.0 ms + 404.2 ms over 2138 nodes each. key = e.get("name") works.
The sentence in BENCHMARK-PARITY.md still says the tool "prints one table per execution, so prefill and decode cannot be blended into one share table any more". It prints one line per run plus a single aggregate top ops over all runs table — on my 2-execution trace that aggregate read MatMul 85.0 % across both. Either add the ~6-line per-run op table (the fix becomes true) or reword to "one line per execution; the op table sums all runs, so profile a single execution for a stage's own shares".
That is the only thing between this and READY. CI at this head: build, CodeQL, Analyze ×4 completed success.
PR Reviewer Guide 🔍(Review updated until commit 5fc4acd)Here are some key observations to aid the review process:
|
… 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).
|
Fixed at That is a 2048-token prefill against its decode step on this box — the split you were after. The all-runs total is kept (useful for "what does this model cost in total") but is labelled Verified on two real traces from this tree: the 2-execution one above, and 6 executions from Rebased onto |
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At cf38bba8. The fix went the better of the two ways I offered: the tool now prints one table per execution, and the aggregate is labelled as a blend — so the sentence in the doc is true rather than reworded.
Ran it on a synthetic two-execution trace (same node names, new timestamps — what a real second execution looks like; no model needed):
runs: 2 nodes: 6
per execution (ms, then that execution's own top ops):
run 0: 6.0 ms (3 nodes)
MatMul 3.0 ms 50.0%
Add 3.0 ms 50.0%
run 1: 6.0 ms (3 nodes)
…
all runs blended (share of 12 ms of node time) -- read the per-execution tables above for a stage's own shares:
MatMul 6.0 ms 50.0%
Per-execution totals and per-execution op shares, with the blended table labelled and pointed at the tables above. That closes the thing I opened this PR for: prefill and decode can no longer be blended without the reader being told.
The boundary itself I verified earlier on a real trace (--lens 64 --gen 1 --warmup 0 --repeat 1): old script runs: 1 / 2134.2 ms over 4276 nodes; new script runs: 2 / 1730.0 + 404.2 ms over 2138 nodes each — and key = e.get("name") is still what does it.
Not verified: the doc's strixhalo share table against a fresh profile (unchanged from my earlier review — it was taken under thermal load and I compare shares only), and the ryzen row, which is the author's.
tprs-ready applied.
|
Persistent review updated to latest commit 90741d9 |
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At 90741d99, rebased as the merges ahead of it landed. The author patch is byte-identical to the head I reviewed — patch-id from the merge base is unchanged before and after — so only main arrived in the rebase and my review stands without re-reading.
Nothing new to verify; everything in my earlier verdict on this PR, including what I recorded as not-verified-by-me, applies unchanged at this head.
|
Persistent review updated to latest commit 20a13cd |
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At 20a13cd5, rebased as the merges ahead of it landed. The author patch is byte-identical to the head I reviewed (patch-id from the merge base unchanged), so only main arrived and my review stands without re-reading. Nothing new to verify; everything in my earlier verdict, including what I recorded as not-verified-by-me, applies at this head unchanged.
|
Persistent review updated to latest commit d573357 |
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At d5733571, clean rebase (identical patch-id). My review stands: the tool now prints per-execution tables plus a labelled "all runs blended" aggregate — I verified that on a synthetic two-execution trace — and the boundary itself on a real one (runs: 2, 1730.0 + 404.2 ms over 2138 nodes each) via key = e.get("name").
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At 318c2a79, rebased as the merges ahead of it landed. Author patch byte-identical to the head I reviewed (patch-id from merge base unchanged), so only main arrived and my review stands without re-reading. Nothing new to verify; everything in my earlier verdict, including what I recorded as not-verified-by-me, applies at this head unchanged.
|
Persistent review updated to latest commit 318c2a7 |
|
Persistent review updated to latest commit 5fc4acd |
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY
At 5fc4acde — mergeable: true, state clean. The author patch is byte-identical to the head I reviewed (patch-id 2d88494bfd53 before and after), so this is a clean rebase and my review stands unchanged.
The substance, from the head I verified: the summariser splits executions (key = e.get("name") — on a real trace old script runs: 1 / 2134.2 ms over 4276 nodes, new runs: 2 / 1730.0 + 404.2 ms over 2138 nodes each), and it now prints per-execution tables plus a labelled "all runs blended … read the per-execution tables above" aggregate — which I confirmed on a synthetic two-execution trace. The doc's sentence is therefore true rather than reworded.
Not verified: the strixhalo share table against a fresh profile (taken under thermal load; I compare shares only) and the ryzen row, which are the author's.
tprs-ready is on it.
Stacked on #686 (both touch
onnx/ort_run.cpp); merge that first, or merge both together.Wall-clock per stage cannot say which change is worth making. ORT already carries the answer behind
EnableProfiling— this exposes it and folds it.ort_run --profile PREFIXenables the trace; ORT writesPREFIX_<timestamp>.jsonwhen the sessionis destroyed, so the flag is a prefix and not a filename.
onnx/prof_summary.pyfolds that trace byop_name, splits it perRun(so prefill and each decodestep are distinguishable) and lists the largest single nodes.
First use — one 2048-token prefill,
ryzen, 8 threads, fp32 (4182 ms of node time):MatMulAddFusedMatMul(attention)SoftmaxConcat(cache stacking)Mul+Where+ExpandThe two largest single nodes in the entire run are mask construction: one
Addat 161.8 ms and oneWhereat 141.6 ms. So ~22% of prefill is the causal mask being rebuilt as a[1,1,2048,2048]tensor inside the graph every step, and that is graph shape we control — which is also why it is worth
revisiting the mask-as-input interface that was dropped earlier for an unrelated
Expandfailure atzero-length
past, this time with the cost known.The other 53% is matmul, which no graph change reaches: it wants precision (see #687) or another device.