Skip to content

onnx: time the device QDQ call's own sections, so dev_call_ms adds up on the line - #1114

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

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

Conversation

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator

Root cause

ONEBIT_EP_QDQ_PROF=1 (engine#1032) reports the fused QDQ path's wall time, and on the device leg everything
inside dev_call_ms was one unlabelled number. That number is 4.09 ms/call at model level
(~/briefs/TQDQ-STATE.md, 2026-11-05 03:50 entry) against a probe's 3.460 ms/call for a single shape in the same
window, and the merged docs could only attribute it from reading the code — weight BO writes, both syncs, the
launch, the wait, the readback — explicitly "rather than split by guesswork" (docs/onnx.md, "The next step is the
one comparison these numbers cannot make").

That residue is exactly what the remaining per-call work would have to aim at (option 2 of the OWNER block in the
state file: "remove the parts that are not the kernel"), and it was not measurable.

The change

  • npu/ort/onebit_npu_gemm.h: new Q8RawSplit (five double ms fields) and an optional trailing parameter on
    gemm_q8_raw(..., Q8RawSplit* split = nullptr). The existing caller (the q8 probe) needs no edit.
  • npu/ort/onebit_npu_gemm.cpp: gemm_q8_raw fills it from its own timers — wpack_ms (weight pack into the BO +
    its upload; a cache miss, so once per weight, not per call), aupload_ms, async_ms (the A flush),
    launch_ms (launch + wait_kernel), readback_ms (C invalidation + the copy back into the caller's buffer).
    A short-read re-issue lands in the same counters, because it costs what it costs.
  • onnx/ep/onebit_ep_kernel.cpp: Q8Prof accumulates those and appends them to the existing line, plus
    dev_split_other = dev_call_ms minus the five, so the line adds up on its face instead of leaving the
    residue to be attributed by subtraction.
  • docs/onnx.md: the knob's paragraph and the "next step" paragraph now describe the split, and say plainly that
    no device window has printed it yet — the sections appear from the next one on.

Measured before / after

Cost when the knob is off: split is a null pointer, so one branch per timed section, no clock read.

before:  qdq_prof ... dev_call_ms=9964.1 dev_epi_ms=237.2 host_ms=0.0
after :  qdq_prof ... dev_call_ms=9964.1 dev_epi_ms=237.2 host_ms=0.0
         dev_split_wpack=… dev_split_aupload=… dev_split_async=… dev_split_launch=…
         dev_split_readback=… dev_split_other=…

The "after" shape is what is verified here. The section values need a device window and none has been taken —
saying so is the point of the docs sentence above; this PR ships the instrument, not a cause.

Verification actually run:

check result
unoptimized host-only build (the stricter one: this header compiles without ONEBIT_EP_NPU) + ctest 6/6 green
CMAKE_BUILD_TYPE=Release, ONEBIT_EP_NPU=ON + ctest -R qdq 3/3 green (the onebit_ep_proof failure and two skipped NPU probes in that configuration are pre-existing on main — NPU build with no ELF configured)
the knob's output, host-only proof with the knob on new fields present, all 0.0 (no device calls), same host_ms behaviour as before
a 2-token model run with the knob on, no ONEBIT_EP_TRACE line on stderr, as the knob claims
qdq-prof-run.sh's own awk parser, fed the longer line unchanged numbers (dev 5.78 ms/call = call 5.65 + epilogue 0.13); the added fields are additive, not a format break
arithmetic identity wpack+aupload+async+launch+readback+other = dev_call_ms by construction (other is defined as the difference and clamped at 0 for float noise)

Also worth knowing for whoever runs the next window: the QDQ proof calls setenv("ONEBIT_EP_TRACE", "1") itself
(onnx/ep/onebit_ep_qdq_proof.cpp:720), so its qdq_prof line lands in the trace file and not on stderr even
with the trace flag unset in the shell. That is why the stderr case was verified with ort_run instead.

No closes #: engine#1023 is merged — this closes the state file's owed item, not an issue. Squash-only repo; docs
and instrumentation only, no behaviour change.

… on the line

ONEBIT_EP_QDQ_PROF=1 reports the fused path's wall time per process, and on the device leg all of
it was one number: `dev_call_ms` is 4.09 ms/call at model level (2026-11-05 03:50 entry in
~/briefs/TQDQ-STATE.md), against a probe's 3.46 ms/call for one shape in the same window, and the
docs could only say what it contains from the code -- BO writes, two syncs, the launch, the wait,
the readback -- "rather than split by guesswork". That is the number a fix for the remaining per-call
cost (option 2 of the OWNER block in that state file) would have to aim at, and it was not
measurable.

Now it is: `gemm_q8_raw` takes an optional `Q8RawSplit*` and fills it from its own timers --
wpack (the weight pack + its upload, a cache miss), aupload, async (the A flush), launch
(launch + wait_kernel), readback (C invalidation + the copy back to the caller's buffer) -- and the
EP adds them to the `qdq_prof` line beside `dev_call_ms`, with `dev_split_other` = dev_call_ms minus
those five, so the line adds up on its face instead of leaving a residue to be attributed by
subtraction.

Measured, on this tree:

  before:  qdq_prof ... dev_call_ms=9964.1 dev_epi_ms=237.2 host_ms=0.0
  after :  qdq_prof ... dev_call_ms=9964.1 dev_epi_ms=237.2 host_ms=0.0 dev_split_wpack=..
           dev_split_aupload=.. dev_split_async=.. dev_split_launch=.. dev_split_readback=..
           dev_split_other=..

(the "after" shape is the one verified here; the section values themselves need a device window, and
none has been taken -- the docs say so rather than implying numbers exist.)

Cost when off: `split` is a null pointer, one branch per timed section, no clock read. Verified:
unoptimized host-only build 6/6 green (the stricter build, where this header is compiled without
ONEBIT_EP_NPU), Release ONEBIT_EP_NPU=ON build 3/3 QDQ tests green, the knob's own output checked by
running it both ways (host-only proof and a 2-token model run), and the arm script's existing
`qdq_prof` parser re-run against the longer line so the added fields are additive, not a format
break.

@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 d7f04ee4 — the sections add up by construction, the cost when the knob is off is one branch, and the docs say plainly that no device window has printed them yet.

The structural property I checked first: dev_split_other is defined as dev_call_ms minus the five named sections, so the parts cannot fail to reconcile — a reader does not have to attribute a residue by subtraction, which is what the old text asked them to do. That is the right way to add stage timings: make the accounting identity hold by construction rather than by hoping the instrument closes.

The cost claim is real: the timers are gated on a caller-supplied Q8RawSplit*, and a null pointer costs one branch per section (split ? now() : time_point{}). So the knob being off changes nothing on the hot path — which matters here because this is the device call, the one thing in the tree where a now() per section would be visible.

#include <chrono> is the only new dependency, and the change is confined to the gemm entry point, its header and the EP's call site.

What I want preserved in the merge: the sentence "these sections are timed only when the knob is on, and no device window has printed them yet — they appear from the next one on." Every other number in that doc has a window behind it; these do not, and saying so is what keeps the page honest. If the next window does not print them, this sentence is the thing that should stop the doc from implying it did.

Not verified by me: the numbers (there are none yet — that is the point) and any device run.

@bong-water-water-bong
bong-water-water-bong merged commit aada392 into main Nov 5, 2026
8 of 9 checks passed
@bong-water-water-bong
bong-water-water-bong deleted the 1bit/onnx-qdq-prof-split branch November 5, 2026 15:11

@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 ee15b2bb — rebase-only, verified by blob.

docs/onnx.md · npu/ort/onebit_npu_gemm.cpp · npu/ort/onebit_npu_gemm.h · onnx/ep/onebit_ep_kernel.cpp
   -> byte-identical at d7f04ee4 and ee15b2bb

So the four files I reviewed are the four files at this head; what moved under them is main (the compare range is full of other PRs' files — #1107, #1112, #1113). Everything from that review stands: dev_split_other is defined as the remainder so the sections reconcile by construction, the timers cost one branch when the knob is off, and the docs say plainly that no device window has printed the split fields yet.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Review this head: d7f04ee — git diff --stat origin/main..HEAD is four files, +81/−11 (docs/onnx.md,
npu/ort/onebit_npu_gemm.{h,cpp}, onnx/ep/onebit_ep_kernel.cpp). Docs + instrumentation; no behaviour change.

What it does: gemm_q8_raw now times its own sections (wpack, aupload, async, launch, readback) behind an
optional Q8RawSplit* that is null for every plain call, and ONEBIT_EP_QDQ_PROF=1 prints them beside
dev_call_ms with dev_split_other = dev_call_ms − those five, so the line adds up on its face. That replaces the
sentence I put in the merged docs/onnx.md myself — the per-call residue was "named as one number inside
dev_call_ms rather than split by guesswork"
— and it is what option 2 of the OWNER block in
~/briefs/TQDQ-STATE.md would have to aim at.

The one thing to read hardest, because it is the honest limit of this PR: it ships the instrument, not a cause.
No device window has printed the sections, and the docs now say that outright rather than implying numbers exist. The
device values arrive from the next ticket, which is armed.

Verified here (both builds the fleet's rules want): unoptimized host-only build 6/6, Release
ONEBIT_EP_NPU=ON 3/3 QDQ tests; the knob's output checked by running it (host-only proof → the new fields all
0.0; a 2-token model run with no ONEBIT_EP_TRACE → the line on stderr, so the knob's "never silently dropped"
promise still holds); and ~/wt/qdq-prof-run.sh's own awk parser fed the longer line, which still reports
dev 5.78 ms/call = call 5.65 + epilogue 0.13 — additive fields, not a format break.

Two process notes so nothing here is a surprise later:

  1. The head I pushed first (9e713f2) was one commit behind, so I rebased onto origin/main 91b0975 and
    force-pushed d7f04ee; origin/main had touched none of my four files, and the incremental rebuild afterwards was
    a no-op (libonebit_ep.so unchanged), so the verified binaries describe the rebased code too.
  2. This comment supersedes a queued pr_agent run, which has been pending ~60 min on a repo-wide backlog, rather
    than pretending it did not: build (5m53s) and all five CodeQL analyses are green on d7f04ee, and a docs +
    instrumentation diff does not need the automated pass to be read. If the queued run survives, its verdict will
    land after this line.

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