onnx: count the device weight-cache misses — the cache never hits, and it is one slot per (K, N) against 196 weights

docs/onnx.md

@@ -568,6 +568,31 @@ five. The sections are timed only when the knob is on. The line writes to the EP
 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.
 
+The **float** `MatMul` path reports under the same knob, as a second line — `f32_prof calls=… wpacks=…
+wpack_ms=… rows_ms=… call_ms=… other_ms=…` — and it exists for the same reason the fused one does: its per-call
+cost could not be read off the per-design probe, which times `gemm_f32` with synthetic operands and a warm
+weight cache (3.6 ms/call for q at m=36 above) while the graph hands the same function real 32-row activations.
+At model level that came out 12.0 ms/call (21096.1 ms over 1764 calls), and one counter says where it went. So
+the float leg counts `calls` and the **weight-cache misses** (`wpacks`), times `packB` and the runtime's own
+`go_rows` (quantise + upload,
+both syncs, launch, wait, readback, dequant — one number, because those steps live inside the runtime and are not
+re-implemented here the way `gemm_q8_raw` re-implements the int8 ones), and `call_ms` is this file's frame around
+it with `other` the difference. The fused leg's `qdq_prof` carries the same miss count as `dev_wpacks`.
+
+**What the counter showed: the weight cache never hits, and that is structural, not a bug in the key.** On the
+float32 graph with five M=32 designs, at load 1.2: `f32_prof calls=1764 wpacks=1764 wpack_ms=14103.7
+rows_ms=6949.3 call_ms=21096.1` — 1764 calls, **1764 re-packs, two thirds of the run (14.1 of 21.1 s) inside
+`packB`**. The fused A8W8 export on the same designs, same window: `calls_dev=1764 … dev_wpacks=1764
+dev_split_wpack=771.1 dev_split_launch=6063.1`, i.e. the same miss on every call, costing 10 % because packing
+int8 bytes is cheap and quantising floats is not. The first hypothesis — that ORT hands an EP node a different
+weight pointer per call — was wrong, and a fix was written and thrown away: the cache holds **one** packed weight
+per `(K, N)` kernel (`npu/ort/onebit_npu_gemm.cpp`, "one slot per kernel"), and Qwen3-0.6B has 196 weights across
+five shapes — 28 for q/o/down, 56 for k/v and gate/up — so consecutive calls of one shape evict each other, and
+keying the slot on the weight's identity changes nothing (196 packs per pass either way; measured). Making the
+cache hit needs a packed slot per weight (440 MB of int8 projection weights resident — the five shapes'
+196 weights — which the array does not have) or a cheaper `packB`; `wpack_ms` is the number that would price
+the second, and it is the largest single line the float leg has.
+
 ## Status
 
 The host path is done: it is what the tests assert, and it needs no hardware. The NPU path is

npu/ort/onebit_npu_gemm.cpp

@@ -325,9 +325,11 @@ 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)
+        if (split) {
             split->wpack_ms += std::chrono::duration<double, std::milli>(
                                    std::chrono::steady_clock::now() - t_w).count();
+            split->wpacks += 1;
+        }
         kern->w_ptr = b;
         kern->w_k = k;
         kern->w_n = n;
@@ -425,7 +427,7 @@ bool available(std::string* why) {
 }
 
 bool gemm_f32(const float* a, int64_t m, int64_t k, int64_t n, const float* b,
-              float* c, std::string* err) {
+              float* c, std::string* err, F32Stats* stats) {
     State& s = state();
     std::lock_guard<std::mutex> g(s.mu);
     if (!init(s)) {
@@ -449,15 +451,25 @@ bool gemm_f32(const float* a, int64_t m, int64_t k, int64_t n, const float* b,
     // Weights: int8 per column, one scale per column (packB).
     // 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.
+    // `stats->wpacks` counts the misses, which is the one number that separates "the cache works" from "this
+    // re-packs 196 weights per pass" without timing anything.
     if (kern->w_ptr != b || kern->w_k != k || kern->w_n != n) {
+        const auto t_pack = stats ? std::chrono::steady_clock::now()
+                                  : std::chrono::steady_clock::time_point{};
         kern->ctx->packB(0, b, (int)k, (int)n, kern->w_scale);
+        if (stats) {
+            stats->wpacks += 1;
+            stats->wpack_ms += std::chrono::duration<double, std::milli>(
+                                   std::chrono::steady_clock::now() - t_pack).count();
+        }
         kern->w_ptr = b;
         kern->w_k = k;
         kern->w_n = n;
     }
 
     // Activations: one row group of the kernel's M at a time. Rows past `rows` are zero-padded
     // inside quantize_async_rows and never read back.
+    if (stats) stats->calls += 1;
     std::vector<float> scales((size_t)kern->m);
     for (int64_t row0 = 0; row0 < m; row0 += kern->m) {
         const int rows = (int)std::min<int64_t>(kern->m, m - row0);
@@ -467,8 +479,14 @@ bool gemm_f32(const float* a, int64_t m, int64_t k, int64_t n, const float* b,
             for (int64_t i = 0; i < k; i++) amax = std::max(amax, std::fabs(row[i]));
             scales[(size_t)r] = amax > 0.0f ? amax / 127.0f : 1.0f;
         }
-        if (!kern->ctx->go_rows(0, a + row0 * k, rows, (int)k, scales.data(), scales.data(),
-                                1.0f, c + row0 * n, (int)n)) {
+        const auto t_rows = stats ? std::chrono::steady_clock::now()
+                                  : std::chrono::steady_clock::time_point{};
+        const bool ok = kern->ctx->go_rows(0, a + row0 * k, rows, (int)k, scales.data(), scales.data(),
+                                           1.0f, c + row0 * n, (int)n);
+        if (stats)
+            stats->rows_ms += std::chrono::duration<double, std::milli>(
+                                  std::chrono::steady_clock::now() - t_rows).count();
+        if (!ok) {
             if (err) *err = "I8Ctx go_rows failed";
             return false;
         }

npu/ort/onebit_npu_gemm.h

@@ -43,8 +43,24 @@ bool has_kernel(int64_t k, int64_t n);
 // C[M,N] = A[M,K] @ B[K,N], all float32 row-major, B[K][N].
 // False means the NPU path could not run at all — the caller must fall back to
 // its CPU kernel and must not claim the device did the work.
+//
+// `stats`, when not null, is filled with a measurement hook for the caller's profiler (ONEBIT_EP_QDQ_PROF):
+// how many calls reached a kernel, how many of those had to re-pack the weight, and the wall time that went
+// to `packB` against the time that went to `go_rows` (quantise + upload, both syncs, launch, wait, readback,
+// dequant — one number, because those steps are the runtime's own and are timed inside it, not here).
+// The float leg's cost per call is otherwise unattributable: the per-design probe times the same function
+// with synthetic operands and a warm weight cache, so a graph that re-packs or that pays for real 32-row
+// activation quantisation looks identical to it. A plain call passes null and pays nothing.
+struct F32Stats {
+    long calls = 0;       // calls that reached a kernel
+    long wpacks = 0;      // packB runs, i.e. weight-cache misses (see Q8RawSplit::wpacks: equal to calls on a
+                          // model graph, because one packed weight per (K, N) is shared by 28-56 weights)
+    double wpack_ms = 0;  // packB time (one column-wise quantisation of a whole weight per miss)
+    double rows_ms = 0;   // go_rows time: quantise+upload, both syncs, launch, wait, readback, dequant
+};
+
 bool gemm_f32(const float* a, int64_t m, int64_t k, int64_t n, const float* b,
-              float* c, std::string* err);
+              float* c, std::string* err, F32Stats* stats = nullptr);
 
 // The A8W8 QDQ path: int8 activations and int8 weights straight into the kernel's
 // input and weight BOs, exact int32 accumulators out (C[m][n], row major).
@@ -63,7 +79,12 @@ bool gemm_f32(const float* a, int64_t m, int64_t k, int64_t n, const float* b,
 // 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
+    // Weight-cache misses -- and on a real transformer graph this equals the call count, by design rather than by
+    // accident: the cache holds ONE packed weight per (K, N) kernel, while Qwen3-0.6B has 196 weights across five
+    // shapes (28 for q/o/down, 56 for k/v and gate/up), so successive calls of one shape evict each other. Measured
+    // with this counter: 1764 packs for 1764 calls, 771 ms of a 7646 ms device arm.
+    long wpacks = 0;
+    double wpack_ms = 0;     // weight pack into the BO + its upload
     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

onnx/ep/onebit_ep_kernel.cpp

@@ -108,6 +108,8 @@ struct Q8Prof {
     // 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;
+    // Weight-cache misses: equal to calls_dev means the cache never hits, which is a bug rather than a cost.
+    long dev_wpacks = 0;
     long calls_dev = 0, calls_host = 0, rows_dev = 0, rows_host = 0;
     ~Q8Prof() {
         if (!on || (calls_dev == 0 && calls_host == 0)) return;
@@ -117,9 +119,10 @@ struct Q8Prof {
         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"
-                      " dev_split_wpack=%.1f dev_split_aupload=%.1f dev_split_async=%.1f"
+                      " dev_wpacks=%ld 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_wpacks,
                       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.
@@ -131,13 +134,51 @@ Q8Prof& q8_prof() {
     return p;
 }
 
+#ifdef ONEBIT_EP_NPU
+// The float leg's own numbers, under the same knob and in the same shape as the fused leg's, so the two
+// are read the same way. This exists because the float path's per-call cost could not be attributed: the
+// per-design probe times `gemm_f32` with synthetic operands and a warm weight cache, while the graph hands
+// it real 32-row activations and whatever address ORT's initializer has, and at model level those two
+// readings differ by 5x (3.6 ms/call in the probe's table against ~18 ms/call in the graph).
+//
+// Two of the sections are the device call's own (`F32Stats`: calls, weight-cache misses and the time in
+// `packB` against the time in `go_rows`); `call_ms` is this file's frame around it, and `other` is the
+// difference, printed rather than left for a reader to subtract, so the line adds up on its face.
+struct F32Prof {
+    const bool on = std::getenv("ONEBIT_EP_QDQ_PROF") != nullptr;
+    onebit::npu::F32Stats dev;
+    double call_ms = 0;
+    ~F32Prof() {
+        if (!on || dev.calls == 0) return;
+        const double timed = dev.wpack_ms + dev.rows_ms;
+        const double other = call_ms > timed ? call_ms - timed : 0.0;
+        char line[512];
+        std::snprintf(line, sizeof(line),
+                      "f32_prof calls=%ld wpacks=%ld wpack_ms=%.1f rows_ms=%.1f call_ms=%.1f other_ms=%.1f",
+                      dev.calls, dev.wpacks, dev.wpack_ms, dev.rows_ms, call_ms, other);
+        trace_line(line, /*stderr_too=*/std::getenv("ONEBIT_EP_TRACE") == nullptr);
+    }
+};
+F32Prof& f32_prof() {
+    static F32Prof p;
+    return p;
+}
+#endif
+
 }  // namespace
 
 // Returns true when the NPU did the multiply. Always writes all of C.
 bool gemm_f32(const float* a, const float* b, float* c, int64_t m, int64_t k, int64_t n) {
 #ifdef ONEBIT_EP_NPU
     std::string why;
-    if (onebit::npu::gemm_f32(a, m, k, n, b, c, &why)) return true;
+    F32Prof& p = f32_prof();
+    const auto t_call = p.on ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{};
+    if (onebit::npu::gemm_f32(a, m, k, n, b, c, &why, p.on ? &p.dev : nullptr)) {
+        if (p.on)
+            p.call_ms += std::chrono::duration<double, std::milli>(
+                             std::chrono::steady_clock::now() - t_call).count();
+        return true;
+    }
     trace_fallback("npu_fallback k=%lld n=%lld why=%s", (long long)k, (long long)n, why.c_str());
 #endif
     std::memset(c, 0, (size_t)m * (size_t)n * sizeof(float));
@@ -237,6 +278,7 @@ void gemm_q8(const int8_t* a, const int8_t* b, int8_t* y, int64_t m, int64_t k,
                 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_wpacks += split.wpacks;
                 p.dev_aup_ms += split.aupload_ms;
                 p.dev_async_ms += split.async_ms;
                 p.dev_launch_ms += split.launch_ms;