Skip to content

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

Merged
bong-water-water-bong merged 5 commits into
mainfrom
1bit/onnx-qdq-f32-prof-weights
Nov 6, 2026
Merged

bong-water-water-bong merged 5 commits into
mainfrom
1bit/onnx-qdq-f32-prof-weights

Conversation

@bong-water-water-bong

@bong-water-water-bong bong-water-water-bong commented Nov 6, 2026 •

Copy link
Copy Markdown
Collaborator

What

A counter, and the finding it produced. No behaviour change — the only executable difference is that the float MatMul leg's profiler now reports how often it re-packs a weight, and the fused leg's line carries the same count.

ONEBIT_EP_QDQ_PROF=1 already priced the fused A8W8 leg (dev_split_*, #1114). The float leg had no instrumentation, and its per-call cost could not be read off the per-design probe: the probe times gemm_f32 with synthetic operands and a warm weight cache (3.63 ms/call for q at m=36), while the graph hands the same function real 32-row activations and measured 12.0 ms/call at model level. So:

  • npu/ort/onebit_npu_gemm.{h,cpp}: gemm_f32 takes an optional F32Stats* (calls, weight-cache misses, packB ms, go_rows ms) and fills it; Q8RawSplit gains wpacks. A plain call passes null and pays one branch, not a clock read.
  • onnx/ep/onebit_ep_kernel.cpp: a second prof line under the same knob — f32_prof calls=… wpacks=… wpack_ms=… rows_ms=… call_ms=… other_ms=… — where other is printed rather than left to be subtracted; and qdq_prof gains dev_wpacks.
  • docs/onnx.md: what the knob now prints for both legs, and what it found.

What it found: the weight cache never hits, and that is structural

Three npu-hold -l qdq tickets on a quiet box, each released cleanly — the float numbers below from the 04:07 ticket
(01793952433298170742.qdq, token after 12 s, 69 s of a 7-minute hold, load1 1.20), the A8W8 numbers from the 04:10 one
(01793952632360825046.qdq, token after 6 s, 57 s of a 6-minute hold, load1 1.17), and the 04:14 one
(01793952840214864204.qdq, 37 s) as the re-measurement that disproved the key hypothesis:

float32 graph, 5 M=32 designs : f32_prof calls=1764 wpacks=1764 wpack_ms=14103.7 rows_ms=6949.3 call_ms=21096.1
                                decode 2580.84 ms/token   (CPU EP control in the same window: 223.23)
A8W8 export, same designs     : qdq_prof calls_dev=1764 dev_wpacks=1764 dev_split_wpack=771.1
                                dev_split_launch=6063.1 dev_call_ms=7646.4   decode 951.66 ms/token

1764 calls, 1764 re-packs, on both legs — two thirds of the float leg's run (14.1 of 21.1 s) inside packB, 10 % of the fused leg's, because packing int8 bytes is cheap and quantising floats is not.

The first hypothesis was wrong, and the fix it produced was measured and thrown away. I assumed ORT hands an EP node a different weight pointer per call, and wrote a stable weight identity for the cache (graph initializer captured at CreateState, plan id for fused groups, fingerprint-guarded, plus a ReleaseState split the QDQ proof immediately caught as a double free against the fused path's QdqPlan). Measured on the same graph, same designs, load1 1.52: calls=1764 wpacks=1764 still, and the wall time moved only with the load (2461.11 ms/token against 2580.84). The reason is in this file already, as a comment on the kernel struct — the cache holds one packed weight per (K, N) kernel, and 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. Keying the slot on identity cannot fix a one-slot cache. That revert is why this PR changes no behaviour: shipping it would have been a fix for a bug that does not exist.

Making the cache hit needs a packed slot per weight — 440 MB of int8 projection weights resident (28·1024·2048 + 56·1024·1024 + 56·1024·3072 + 28·2048·1024 + 28·3072·1024), which the array does not have — or a cheaper packB. wpack_ms is the number that prices the second option, and it is now the largest single line the float leg has: ~8 ms per weight.

Gates

  • Host build, no CMAKE_BUILD_TYPE (the stricter one): ctest 6/6 pass.
  • ONEBIT_EP_NPU=ON Release (~/wt/qdq-model-build.sh): builds, ctest 5/5 QDQ pass, onebit_ep_proof fails and the two NPU probes skip — the recorded "NPU build with no ONEBIT_EP_NPU_ELFS configured" state since 2026-10-31, not a regression.
  • strings ep/libonebit_ep.so carries both new format strings (f32_prof …, dev_wpacks=%ld), i.e. the measurement above came from a binary that has them.
  • python3 tools/copyright.py --check → rc 0 (no new files).
  • The numbers came from the tree before the rebase onto today's main; git log e0f0362d..origin/main -- onnx/ npu/ort/ npu/forward/ is one commit (npu-pack: an imported container keeps the pack's fp32 scale/zero and stays servable, under layout q4nx-2 (closes #1185) #1242, npu-pack container scales — not the EP's float path), so nothing on this path moved underneath them.

Head 3127e92e, base origin/main 99c62594.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

#1247 ready for review at 3127e92

@github-actions

github-actions Bot commented Nov 6, 2026 •

Copy link
Copy Markdown

PR Reviewer Guide 🔍

(Review updated until commit 4835ad3)

Here are some key observations to aid the review process:

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

Profiler Instrumentation Overhead

The addition of F32Stats instrumentation in gemm_f32 introduces timing and counting operations that could impact real-time performance in production. Although the code uses conditional compilation and null checks to avoid overhead when profiling is disabled, the instrumentation itself should be validated to ensure it doesn't introduce unexpected latency or resource usage in the critical path. Specifically, the use of std::chrono::steady_clock::now() and conditional increments for stats->calls, stats->wpacks, and stats->wpack_ms should be verified for performance impact.

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();
    }
Profiler Output Consistency

The new f32_prof output format mirrors the structure of the existing qdq_prof output, which is good for consistency. However, the documentation in docs/onnx.md claims that the counter shows "the weight cache never hits" and that this is "structural, not a bug in the key." This claim should be validated with actual measurements on the hardware to confirm that the cache behavior is indeed as described and not due to an implementation issue or misconfiguration. The PR description mentions that the claim was validated with measurements from specific hardware runs, but the code changes themselves do not include any verification logic.

              "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);
Profiler Output Consistency

The new f32_prof output format mirrors the structure of the existing qdq_prof output, which is good for consistency. However, the documentation in docs/onnx.md claims that the counter shows "the weight cache never hits" and that this is "structural, not a bug in the key." This claim should be validated with actual measurements on the hardware to confirm that the cache behavior is indeed as described and not due to an implementation issue or misconfiguration.

#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;
    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));
    // i-k-j instead of i-j-k: each B row is walked once per A row, which is what keeps this
✅ Resolved findings

npu/ort/onebit_npu_gemm.cpp:429-493

Profiler Instrumentation

The addition of F32Stats instrumentation in gemm_f32 introduces a new profiling capability for the float MatMul path. While this is valuable for performance analysis, it's important to ensure that the overhead of timing and counting operations does not impact real-time performance in production. The code correctly uses conditional compilation and null checks to avoid overhead when profiling is disabled, but the instrumentation itself should be validated to ensure it doesn't introduce unexpected latency or resource usage in the critical path.

@github-actions

github-actions Bot commented Nov 6, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit 3127e92

@bong-water-water-bong
bong-water-water-bong merged commit daaa96d into main Nov 6, 2026
9 checks passed
@bong-water-water-bong
bong-water-water-bong deleted the 1bit/onnx-qdq-f32-prof-weights branch November 6, 2026 16:51
@github-actions

github-actions Bot commented Nov 6, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit 4835ad3

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