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

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.
 

npu/ort/onebit_npu_gemm.cpp

@@ -25,6 +25,7 @@
 #include <unistd.h>
 
 #include <algorithm>
+#include <chrono>
 #include <type_traits>
 #include <cmath>
 #include <cstdio>
@@ -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<std::mutex> g(s.mu);
     if (!init(s)) {
@@ -314,13 +315,19 @@ 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
         // measured 1.44 ms for a 1024x2048 weight, 295 ms of a 1074 ms token.
         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<double, std::milli>(
+                                   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<int64_t>(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<double, std::milli>(
+                                     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<double, std::milli>(
+                                       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<double, std::milli>(
+                                        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<double, std::milli>(
+                                          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<double, std::milli>(
+                                      std::chrono::steady_clock::now() - t_c).count();
     }
     return true;
 }

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

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,15 +224,23 @@ void gemm_q8(const int8_t* a, const int8_t* b, int8_t* y, int64_t m, int64_t k,
         std::vector<int32_t> 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);
             if (p.on) {
                 const auto t_end = std::chrono::steady_clock::now();
                 p.dev_call_ms += std::chrono::duration<double, std::milli>(t_epi - t_dev).count();
                 p.dev_epi_ms += std::chrono::duration<double, std::milli>(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;
             }