From d7f04ee48e3c3d5cbddaf9579b2b99f86a32c63f Mon Sep 17 00:00:00 2001 From: bong-water-water-bong Date: Thu, 5 Nov 2026 10:22:48 -0400 Subject: [PATCH] onnx: time the device QDQ call's own sections, so dev_call_ms adds up 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. --- docs/onnx.md | 18 ++++++++++++++---- npu/ort/onebit_npu_gemm.cpp | 35 +++++++++++++++++++++++++++++++++-- npu/ort/onebit_npu_gemm.h | 14 +++++++++++++- onnx/ep/onebit_ep_kernel.cpp | 25 +++++++++++++++++++++---- 4 files changed, 81 insertions(+), 11 deletions(-) diff --git a/docs/onnx.md b/docs/onnx.md index 639177024..c570ceb9b 100644 --- a/docs/onnx.md +++ b/docs/onnx.md @@ -364,9 +364,15 @@ cause is stated as open rather than as dispatch. The next step is the one comparison these numbers cannot make, not a redesign: **both arms with `ONEBIT_EP_QDQ_PROF=1` in one window** — the device arm's `dev_call_ms/call` against the host arm's `host_ms/call` on -the graph's own int8 bytes, which prices candidate 2 directly. `NPU_C_SYNC_PROF=1` (engine#988) prints the C-sync -counters per call if the syncs inside `dev_call_ms` need separating further. What a *fix* would look like if -(1) dominates is one launch covering many projections — a resident weight layout and a pass-level submission, rather +the graph's own int8 bytes, which prices candidate 2 directly. The call's own sections are timed as well — +the same line carries `dev_split_wpack` (weight pack into the BO + its upload, a cache miss), `dev_split_aupload`, +`dev_split_async` (the A flush), `dev_split_launch` (launch + wait), `dev_split_readback` (C invalidation + the copy +back) and `dev_split_other` (the device lock, the kernel lookup and the EP's own frame around the call, i.e. what the +five named sections do not account for) — so `dev_call_ms` adds up on the face of the line rather than leaving a reader +to attribute one residue by subtraction. `NPU_C_SYNC_PROF=1` (engine#988) still prints the C-sync counters per call +if a section needs separating further. These sections are timed only when the knob is on (a plain call pays one branch +per section), and **no device window has printed them yet** — they appear from the next one on. What a *fix* would +look like if (1) dominates is one launch covering many projections — a resident weight layout and a pass-level submission, rather than the per-projection ELF this leg uses — which is also why the threshold discussion above stands unchanged: `kDeviceMinRows` is about one call, and the model-level question is about 196 of them. Worth knowing before anyone starts that work: the resident-weight half of it has now been measured and is worth 35 ms/pass for 568 MiB, i.e. the @@ -518,7 +524,11 @@ its own wall time went, as one line per process at exit — `qdq_prof calls_dev=… calls_host=… rows_dev=… rows_host=… dev_call_ms=… dev_epi_ms=… host_ms=…`, split into the device call (kernel, BO writes, both syncs, the wait), the epilogue both legs share, and the host loop — so two runs that differ only in the leg price that leg on the graph's own int8 bytes, which is the one thing -a per-call probe timing synthetic operands cannot do. It writes to the EP trace when `ONEBIT_EP_TRACE` is set +a per-call probe timing synthetic operands cannot do. On the device leg the call is split further, by the device +leg's own timers: `dev_split_wpack` (weight pack + upload, a cache miss — once per weight, not per call), +`dev_split_aupload`, `dev_split_async` (the A flush), `dev_split_launch` (launch + wait), `dev_split_readback` +(C invalidation + the copy back to the caller's buffer) and `dev_split_other`, which is `dev_call_ms` minus those +five. The sections are timed only when the knob is on. The line writes to the EP trace when `ONEBIT_EP_TRACE` is set and to stderr when it is not: a knob whose only output can silently vanish is how a debugging session gets lost, and this file already paid for that once. diff --git a/npu/ort/onebit_npu_gemm.cpp b/npu/ort/onebit_npu_gemm.cpp index 3bd161475..e96090253 100644 --- a/npu/ort/onebit_npu_gemm.cpp +++ b/npu/ort/onebit_npu_gemm.cpp @@ -25,6 +25,7 @@ #include #include +#include #include #include #include @@ -289,7 +290,7 @@ Q8Kernel* q8_kernel(State& s, int64_t k, int64_t n) { } // namespace bool gemm_q8_raw(const int8_t* a, int64_t m, int64_t k, int64_t n, const int8_t* b, int32_t* c, - std::string* err) { + std::string* err, Q8RawSplit* split) { State& s = state(); std::lock_guard g(s.mu); if (!init(s)) { @@ -314,6 +315,9 @@ bool gemm_q8_raw(const int8_t* a, int64_t m, int64_t k, int64_t n, const int8_t* // ONNX initializers are immutable, so the tensor's address is its identity: a graph that rewrote the bytes // in place would keep the old ones here, and re-uploading on every call would cost what this cache saves. if (kern->w_ptr != b || kern->w_k != k || kern->w_n != n) { + // Timed only for a caller that asked (the EP's ONEBIT_EP_QDQ_PROF); a null `split` costs one branch. + const auto t_w = + split ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; // Pack through the layout helper, which writes the same bytes a byte-at-a-time bpos() scatter // would but in 8-byte microtile runs: this is the loop that a pass pays once per group (a kernel is // keyed by (K, N), so a pass sends 28 different weights through each of 5 of them), and the scatter @@ -321,6 +325,9 @@ bool gemm_q8_raw(const int8_t* a, int64_t m, int64_t k, int64_t n, const int8_t* auto* Bm = (int8_t*)ctx.layerB[0]->map(); q4nx_layout::pack_int8_image(Bm, b, (int)k, (int)n, ctx.KD, ctx.ND, ctx.blocked_b); ctx.layerB[0]->sync(XCL_BO_SYNC_BO_TO_DEVICE); + if (split) + split->wpack_ms += std::chrono::duration( + std::chrono::steady_clock::now() - t_w).count(); kern->w_ptr = b; kern->w_k = k; kern->w_n = n; @@ -330,21 +337,40 @@ bool gemm_q8_raw(const int8_t* a, int64_t m, int64_t k, int64_t n, const int8_t* // zeroed, which is what the kernel reads for them and what the host path also assumes. for (int64_t row0 = 0; row0 < m; row0 += ctx.MD) { const int rows = (int)std::min(ctx.MD, m - row0); + const auto t_a = split ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; std::memset(ctx.Am, 0, (size_t)ctx.MD * ctx.KD); for (int r = 0; r < rows; ++r) std::memcpy(ctx.Am + (size_t)r * ctx.KD, a + (row0 + r) * k, (size_t)k); // This path writes A itself (no quantiser), so the context has no way to know how many rows the host // will read back: one row of the C BO is the default, and a batched block needs `rows` of them. ctx.set_activation_rows(rows); + if (split) + split->aupload_ms += std::chrono::duration( + std::chrono::steady_clock::now() - t_a).count(); // Only row 0 of a launch is watched (that is what #701's canary covers, and deliberately: poisoning // the padded last row of a batched launch fires on every prefill), so a block after the first is // protected exactly as much as the rest of this file's batched paths are. - auto launch_and_read = [&ctx, n] { + auto launch_and_read = [&ctx, n, split] { + const auto t_s = + split ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; ctx.sync_A(0); + if (split) + split->async_ms += std::chrono::duration( + std::chrono::steady_clock::now() - t_s).count(); poison_if_canaried(ctx, (int)n); + const auto t_l = + split ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; auto run = ctx.launch(0); ctx.wait_kernel(run); + if (split) + split->launch_ms += std::chrono::duration( + std::chrono::steady_clock::now() - t_l).count(); + const auto t_r = + split ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; ctx.readback(); + if (split) + split->readback_ms += std::chrono::duration( + std::chrono::steady_clock::now() - t_r).count(); }; launch_and_read(); if (short_read(ctx)) { @@ -357,8 +383,13 @@ bool gemm_q8_raw(const int8_t* a, int64_t m, int64_t k, int64_t n, const int8_t* return false; // gemm_q8 redoes every row on the host; never write a poisoned accumulator } } + const auto t_c = + split ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; for (int r = 0; r < rows; ++r) for (int64_t j = 0; j < n; ++j) c[(row0 + r) * n + j] = ctx.Cm[(size_t)r * ctx.ND + j]; + if (split) + split->readback_ms += std::chrono::duration( + std::chrono::steady_clock::now() - t_c).count(); } return true; } diff --git a/npu/ort/onebit_npu_gemm.h b/npu/ort/onebit_npu_gemm.h index e481ae06c..285975722 100644 --- a/npu/ort/onebit_npu_gemm.h +++ b/npu/ort/onebit_npu_gemm.h @@ -58,7 +58,19 @@ bool gemm_f32(const float* a, int64_t m, int64_t k, int64_t n, const float* b, // device run and a host run of the same graph agree to the byte. // False means the device could not run it (no ELF for this K x N, device busy, // XRT failure); the caller keeps its host loop and must not claim the device. +// +// `split`, when not null, is filled with where that call's wall time went, in ms. It is a measurement +// hook for the caller's own profiler (onnx/ep/onebit_ep_kernel.cpp, ONEBIT_EP_QDQ_PROF): a plain call +// passes null and pays one branch per section, not a clock read. +struct Q8RawSplit { + double wpack_ms = 0; // weight pack into the BO + its upload -- a cache miss, once per weight + double aupload_ms = 0; // activation memset/memcpy + A readback sizing, per launch block + double async_ms = 0; // A flush (sync_A) per launch block + double launch_ms = 0; // launch + wait_kernel: the device's own time, as the host sees it + double readback_ms = 0; // C invalidation + the block's copy back to `c` +}; + bool gemm_q8_raw(const int8_t* a, int64_t m, int64_t k, int64_t n, const int8_t* b, - int32_t* c, std::string* err); + int32_t* c, std::string* err, Q8RawSplit* split = nullptr); } // namespace onebit::npu diff --git a/onnx/ep/onebit_ep_kernel.cpp b/onnx/ep/onebit_ep_kernel.cpp index 5269a48cc..0d2a3c433 100644 --- a/onnx/ep/onebit_ep_kernel.cpp +++ b/onnx/ep/onebit_ep_kernel.cpp @@ -104,14 +104,23 @@ void trace_fallback(const char* fmt, ...) { struct Q8Prof { const bool on = std::getenv("ONEBIT_EP_QDQ_PROF") != nullptr; double dev_call_ms = 0, dev_epi_ms = 0, host_ms = 0; + // Where dev_call_ms goes, from the device leg's own timers (Q8RawSplit). `other` is what is left: + // the device lock, the kernel lookup, and the EP's own frame around the call. Printed rather than + // subtracted by a reader, so the line adds up on its face. + double dev_wpack_ms = 0, dev_aup_ms = 0, dev_async_ms = 0, dev_launch_ms = 0, dev_rdb_ms = 0; long calls_dev = 0, calls_host = 0, rows_dev = 0, rows_host = 0; ~Q8Prof() { if (!on || (calls_dev == 0 && calls_host == 0)) return; - char line[256]; + const double split = dev_wpack_ms + dev_aup_ms + dev_async_ms + dev_launch_ms + dev_rdb_ms; + const double other = dev_call_ms > split ? dev_call_ms - split : 0.0; + char line[512]; std::snprintf(line, sizeof(line), "qdq_prof calls_dev=%ld calls_host=%ld rows_dev=%ld rows_host=%ld" - " dev_call_ms=%.1f dev_epi_ms=%.1f host_ms=%.1f", - calls_dev, calls_host, rows_dev, rows_host, dev_call_ms, dev_epi_ms, host_ms); + " dev_call_ms=%.1f dev_epi_ms=%.1f host_ms=%.1f" + " dev_split_wpack=%.1f dev_split_aupload=%.1f dev_split_async=%.1f" + " dev_split_launch=%.1f dev_split_readback=%.1f dev_split_other=%.1f", + calls_dev, calls_host, rows_dev, rows_host, dev_call_ms, dev_epi_ms, host_ms, + dev_wpack_ms, dev_aup_ms, dev_async_ms, dev_launch_ms, dev_rdb_ms, other); // Bare stderr when ONEBIT_EP_TRACE is off: this line is the knob's whole output, and losing the one // measurement that answers the question is not worth saving a trace file. trace_line(line, /*stderr_too=*/std::getenv("ONEBIT_EP_TRACE") == nullptr); @@ -215,8 +224,11 @@ void gemm_q8(const int8_t* a, const int8_t* b, int8_t* y, int64_t m, int64_t k, std::vector acc((size_t)m * (size_t)n); std::string why; Q8Prof& p = q8_prof(); + // Where the call's time goes, but only when the profiler is on: a plain run passes null and the + // device leg pays one branch per timed section instead of five clock reads per launch block. + onebit::npu::Q8RawSplit split; const auto t_dev = p.on ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; - if (onebit::npu::gemm_q8_raw(a, m, k, n, b, acc.data(), &why)) { + if (onebit::npu::gemm_q8_raw(a, m, k, n, b, acc.data(), &why, p.on ? &split : nullptr)) { const auto t_epi = p.on ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{}; for (int64_t i = 0; i < m; ++i) epilogue_row(acc.data() + i * n, i, y + i * n); @@ -224,6 +236,11 @@ void gemm_q8(const int8_t* a, const int8_t* b, int8_t* y, int64_t m, int64_t k, const auto t_end = std::chrono::steady_clock::now(); p.dev_call_ms += std::chrono::duration(t_epi - t_dev).count(); p.dev_epi_ms += std::chrono::duration(t_end - t_epi).count(); + p.dev_wpack_ms += split.wpack_ms; + p.dev_aup_ms += split.aupload_ms; + p.dev_async_ms += split.async_ms; + p.dev_launch_ms += split.launch_ms; + p.dev_rdb_ms += split.readback_ms; p.calls_dev++; p.rows_dev += m; }