Skip to content

onnx: print the QDQ device leg's per-call sections, and measure the sign on a quiet box - #1195

Merged
bong-water-water-bong merged 2 commits into
mainfrom
1bit/onnx-qdq-split-printed
Nov 6, 2026
Merged

bong-water-water-bong merged 2 commits into
mainfrom
1bit/onnx-qdq-split-printed

Conversation

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator

Root cause

docs/onnx.md and docs/onnx-pack.md carried two statements that #1114 itself shipped as placeholders, and both
were false as of the next device window:

  1. docs/onnx.md: the six dev_split_* sections "have not printed yet — they appear from the next one on".
  2. docs/onnx-pack.md: the device leg is "not yet a speed one", and the 4.4 % row "needs a quiet-box repetition
    before anyone quotes it as the device leg's worth".

This PR is the window those sentences asked for, and the docs now carry what it printed. Docs only — no code
touched, no behaviour change.

The measurement

One npu-hold ticket, both EP arms back to back, two runs each, ONEBIT_EP_QDQ_PROF=1 on both, 32-token prompt +
8 decode tokens, one thread, the five M=32 designs, Release build of origin/main f406769 (the QDQ path is
byte-identical through current main 22a4e625 — git diff f406769..22a4e625 -- onnx/ep npu/ort npu/forward is
empty). Load1 1.3 / 1.6 for the host arm and 3.3 / 2.8 for the device arm against the watcher's load1 < 4 gate;
identical ids (576 11320 9109 374 264 3175 7546 10001), fallbacks=0, host-rows policy=0, device-busy=0, and
qdq runs=1764 = 196 groups × 9 passes, i.e. every fused call went to the array.

arm decode per pass, from the profile
our EP, array 1000.2 / 983.4 ms/token device calls 846.5, epilogue 23.6, other 113.4
our EP, host kernel 1073.6 / 1088.8 ms/token host loop 978.9, other 109.9

8.3 % ahead (means 991.8 against 1081.2 ms/token; per call 4.32 against the host loop's 4.99). Previously in this
file's record: 1.13–1.16× behind at load 1.2–1.4 and 4.4 % ahead at load 4.9–6.9.

The call's own sections, first printing

Per call over 1764 calls (run 2), against dev_call_ms = 4.32 (the sections sum to it exactly):

section ms/call share
dev_split_launch (launch + wait_kernel) 3.90 90 %
dev_split_wpack (weight pack + upload, cache miss) 0.25 5.8 %
dev_split_other (lock, kernel lookup, EP frame) 0.13 3 %
dev_split_readback (C invalidate + copy back) 0.036 0.8 %
dev_split_aupload / dev_split_async 0.004 / 0.004 0.2 %

So every non-multiply thing the leg does per call is 0.42 ms (9.8 %), or 0.54 ms with the 0.12 epilogue it pays
outside the call. The weight path, the readback, both flushes and the epilogue are ruled out as the model-level
residue, and no fix aimed at them can recover more than ~10 %.

What this deliberately does not claim: that launch is dispatch overhead. That section contains the kernel's own
run time
— the probe prices q at m=36 at 3.460 ms/call device against 5.836 host in the same window — so the
registry of this file's own 2026-11-04T20:24 correction ("the re-pack was never 295 ms/pass") applies: what is left of
that section once the multiply is taken out is the dispatch residue, not the section itself.

Also corrected while measuring

  • The 1.13× loss does not reproduce at the host-leg load it was taken at, and the text says why that is not an
    arm-for-arm repeat (this window's device arm ran at 2.8–3.3, not 1.2–1.4) rather than implying a clean like-for-like.
  • other is the noisiest row of the table (54 and 110 ms/pass on the host's runs, 119 and 113 on the device's) and is
    now stated as such: the 89 ms gap between the arm means is larger than that spread, which is why the claim is the
    mean of two runs.
  • onnx-pack.md's three separately-measured per-call costs (0.24 epilogue/pack etc.) are superseded in place by the
    full split from one window rather than left beside it.
  • Prefill is quoted as "ahead, magnitude unsettled": 725.5 / 746.3 ms against 1409.1 / 878.9, and those two host
    numbers are 60 % apart.

Gates

  • python3 tools/copyright.py --check → rc 0 (no new files).
  • Docs only: git diff --name-only = docs/onnx.md, docs/onnx-pack.md. Nothing in onnx/, npu/ or tests is
    touched, so no build/test claim is made here beyond CI's.
  • The build the numbers come from was verified before the ticket: CMAKE_BUILD_TYPE=Release (not the -O0 trap of
    2026-11-04T15:45), and strings ep/libonebit_ep.so | grep dev_split_ returns all six fields, so the binary carried
    onnx: time the device QDQ call's own sections, so dev_call_ms adds up on the line #1114. ctest there: 5/5 QDQ tests green (the one onebit_ep_proof failure is the long-recorded "NPU build with no
    ELF configured" state, not a regression).

No issue to close: this closes the two sentences #1114 merged. Raw window output, traces and both arms' id files are
kept at /tmp/qdq-prof-arms/ and /tmp/qdq-prof-arms.log on strixhalo.

…n is measured on a quiet box

Two statements in the merged pages were false. docs/onnx.md said the six
`dev_split_*` sections "have not printed yet"; docs/onnx-pack.md called the
device leg "not yet a speed one" and asked for a quiet-box repetition before
anyone quoted it. One window (load1 1.3-3.3, both arms, two runs each,
ONEBIT_EP_QDQ_PROF=1, identical ids, fallbacks=0, device-busy=0, all 1764
fused calls on the array) settles both:

  host arm      1073.6 / 1088.8 ms/token    host loop 978.9 ms/pass, 4.99 ms/call
  device arm    1000.2 /  983.4 ms/token    calls 846.5 + epilogue 23.6, 4.32 ms/call

i.e. 8.3 % ahead, and the call's own sections are now on the record:
launch+wait 3.90 (90 %, and it contains the kernel's multiply), wpack 0.25,
other 0.13, readback 0.036, flushes 0.008, so every non-multiply thing the
leg does per call is 0.42 ms (0.54 with the 0.12 epilogue). The weight path,
the readback and the epilogue are therefore ruled out as the model-level
residue, and the section that remains is the one that contains the multiply.

Also corrected while measuring: the 1.13-1.16x loss of the earlier row does
not reproduce at the host-leg load it was taken at (stated as not an
arm-for-arm repeat, since this window's device arm ran at 2.8-3.3), and
`other` is the noisiest row of the table (54-119 ms/pass across the four
runs), which is why the claim is the mean of two runs.

Docs only; no behaviour change, no code touched.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY at a2753126 (docs only; the device numbers are the author's window, what I re-derived is below).

Re-derived here:

  • The arithmetic of both tables: 7618.2/9 + 212.1/9 + 113.4 = 983.4 and 8810.2/9 + 109.9 = 1088.8; means 991.8 against 1081.2; 1 - 991.8/1081.2 = 8.27 %, so "8.3 % ahead" uses the same convention as the older "4.4 % ahead" row. Per call 846.5/196 = 4.32 against 978.9/196 = 4.99. The six sections sum to 4.324 against dev_call_ms 4.32, and the non-multiply set is 0.25+0.13+0.036+0.008 = 0.424 = 9.8 %, 0.544 with the 0.12 epilogue. 1764 = 196 x 9.
  • The sections exist in the code at this base: onnx/ep/onebit_ep_kernel.cpp:120-121 prints exactly dev_split_wpack/aupload/async/launch/readback/other.
  • The "QDQ path is byte-identical" sentence holds: git diff f406769 22a4e625 -- onnx/ep npu/ort npu/forward is empty, so measuring at the older sha is measuring this one.
  • The probe numbers the subtraction leans on (3.460 device / 5.836 host for q at m=36) were already in docs/onnx.md before this PR, so they are not new claims introduced with the sign.
  • Both placeholders are gone and replaced in place: onnx.md "no device window has printed them yet" and onnx-pack.md "not yet a speed one" / "needs a quiet-box repetition"; onnx-pack.md supersedes its three separately-measured per-call costs rather than leaving them beside the new split, as the body says.

Nit, and it is the only thing I would change: /tmp/qdq-prof-arms/ and the build it came from are gone — this box was rebooted at 19:59 AST and /tmp is a tmpfs, so the raw 1764-call profile, both arms' id files and the binary behind this table cannot be re-derived on the box any more (your text already says the earlier build is gone for the same reason). Every other lane's measurements in this repo keep their artifacts under ~/lb/<lane>-<timestamp>/. Next window, put the raw output there; then a reviewer can re-derive a section instead of checking that the numbers add up.

Not re-derived by me: the device numbers themselves (991.8/1081.2 ms/token, the 3.90 of 4.32 ms launch section, fallbacks=0). That would be another two-arm npu-hold window on a build that no longer exists here.

@github-actions

github-actions Bot commented Nov 6, 2026

Copy link
Copy Markdown

PR Reviewer Guide 🔍

Here are some key observations to aid the review process:

🎫 Ticket compliance analysis 🔶

1114 - Partially compliant

Compliant requirements:

  • Instrumented the QDQ device leg to time its own sections and print them
  • Updated documentation to reflect the new measurements and the sign of the performance difference
  • Verified that the new profiling fields add up to the total dev_call_ms value
  • Documentation accurately reflects the measured performance difference

Non-compliant requirements:

  • None

Requires further human verification:

  • None
⏱️ Estimated effort to review: 2 🔵🔵⚪⚪⚪
🧪 No relevant tests
🔒 No security concerns identified
⚡ Recommended focus areas for review

Documentation Update Accuracy

The documentation update in docs/onnx-pack.md claims that the device leg is now a "small speed one" with an 8.3% advantage, but this claim is based on measurements from a specific load condition (load1 1.3–3.3) and may not be representative of all conditions. The PR description states that the measurements were taken on a "quiet box" but does not specify the exact conditions under which the 8.3% figure was obtained, potentially leading to misinterpretation if the performance difference is load-dependent.

**Re-measured on the current tree those two arms are 930.5 against 972.9 ms/token, i.e. the array 4.4 %
ahead** — same window, two runs each, both agreeing on the sign, and the profile now splits a pass into
device calls 802.5 + epilogue 19.0 against the host loop's 879.0 with 94–109 ms of per-pass work that
neither leg touches. **Repeated on a quiet box (load1 1.3–3.3) the same sign is larger and is now the
quotable one: 983.4 / 1000.2 against 1073.6 / 1088.8 ms/token, i.e. 8.3 % ahead**, per call 4.32 against
Documentation Clarity on Measurement Conditions

The documentation in docs/onnx.md introduces a new section on "Where a pass actually goes, and the sign on the current tree" but does not clearly distinguish between the conditions under which the measurements were taken. The PR description mentions that the measurements were taken on a "quiet box" with specific load conditions, but the documentation does not explicitly state these conditions, which could lead to confusion when interpreting the performance figures.

**Where a pass actually goes, and the sign on the current tree.** The same two EP arms, two runs each, back to back in
one `npu-hold` ticket with `ONEBIT_EP_QDQ_PROF=1` on both — this is the quiet-box repetition the rows above asked for,
load1 1.3 and 1.6 for the host arm and 3.3 and 2.8 for the device arm (the gate is load1 < 4; the 15-minute average was
still falling from 9.8, this lane's own build), identical ids, `fallbacks=0`, `device-busy=0`, and all 1764 fused calls
= 196 groups × 9 passes on the array:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant