Experiment — run_multicore phase profiling (Tier-1)

Date: 2026-06-13 · Status: ✅ KEPT (always-on instrumentation) · Path: ork-driver

Hypothesis

The open ggml-ork integration was measured ~2.6× slower (decode) than closed librkllmrt on the same 1.7B model. Hypothesis: the gap lives in the CPU-side machinery inside run() / run_multicore — auto-tuner, mc_ensure checks, cres realloc/memset, the cres → C memcpy, pool cond signal/wait — not in the NPU itself.

Implementation

• Commit: bd900ae (oRKLLM/ork-driver, main)
• Symbol: npu.c : run_multicore + exported ork_npu_run_timing(setup, submit, copy, n) (declared in ork_npu.h)
• Change: time each multi-core matmul in three phases — setup (pre-dispatch checks + mc_ensure + cres memset), submit (pool dispatch + workers + NPU), copy (cres → C memcpy) — accumulate, expose via getter.
• Knob: read under ORK_PROFILE=1 (printed by ggml-ork on backend free).

static double g_rt_setup=0, g_rt_submit=0, g_rt_copy=0; static long g_rt_n=0;
void ork_npu_run_timing(double*setup,double*submit,double*copy,long*n){
    if(setup)*setup=g_rt_setup; if(submit)*submit=g_rt_submit;
    if(copy)*copy=g_rt_copy; if(n)*n=g_rt_n;
}
static int run_multicore(ork_npu *c,ork_w *w,int M,const void *A,void *C,int nc){
    int dt=w->dtype, fd=c->fd;
    const double ts=ork_now_us();
    /* ...clamp nc, dtype switch, mc_ensure, cres realloc + memset... */
    const double t1=ork_now_us();                 /* setup done */
    /* ...pool dispatch (pgo broadcast) + mcworker(core0) + wait for pdone... */
    const double t2=ork_now_us();                 /* submit (NPU) done */
    memcpy(C,c->cres,need);
    const double t3=ork_now_us();
    g_rt_setup+=t1-ts; g_rt_submit+=t2-t1; g_rt_copy+=t3-t2; g_rt_n++;
    return 0;
}

The ggml-ork side prints it on backend free:

double rt_s=0, rt_sub=0, rt_cp=0; long rt_n=0;
ork_npu_run_timing(&rt_s, &rt_sub, &rt_cp, &rt_n);
if (rt_n) {
    double rt_tot = rt_s + rt_sub + rt_cp;
    GGML_LOG_INFO("ork profile: run_multicore %ld calls | setup %.0fms (%.0f%%) "
        "submit %.0fms (%.0f%%) copy %.0fms (%.0f%%) | %.1f us/call ...\n",
        rt_n, rt_s/1e3, 100*rt_s/rt_tot, rt_sub/1e3, 100*rt_sub/rt_tot,
        rt_cp/1e3, 100*rt_cp/rt_tot, rt_tot/rt_n);
}

Method

Ran the Qwen3-1.7B-w8a8 integration warm, ORK_PROFILE=1, decode pass.

Results

run_multicore: setup 9.0 µs (2%)   submit 365.2 µs (97%)   copy 1.0 µs (0%)

Per decode matmul: machinery (setup + copy) = 10 µs / call (3%); the other 97% is genuine NPU submit.

Benchmark (standardized — 2026-06-13, reference model)

Re-confirmed on Qwen3-1.7B-w8a8, all-NPU (ORK_MINM=1 ORK_PROFILE=1), warm, DDR 2112 / CPU 2.4 GHz:

ork profile: run_multicore 9653 calls | setup 114ms (3%) submit 3531ms (97%) copy 11ms (0%)
            | 378.8 us/call (setup 11.9 submit 365.8 copy 1.1)

Machinery (setup 11.9 µs + copy 1.1 µs = 13 µs/call, 3%) is unchanged from the first measurement; 97% is the genuine NPU submit. The end-to-end consequence is documented in Hybrid M-Gate (all-NPU decode 5.03 vs CPU 9.43 tok/s).

Closed-runtime baseline (per-matmul, RKNN matmul API): the applicable apples-to-apples here is per-matmul, not full-model. Same isolated int8 2048² M=1 matmul: ork 1-core 495.9 µs vs rknn 1-core 398.8 µs (1.24×) — see Matmul apples-to-apples. Since our run() machinery is only 3% and RKNN's kernel is only 1.24× tighter, the open-vs-closed decode gap is not in run() machinery — it's in per-matmul kernel efficiency. (rkllm full-model cross-check: decode 11.71 tok/s ⇒ ~1 submit/matmul at a similar floor.)

Verdict

❌ Hypothesis refuted. There is no fat to trim in run() — the machinery is already lean. The open-vs-closed gap is not addressable by optimizing CPU-side run() code. This redirected the effort: the real lever is which matmuls go to the NPU at all (decode M=1 should not) → led directly to the Hybrid M-Gate. A negative result that saved a wild-goose optimization.