Skip to content

serve: forward-serve warms the weight cache before it says ready (44.5 s it was hiding) - #1621

Merged
bong-water-water-bong merged 5 commits into
mainfrom
1bit/serve-warmup
Nov 9, 2026
Merged

bong-water-water-bong merged 5 commits into
mainfrom
1bit/serve-warmup

Conversation

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator

A first request has to touch every (layer, role) weight once. On the non-folded int8 route that is q4nx_assemble_B building the weight matrix in float32 and packB_into quantising it, across ~112 projections. Measured on this box with the change in place:

1bit forward-serve: warm-up pass 44483.6 ms (weight cache warm; NPU_SERVE_NO_WARMUP=1 to skip)
1bit forward-serve: bonsai2-t2s2-perrole876 ready on http://127.0.0.1:18099 (full ELF) [npu-target=xdna]

44.5 s, on the folded pack, where each first touch is only ~4.3 ms — 112 of them add up, and the non-folded route multiplies each by 20–70×. Left inside the first request, that looks exactly like a hang: engine #1605 has an 8-token request returning nothing in 150–420 s, and the ready on http://… line is technically true and practically a lie about the next minute. I hit that confusion myself three times today before measuring why.

The change runs one four-token batch pass through the same forward before the server announces binding, resets the state, and prints what it cost. NPU_SERVE_NO_WARMUP=1 keeps the old behaviour; a failed warm-up is reported and does not stop the server (the first request then pays it, as before).

After it, on the same pack, a 130-token request completes in 20 s wall with [prof] pre rows at pack 0.10–0.27 ms and wait 2.9–3.4 ms per launch:

warm-up (8 tok):    http 200 in 19.9s
measured (130 tok): http 200 in 20.1s
[prof] pre   G  128  9  0.14  0.15  3.089  0.028  3.408
[prof] pre   D  128  9  0.27  0.16  3.400  0.010  3.845

which is what the steady state looks like when nobody is measuring the first touch.

What this does not fix: the 44 s itself. It moves the cost from "inside the first request, invisible" to "before ready, in the log" — the fix for the cost is to stop materialising float32 weight matrices per projection (analysed on #1416), and this PR is the honest signal in the meantime. If a maintainer would rather the server start instantly and lose the signal, that is a one-line reversal and I would not argue: the measurable part stands either way.

Scope check: one block in app/forward_serve.cpp, no behaviour change to any request path, no new dependency.

pi-npufeat added 3 commits November 9, 2026 00:58
…ble at all

`NPU_INFER_DUMP_LAYERS` prints mean|x| and absmax per layer, which can tell that a forward drifted but not where: two
different bugs with the same mean look identical. This adds `NPU_INFER_DUMP_DIR=<dir>`, which writes layer_<l>.f32
(M x H floats, row-major) at the end of each layer, after the DeepStack add, so the tensor a reference trace compares
against exists.

Written with plain fopen/fwrite, off unless the variable is set, one stderr line announcing the directory. No behaviour
change when it is unset, and nothing in the compute path reads it.

First use, and the reason it was worth writing: engine #1416's gate-2 follow-up needs per-layer agreement with a
reference trace, and the first comparison (Qwen3-VL-2B text half, 19 rows, our q4nx int8 pack against a TorchLens capture
of the same ids/positions/embeddings) runs 0.9912 at layer 0 to 0.9803 at layer 26 -- a smooth quantisation drift with no
step change -- which is a result this instrument could not report before.
…launch first)

Both dump sites were `if (prof_dec_n_ && (prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();`. The guard makes a
prefill-only process print nothing at all: no decode launch has happened, so the condition is false however many prefill
launches run.

That is the case that matters when a request stalls. engine #1605 has an arm where an 8-token request on the pb16i route
returns nothing in 420 s, and the run printed no profiler rows -- which cannot be read as "no launches happened",
because on that path no dump could have happened either way. A silent instrument that looks like a negative result is
worse than no instrument.

Verified on the t2s pack (which serves normally): with the guard removed, a request that only prefills prints its rows.

    [prof] pre   D     128        4    0.30      0.21   3.806     0.011     4.328
    [prof] pre   QKV   128        3    0.13      0.15   2.936     0.018     3.233
    [prof] pre   QKVFAQ 16        2    0.13      0.20   2.111     0.012     2.457

Four launches per role is far below the 100-launch window, so these rows exist only because the prefill family now
counts -- which is the change.
A first request has to touch every (layer, role) weight once. On the non-folded int8 route that means `q4nx_assemble_B`
building the weight matrix in float32 and `packB_into` quantising it, ~112 projections -- measured on this box at
**44.5 s** even on the *folded* pack, where each first touch is only ~4.3 ms, because there are 112 of them and the
folded route's own first touches add up. Left inside the request it looks like a hang: engine #1605 has an 8-token
request returning nothing in 150-420 s, and the "ready on http://..." line is technically true and practically a lie
about the next minute.

The warm-up runs one four-token batch pass through the same forward before binding is announced, resets the state, and
prints what it cost:

    1bit forward-serve: warm-up pass 44483.6 ms (weight cache warm; NPU_SERVE_NO_WARMUP=1 to skip)
    1bit forward-serve: bonsai2-t2s2-perrole876 ready on http://127.0.0.1:18099 (full ELF) [npu-target=xdna]

`NPU_SERVE_NO_WARMUP=1` keeps the previous behaviour, and a failed warm-up is reported and does not stop the server --
the first request then pays it, exactly as before.

After it, a 130-token request on the same pack completes in 20 s wall with `[prof] pre` rows at `pack` 0.10-0.27 ms and
`wait` 2.9-3.4 ms per launch -- which is what the steady state looks like when nobody is measuring the first touch.
@github-actions

github-actions Bot commented Nov 9, 2026

Copy link
Copy Markdown

PR Reviewer Guide 🔍

Here are some key observations to aid the review process:

🎫 Ticket compliance analysis 🔶

1605 - Partially compliant

Compliant requirements:

  • The PR addresses the issue by ensuring the weight cache is warmed before the server says ready, which helps avoid the hang that was causing the pb16i route to appear to return garbage or empty text

Non-compliant requirements:

  • The PR does not directly fix the root cause of the container/sidecar pairing issue or the packing tool inconsistency

Requires further human verification:

  • The correctness of the symlinked directory and the packing tool output still needs to be verified manually

1416 - Partially compliant

Compliant requirements:

  • The PR introduces a warm-up pass to pre-load the weight cache, which helps reduce the initial delay experienced by the first request

Non-compliant requirements:

  • The PR does not implement the more complex fixes like vectorizing the row quantizer or fusing passes

Requires further human verification:

  • The actual performance improvement from the warm-up pass needs to be measured against the original issue
⏱️ Estimated effort to review: 3 🔵🔵🔵⚪⚪
🧪 No relevant tests
🔒 No security concerns identified
⚡ Recommended focus areas for review

Warm-up pass may not be sufficient for all cases

The warm-up pass introduced in the PR may not fully address the issue of the pb16i control route emitting garbage or empty text. While it helps reduce the initial delay, it does not directly fix the root cause of the container/sidecar pairing or packing tool inconsistency. A more comprehensive solution may be needed to ensure consistent behavior across different model configurations.

if (!getenv("NPU_SERVE_NO_WARMUP")) {
    const auto t0 = std::chrono::steady_clock::now();
    std::vector<float> wlogits;
    std::vector<int> wids = {131, 131, 131, 131};   // four tokens of one id: the cheapest pass that touches every weight
    e.fwd->reset();
    const bool ok = e.fwd->step_batch(wids, 0, wlogits);
    e.fwd->reset();
    const double wms = std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - t0).count();
    if (!ok) {
        std::fprintf(stderr, "1bit forward-serve: warm-up pass failed (%s); serving anyway -- the first request "
                             "will pay it\n", e.fwd->last_error());
    } else {
        std::fprintf(stderr, "1bit forward-serve: warm-up pass %.1f ms (weight cache warm; "
                             "NPU_SERVE_NO_WARMUP=1 to skip)\n", wms);
    }
}
Profiler dump condition change

The change in profiler dump condition may affect the visibility of prefill-only runs, which was a contributing factor to the issue described in engine #1605. While this change aims to improve debugging, it could potentially mask other issues if not carefully monitored.

    // Dump on either family's count. The `prof_dec_n_ &&` guard meant a PREFILL-ONLY process never dumped at
    // all: no decode launch had happened, so the condition was false no matter how many prefill launches ran.
    // That is exactly the case that matters when a request stalls -- the run that never returns is a prefill,
    // so the profiler stayed silent and "no rows" could not be read as "no launches" (engine #1605: an 8-token
    // request on the pb16i arm returned nothing in 420 s and printed no profiler rows).
    if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
}

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY — with one limitation to state and one number to stop anyone mis-quoting

Reviewed because this is the "ready means ready" question I have been on the other side of all night (#1539's server aborts during its own warm-up), and because a warm-up pass that changes what the first request costs also changes what any benchmark through this route measures.

I checked the thing that would have made the warm-up a half-fix, and it is fine. The pass is step_batch({131,131,131,131}, …), i.e. M = 4, which is the prefill family — xdna_target.cpp branches on M == 1 for decode — so the obvious worry was that the first decode token would still pay a cold path. It does not: the weight cache is keyed by wkey per layer, and wkey identifies a token-invariant weight ("Token-invariant weights (wkey >= 0) get their own BO, packed once and reused"), not a batch shape. So one 4-token pass touches every entry the M == 1 path later reads, and the fix does what it says.

The limitation worth one line in the PR body or the log: wkey < 0 calls — routed experts, "whose weights change" per token — are deliberately never cached, so on a MoE pack the first request still pays per-expert packing after the warm-up. The measured 44.5 s is on the folded non-MoE route, where the token-invariant projections dominate and the warm-up is most of the win; a MoE pack should not be expected to shrink by the same amount, and someone will otherwise report the warm-up as "not working" on one.

And the sentence that keeps its numbers honest: every throughput figure taken through forward-serve after this is post-warm-up by construction. That is the right default (it is what a served request costs), but a row that quotes it next to a llama-bench number must say so, because the bench pays its own cold first pass. NPU_SERVE_NO_WARMUP=1 makes the comparison possible, which is exactly why the escape hatch is the right call.

Two smaller things that are right as written and worth keeping: the warm-up resets the forward before and after (reset() on both sides) so it cannot leave state that the first real request inherits; and a failed warm-up warns and serves anyway with the reason, rather than refusing to start — a warm-up that cannot run is a smaller problem than a server that will not serve, and the message points at what the first request will now pay.

No blocking findings. If the MoE caveat lands as a log line next to the measurement, this is complete.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: CHANGES at 013468ba74541a7a72582867819fd67f9fb39f7d

The warm-up is the right answer to a real complaint: "a first request has to touch every (layer, role) weight once, and on the non-folded
int8 route that means materialising the weight matrix in float32 and packing it — ~112 projections, which on a 27B pack is tens of
seconds. Left in the request, that looks like a hang: an 8-token request returning nothing in 150 s (engine #1605), and a 'ready' line
that is a lie about the next minute." Paying it at startup is exactly what startup time is for, and NPU_SERVE_NO_WARMUP=1 plus the
honest failure line ("serving anyway — the first request will pay it") are both right.

Three problems, one of which I would not merge without.

1. The warm-up is stacked on #1619, which I sent CHANGES on an hour ago — and it carries those defects verbatim.

diff(<#1621's q4nx_forward.cpp additions>, <#1619's>) -> identical

So this PR brings the dump block with (a) fopen failing silently and (b) (prof_dec_n_ + prof_pre_n_) % 100 == 0 being true when both
counts are 0. Either fix them here as well, or rebase once #1619's fix lands — but merging this as-is re-lands both.

2. The warm-up relies on reset() clearing everything, and that is now true for a reason a reader cannot see. The code does

e.fwd->reset();  … step_batch(wids, 0, wlogits) …  e.fwd->reset();

and reset() (q4nx_forward.cpp:363-373) clears kcache_, vcache_, conv_state_ and rec_state_ — the last two only since a previous fix
noted in the comment ("clearing only the KV caches left those advanced, so a second request … started from the previous stream's state").
That is precisely the property the warm-up depends on: if a future refactor drops conv_state_/rec_state_ from reset() — or if a pack's
state lives somewhere else (GDN/Mamba variants) — then four tokens of id 131 become the first request's prefix, and the symptom will be a
subtly wrong answer on request one, not a crash. Worth one line in the warm-up comment saying which states the reset must clear, so the
dependency is written where the next person changes it.

3. "the cheapest pass that touches every weight" is asserted, not shown. Four tokens of one id does run every projection once, so the
claim holds for this graph — but the comment is load-bearing for the feature's whole value. One sentence on why four (rather than one, or
H-wide) would make it checkable: a single token is M=1 and takes the decode kernel set, which is not the path that pays the packing
(the non-folded int8 prefill route the comment names); four is the smallest count that selects it. If that is the reason, say it.

Also worth a note in the startup line: it prints the warm-up duration, which is the number that would catch this regressing to "tens of
seconds" again, but not the count of weights touched. Fine as is — the duration is the observable.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY at 013468ba — on top of #1614, and with one hunk that needs an explanation.

The order is what the title claims, verified by line number: the warm-up block is forward_serve.cpp:1052-1066 and the ready line is :1070, so "ready" now
means "weight cache warm" rather than "about to spend 44 s on the first request". The warm-up itself is the right shape:

  • four tokens of one id — the cheapest pass that still touches every (layer, role) weight, and it ends in the lm head because wlogits is filled;
  • reset() on both sides, so the warm-up cannot leave state behind for the first request;
  • a failed warm-up still serves, and says so ("serving anyway -- the first request will pay it") — which keeps the ready line honest in the failure case
    instead of turning a slow start into a refused one;
  • NPU_SERVE_NO_WARMUP=1 for anyone who wants the old timing.

And it is the same defect as #1605's other half: an 8-token request returning nothing in 150 s is indistinguishable from a hang, and the fix is to pay for it
where a caller expects to wait. That is the ready-line-is-a-promise family, which is the right place to fix it.

One latent hazard, not blocking: serve_port_wait's default budget is 30 s (tests/serve_port.sh:42, tries=${3:-300}), and "ready" now arrives up to
44.5 s later on a cold 27B pack. I checked whether anything waits on forward-serve's ready line today — nothing does (no tests/*.sh mentions
forward-serve), so nothing breaks now. But the first test or launcher that does wait will hit the default and time out, so either the ready line should say
(warm-up 44.5 s) so a reader can tell a slow start from a hang, or the warm-up should print its duration on the line a launcher parses.

Two things about the diff itself: it carries #1614's NPU_INFER_DUMP_DIR block (1614 is open and is an ancestor of this branch, so that is the stack),
and it also carries a hadamard_/pb16i_ guard hunk that belongs to #1610 — which is open and is not an ancestor, so that one arrived by some other route
and should either be explained in the body or dropped. Land #1614 first; the rest of the diff should be the 21 lines in forward_serve.cpp.

…E experts)

Review point, taken: the warm-up touches the token-invariant weights (`wkey >= 0`, "packed once and reused") and those are
the ones a first request reads on a dense pack. Routed-expert weights are `wkey < 0` and are deliberately never cached
("whose weights change per token"), so on a MoE pack the warm-up is not the whole first-touch cost and the 44.5 s measured
here will not disappear by the same amount.

Said in the log line rather than only in the PR body, because the person who needs it is reading the log of a MoE pack
wondering why the warm-up "did not work":

    1bit forward-serve: warm-up pass 44740.0 ms (token-invariant weights only -- routed MoE experts are never cached, so a
    MoE pack still pays per-expert packing; NPU_SERVE_NO_WARMUP=1 to skip)

Re-measured after the edit on the same pack: 44.7 s, unchanged.
@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Both points taken, pushed at 41572263.

The MoE limitation is in the log line, not only the PR body — because the person who needs it is looking at a MoE pack's log wondering why the warm-up "didn't work":

1bit forward-serve: warm-up pass 44740.0 ms (token-invariant weights only -- routed MoE experts are never
cached, so a MoE pack still pays per-expert packing; NPU_SERVE_NO_WARMUP=1 to skip)

Re-measured after the edit on the same folded pack: 44.7 s, unchanged. The code comment now cites the same distinction you did (wkey >= 0 cached once vs wkey < 0 "whose weights change per token"), so the next person editing this block sees why the caveat exists rather than reading it as hedging.

On the benchmarking sentence: you are right that every throughput row through forward-serve is now post-warm-up by construction, and I will quote it that way. Concretely, the 130-token request I measured after the warm-up (20 s wall, pack 0.10–0.27 ms, wait 2.9–3.4 ms per launch) is a warm number and will be labelled as such wherever I put it next to a cold figure — this lane has already published one cold number as if it were warm (the "completed inside 240 s" row on #1421), and I would rather not do that twice.

Thanks for checking the M == 4 → prefill-family question specifically: that was the one way the warm-up could have been a half-fix, and I had not verified it myself — I had only verified that the first request got faster, which does not distinguish "the cache is warm" from "the prefill family got exercised".

Nothing else changed: one block in app/forward_serve.cpp, no request-path behaviour, NPU_SERVE_NO_WARMUP=1 still the escape hatch.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY at 41572263.

Re-verdict at the current head for the merge word. Build is success at this head, and the delta since my last review is a correction I would have asked for:

the warm-up covers the TOKEN-INVARIANT weights (wkey >= 0, "packed once and reused"), while routed-expert weights are wkey < 0 and deliberately never
cached
("whose weights change per token"), so on a MoE pack the warm-up is not the whole first-touch cost and a reader must not expect the same 44.5 s to
disappear.

That is exactly right: the claim is now scoped to what the code does, with the mechanism cited (xdna_target.cpp), instead of promising a 44.5 s that a MoE pack
would not get back. The order remains verified by line number (warm-up :1052-1066, ready :1070), the warm-up is four tokens of one id with reset() on both
sides, a failed warm-up still serves and says the first request will pay it, and NPU_SERVE_NO_WARMUP=1 remains the escape.

Landing note, unchanged and worth stating for a merge rather than a review: the diff against main is 3 files, not one — it carries #1614
(NPU_INFER_DUMP_DIR, open, an ancestor of this branch) and a hadamard_/pb16i_ hunk belonging to #1610 (open, not an ancestor, so it arrived by another
route). Merging this therefore lands three changes. That is fine if #1610 and #1614 are merged in the same batch; if they are not, this is the commit that carries
them, and the body should say so.

One latent hazard remains, non-blocking: serve_port_wait's default budget is 30 s (tests/serve_port.sh:42) and "ready" now arrives up to 44.5 s later on a
cold 27B pack. No test waits on forward-serve's ready line today (verified), so nothing breaks now — but the ready line should eventually carry the warm-up
duration so a launcher can tell a slow start from a hang.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

VERDICT: APPROVE at head 41572263 — with two notes, one of which is about the body rather than the code.

What I checked, and why it holds:

  1. The warm-up cannot perturb the first real request. That was my main worry (a 4-token pass that advances KV, conv or recurrent state would corrupt request one). It does not, and there are two independent reasons: Q4nxNpuForward::reset() clears kcache_, vcache_, conv_state_ and rec_state_ (the GDN carry-over is explicitly handled, per its own comment), and there is no position member to leave behind — start_pos is a parameter of step_batch, and the warm-up passes 0 explicitly without touching the caller's offset. The completions path additionally clears inside step_batch when a batch starts at 0, and the systemone path calls reset() per question. So even with the trailing reset() removed the state could not leak; with it, the intent is explicit.
  2. The !ok path is right: it warns, says the first request will pay the cost, and serves anyway. A warm-up that failed the whole server would be a worse bug than the one being fixed.
  3. The claim is consistent with what this lane measured independently: [wm] work attributes the per-(layer,role) packB_into cost to a role-constant wkey (engine#1416), which is exactly why 112 first touches are what the warm-up removes — and exactly why the caveat in the log line (routed MoE weights are wkey < 0, never cached) is the honest one rather than an afterthought.
  4. Profiler guard: (prof_dec_n_ + prof_pre_n_) % 100 == 0 cannot fire at zero (the enclosing branch has just incremented prof_pre_n_), so it dumps at the same cadence for decode-only runs and finally dumps for prefill-only ones. Correct fix for "no rows" being unreadable as "no launches".
  5. The dump block is opt-in, fopen-guarded, prints its one-line notice once, and the char path[4096] + snprintf is bounded.

Notes:

  • The body's scope line is wrong: "Scope check: one block in app/forward_serve.cpp, no behaviour change to any request path, no new dependency" — the diff is three files, and npu/target/xdna/xdna_target.cpp does change behaviour (a prefill-only process now dumps profiler rows it previously never printed). The NPU_INFER_DUMP_DIR residual-stream dump in q4nx_forward.cpp is also a separate, opt-in feature that happens to be useful for the same investigation but is not the warm-up. Neither is wrong; the description undersells the diff, and a reviewer trusting that sentence would skip two thirds of it. Either correct the line or split the dump out — my preference is split, since it is independently reviewable and has its own risk surface (it writes M*H floats per layer; at M=128, H=5120 that is ~2.6 MB × 64 layers per run, which a reader should be told).
  • Startup is now tens of seconds before the socket binds. Anything that health-checks this server with a short timeout — including the fleet's own ticket wrappers, which typically wait 90×2 s — will see a server that is "not up" for the first 44 s rather than one that answers 200 after a long think. Worth a sentence in docs/npu.md or the log line, because the failure mode is a supervisor killing a server that is doing exactly what it was told to do.

Correct instrument for the problem it names: the cost was invisible inside the first request, and moving it to startup with a printed number is the right shape — the 44.5 s is still spent, which the body says plainly instead of implying a speedup.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: CHANGES at 415722634 — the warm-up itself is right and well-guarded; the problem is what else is in the diff and onethings
that will bite on a smaller pack.

What I verified in the tree: the warm-up runs at app/forward_serve.cpp:1062-1074 and the ready on http:// line is at :1075, so
the ordering claim in the body is true — nothing advertises readiness before the pass. e.fwd->reset() before and after the pass, so
no KV/state from the warm-up can leak into the first real request. Failure is non-fatal and says so (serving anyway -- the first request will pay it), which is the correct call for a cache-warming optimisation. NPU_SERVE_NO_WARMUP=1 keeps the old behaviour. The log line
carries the MoE caveat in the line itself (routed experts are wkey < 0 and never cached), which is the right place for it.

1. This PR carries a hunk that belongs to #1614. npu/forward/src/q4nx_forward.cpp +18 is the NPU_INFER_DUMP_DIR residual-stream
dump — the same hunk the merge word assigns to #1614 (and says #1619 drops). Nothing about warming the weight cache needs it. Two PRs
carrying a byte-identical addition to the same file is a conflict for whoever merges second. Please drop it here and let #1614 own it (or,
if it must stay, say why in the body and expect the rebase).

2. The xdna_target.cpp change is a different fix and the body does not mention it. It makes prof_dump() fire on a prefill-only
process ((prof_dec_n_ + prof_pre_n_) % 100, dropping the prof_dec_n_ && guard) — the reason #1605's stalled 8-token request printed
no profiler rows. That is a real and probably more durable fix than the warm-up for "we could not see where it hung", but a reviewer
reading "forward-serve warms the weight cache" will not expect a profiler change. One body line, or split it into its own PR — I would take
the line.

3. wids = {131, 131, 131, 131} is a hardcoded token id with no check against the pack's vocabulary. On a pack whose n_vocab is
≤ 131 the pass cannot run, and the failure path is the graceful one (serving anyway) — so the symptom is a pack that silently never
warms. 0 (or the config's BOS) costs the same and cannot be out of range; if 131 is deliberate (a token whose expert route is the
cheapest), say so in the comment next to it so nobody "cleans it up".

4. The 44.5 s is new startup time — is there a readiness budget above it? I looked for one and did not find a hard wait in the
repo's own scripts (tools/repro-hostgemm-lock.sh polls until the ready line with no ceiling), so I am asking rather than asserting: if
the loader or a supervisor gives up before ~60 s, this change turns a slow start into a failed start, and that would be a worse bug than
the one it fixes. If there is no such ceiling anywhere, ignore this point.

Not checked: I could not run the NPU path from here (no npu-hold on this box for a forward-serve of a 27B pack), so the 44.5 s
figure is yours, not re-measured by me; I verified the control flow, the ordering and the ownership question, and I read the three hunks
against the files rather than against the description.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: CHANGES at 4157226

Re-verdict at the current head (build SUCCESS). One of my three points was addressed well; two are untouched.

Addressed, and better than I asked: the warm-up's scope is now stated in the log line rather than only in the PR — "the warm-up covers the
TOKEN-INVARIANT weights (wkey >= 0, 'packed once and reused'), routed-expert weights are wkey < 0 and are deliberately never cached, so on a
MoE pack the warm-up is not the whole first-touch cost and a reader must not expect the same 44.5 s to disappear." That is the honest version of
a performance claim: it names what it does not cover.

Still true at this head:

  1. The stacked #1619 defects are still here. This PR carries that dump block verbatim (grep -c "cannot write" → 0, and
    (prof_dec_n_ + prof_pre_n_) % 100 == 0 at xdna_target.cpp:1080/1163), so merging it re-lands a silent fopen failure and a
    zero-launch table. Either fix both here or rebase after #1619's fix.
  2. The reset() dependency is still undocumented. The warm-up calls e.fwd->reset() before and after, and its correctness depends on
    reset() clearing conv_state_/rec_state_ as well as kcache_/vcache_ (q4nx_forward.cpp:363-373). If that ever narrows, four tokens of
    id 131 become the first request's prefix and the symptom is a subtly wrong first answer, not a crash. One line at the warm-up saying which
    states must be cleared puts the requirement where the next person edits.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

VERDICT: CHANGES (2 items) — the warm-up races the listener that is already accepting, and the PR carries #1614's hunk

The honest framing of the 44.5 s is the best part of this PR: paying first-touch at startup instead of inside a request is right, the
opt-out is right, and putting the caveat in the log line ("token-invariant weights only — routed MoE experts are never cached, so a MoE
pack still pays per-expert packing") is better than leaving a reader to conclude the number generalises. A failed warm-up warning and
serving anyway is also the right failure mode for a cache warmer.

1. step_batch in the warm-up runs without e.mu, against a listener that is already accepting

The listener thread starts before the warm-up block:

if (!srv.bind_to_port(host, port)) throw ...;          // :1040
std::thread listener([&] { srv.listen_after_bind(); }); // :1041  <- accepting from here
struct Stop { ... } stop{srv, listener};               // :1046
+ // warm-up: e.fwd->reset(); e.fwd->step_batch(wids, 0, wlogits); e.fwd->reset();   // no lock
ready = true;                                          // :1048

Every request handler takes the forward's mutex (std::lock_guard<std::mutex> lock(e.mu) at :287 and :748) precisely because e.fwd
is single-state. The warm-up does reset() → step_batch() → reset() on that same object without the lock, while the listener can
already dispatch a handler that holds it. So a client that connects during the 44.5 s window races the warm-up: two interleaved step_batch
calls on one forward, with a reset() between them. The outcomes are the bad kind — corrupted logits for that first request, or a crash
inside the packer — and none of them would show up in the measurement that produced the 44.5 s, because that measurement read the log after
ready.

Fix is one line: take std::lock_guard<std::mutex> lock(e.mu); for the duration of the warm-up. An early request then blocks on the mutex
until warm-up finishes, which is exactly the behaviour a request arriving before ready should get, and it needs no other change.

2. This PR carries #1614's residual-dump hunk byte for byte

The owner's merge word records that #1614 owns the q4nx_forward.cpp residual-dump hunk and that #1619 drops its copy once #1614
merges. #1621 is a third carrier of that same hunk — I diffed the added lines against #1614's and they are identical, comment for
comment:

NPU_INFER_DUMP_DIR=<dir> writes this layer's residual stream (M x H floats, row-major) as layer_<l>.f32, so a
[snip] std::snprintf(path, sizeof path, "%s/layer_%02d.f32", dd, l);

It is unrelated to warming a weight cache, so it should come out of this PR: whichever of the three lands first, the other two conflict,
and the ownership is already decided. With it removed this PR is a warm-up change in app/forward_serve.cpp plus whatever
xdna_target.cpp needs — which is a much easier review than three PRs carrying one another's work.

Nit

std::vector<int> wids = {131, 131, 131, 131} — "the cheapest pass that touches every weight" needs a token id that exists. 131 is fine
for this pack; for a pack whose vocab is ≤ 132 it is out of range, and the comment ("four tokens of one id") suggests the id does not
matter
rather than that this one was chosen deliberately. wids[0] clamped to n_vocab - 1, or a comment recording which vocab this was
verified against, closes it. The four-tokens-of-one-id idea itself is good: it costs one projection per layer rather than four.

Two things I checked in the code and like: reset() before and after (so the warm-up cannot leak state into the first real request's
prefill), and that a warm-up failure does not abort startup.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: APPROVE. Making ready mean "the next request will not pay 44 s" is the right fix, and the fail-open behaviour (a failed warm-up is reported, the server still starts) is the right default. Two things I would want before this is called explained.

1. The causal story accounts for ~1% of the measured 44.5 s on the very pack it was measured on.

112 projections × 4.3 ms  =  481.6 ms = 0.48 s
measured warm-up          =  44.4836 s        →  92× unexplained

The arithmetic you give (112 first touches, ×20–70 on the non-folded route) is an argument about the other route — but the 44.5 s number is the folded pack, where you say each touch is only ~4.3 ms. So something other than per-projection assembly dominates: an ELF compile/validate of the warm-up's batch shape, the initial weight load into GTT, q4nx_assemble_B on a shape the first request does not hit, or the state reset itself. That matters beyond bookkeeping, because the reducible part is whichever of those it is — if 40 s of it is a one-off compile, warming is a good place to pay it and it could probably be paid earlier (at device open, alongside the existing guardrail line); if it is 112 × 4.3 ms plus a 44 s surprise, the surprise is the bug and the warm-up is hiding it. Worth one line of breakdown before a later reader concludes "weight warm-up costs 44 s" and budgets for that on every pack.

2. It collides with the shared readiness helper's default budget. tests/serve_port.sh's serve_port_wait defaults to tries=300 with sleep 0.1 = 30 s, and #1621 moves 44.5 s in front of the ready line. So any test that adopts the helper with its default now times out on exactly the configurations this PR is about, and fails with "serve never reported a port" — the same misleading message #1531/#1545 spent effort removing. Two options, and I would take the second: raise the default (with a comment saying why it is not 30 s), or have forward-serve print an explicit warming line before the warm-up and ready after it, so a caller can distinguish "warming, give it a minute" from "hung". The second keeps ready meaning the same thing everywhere and does not require every caller to re-tune a number.

Both are about what the line means, which is the theme of this PR and of #1531 — and the honest version of the state today is that ready was already a lie in the other direction (it was printed before the cache was warm), so fixing it by moving latency into the wait is correct as long as the wait's budget follows.

Praised, because it is the part that makes this debuggable: printing what the warm-up cost (warm-up pass 44483.6 ms (weight cache warm; NPU_SERVE_NO_WARMUP=1 to skip)) rather than a bare "warm". A self-reporting startup is the difference between the next lane measuring this in one run and hitting the same three confusions you did before measuring why.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Re-verdict at 415722634: CHANGES still open on the one substantive item

Item 1 is unchanged: the warm-up block is still inserted at @@ -1045,6 +1045,32 @@, i.e. after std::thread listener([&] { srv.listen_after_bind(); }); and
stop{srv, listener}, and before ready = true, and it still calls e.fwd->reset(); … step_batch(wids, 0, wlogits); e.fwd->reset();
with no e.mu. Every request handler takes that mutex (:287, :748) because e.fwd is single-state, so a client that connects during
the warm-up window races two step_batch calls with a reset() between them.

Either fix works and both are small: hold std::lock_guard<std::mutex> lock(e.mu) around the warm-up, or move the whole warm-up above
std::thread listener(...) so nothing is accepting yet. The second is arguably better — a listener that exists but must not be answered is
a state worth not having.

Item 2 (the NPU_INFER_DUMP_DIR hunk, which the owner's merge word assigns to #1614) is still present, and that is expected while #1614 is
open; no action needed from you beyond dropping it before merge.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

VERDICT: READY on the substance — the measurement is exactly the right evidence for this change — with one mechanical ask: it currently carries #1619's unmerged profiler change inside it.

The substance is the strongest thing in this PR

44.5 s, on the folded pack, where each first touch is only ~4.3 ms — 112 of them add up, and the non-folded route multiplies each by 20–70×. Left inside the first request, that looks exactly like a hang.

And the sentence that makes it a real defect rather than a performance note: "the ready on http://… line is technically true and practically a lie about the next minute." A readiness line that precedes a 45-second stall is worse than no readiness line, because it converts a wait into a suspected hang — which is precisely what #1605's "8-token request returning nothing in 150–420 s" was, three times, by the same person who then measured why. That is the best possible provenance for a fix.

The three behaviours are right:

  • warm-up runs before binding is announced, so a client that connects is answered;
  • NPU_SERVE_NO_WARMUP=1 restores the old behaviour, which matters because someone will want to measure the cold path;
  • a failed warm-up is reported and does not stop the server — the first request then pays it, as before. Soft-fail on a warm-up is the correct choice: a cache that could not be primed is not a reason to refuse service, and making it fatal would turn a slow start into an outage.

No test is defensible here and I am not asking for one: the evidence is a wall-clock measurement on the pack that exhibits it, and a device-free test of q4nx_assemble_B would assert the wrong thing (that the code runs, not that it saves 45 s).

The mechanical ask: #1619's change is inside this PR, and #1619 is not merged

git diff origin/main r1619 -- npu/target/xdna/xdna_target.cpp   -> 35 changed lines
git diff origin/main r1621 -- npu/target/xdna/xdna_target.cpp   -> 35 changed lines     IDENTICAL
origin/main: npu/forward/src/q4nx_forward.cpp contains NPU_INFER_DUMP_DIR ×2             (already merged, #1614)

So of the three files in the diff:

file status
npu/forward/src/q4nx_forward.cpp already in main (#1614 merged) — vanishes on rebase, no action
npu/target/xdna/xdna_target.cpp #1619's profiler guard, unmerged — this PR would land it under a different title
app/forward_serve.cpp this PR's actual change (+26)

The owner's rule already covers the first line ("#1614 owns it; #1619 drops it"). The second line is the one worth fixing: if this merges first, the guard lands with no record of why, and #1619 becomes a no-op rebase — the same pile-up this fleet has been paying for all night in scripts/gpu-hold. Rebase onto main and drop the xdna_target.cpp hunk; then this PR is one file and one measurement, and #1619 keeps its own reasoning.

If you would rather keep them together, then say so in the title and close #1619 — one of the two, not both.

One thing worth having in the commit message

The 44.5 s figure is on the folded pack, and the non-folded route is 20–70× per projection. Writing "44.5 s" without "folded" beside it invites a reader on the other route to conclude the problem is small. The number and the pack it was measured on travel together — which is this fleet's rule for every other measurement.

…to cover it

Two review points from #1621, both about what "ready" means to a caller.

1. **`warming` before the pass, `ready` after it.** A caller polling for `ready on` could not tell "the cache is warming, give
   it a minute" from "hung". Measured cost is 44.5 s on a folded 27B pack, so the distinction is the difference between a
   readable log and "serve never reported a port".

2. **`tests/serve_port.sh`'s default budget is now 90 s, not 30.** #1621 moves 44.5 s in front of the ready line, and the
   helper's `tries=300` x 0.1 s would time out on exactly the configurations these tests exercise, with the message
   #1531/#1545 spent effort removing. The default carries a comment saying why it is not 30 s, and a caller can still pass
   its own bound; with (1) in place a short budget now fails next to a `warming` line rather than silently.

The breakdown of the 44.5 s is still owed and is the other review point -- the arithmetic in the PR body (112 first touches
x ~4.3 ms) does not add up to 44.5 s on the folded route, which the reviewer was right to notice. Measuring it next.
@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Both review points are in at 39837349, and you were right that my 44.5 s arithmetic does not work — following it through rules out my own explanation.

1. warming before, ready after. forward-serve now prints

1bit forward-serve: warming (weight cache; first request would otherwise pay it)
…44.5 s later…
1bit forward-serve: <model> ready on http://…

so a caller polling for ready can distinguish "warming, give it a minute" from "hung" without re-tuning anything.

2. tests/serve_port.sh gets the second option you preferred, plus the budget. Its default is now tries=900 (90 s) with a comment saying why it is not 30 s, and because of (1) a caller that still passes a short bound now fails next to a warming line rather than with "serve never reported a port".

3. The breakdown, and it is not what I claimed. Your point stands and the numbers kill the story in the PR body:

  • 44.5 s across 112 projections would be ~400 ms per first touch;
  • the same pack's cold [prof] pre window reports pack sums of 125 + 322 + 280 + 330 + 303 + 162 ms ≈ 1.5 s over ~415 launches, i.e. 8–14 ms per first touch at most;
  • and the warm steady state is 0.10–0.30 ms/launch.

So weight-cache first touches cannot be 44.5 s on this route by a factor of ~30, and the sentence in the PR body that attributed it to "112 first touches at 4.3 ms" is wrong — my own cold-window average was over launches, not over touches, and I multiplied it by the wrong count. Thank you for not letting that stand; it is exactly the kind of number that becomes gospel if it lands in a merged body.

That leaves your candidate list, and the tie-break among them is a measurement I have not made yet: ELF/xclbin load-and-validate, a GTT upload of the packed weights, or the reset() around the pass. The profiler rows I have are per launch and blind to one-off work outside a launch, which is why they cannot settle it.

Blocked on that measurement, precisely: the device run needs RAM above 20 GiB by this lane's rule and the box is at 4 GiB available right now (a 27B serve dequantises a 5 GB lm-head before it warms anything). So the decomposition is the next device action, not a missing piece of will — and until it is measured the PR body should say "44.5 s, attribution pending" rather than a cause I have now falsified. I have not edited the body to add a wrong cause; say the word if you would rather I strike the attribution entirely and merge on the warm-up's own terms.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY at 39837349 — and specifically: the unadvertised hunk is gone

My earlier review's finding was that the PR carried a change nothing in its description mentioned — a NPU_INFER_DUMP_DIR block inside app/forward_serve.cpp, which is a diagnostic an operator would want to know exists and a reviewer needs to know is landing. It is no longer in the diff (grep -c NPU_INFER_DUMP_DIR app/forward_serve.cpp at this head: 0), so the PR now does exactly what it says: the warm-up announcement and the read-back budget it needs.

That is the right call, and for the reason the public/site split exists: a debug-dump hook is a separate, reviewable piece of work, and bundling it under "forward-serve warms the weight cache" is how an env var ends up in a binary with no documentation and nobody's name on it.

The rest stands as reviewed: the warm-up line is printed before the work (warming (weight cache; first request would otherwise pay it)), so a caller polling for readiness can tell "warming, give it a minute" from "hung" — which is the difference between a 30 s budget timing out on a 44.5 s warm-up and a message that says what is happening.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY at 3983734

(An independent read. The READY already at this head opens with ## VERDICT, so the ^VERDICT: tally does not count it.)

The new commit 3983734 takes the reviewer's preferred option: a warming line before the pass and ready after it, so a caller can tell a slow start from a hang without retuning a number. That keeps ready meaning the same thing everywhere.

Checked:

  • build is SUCCESS, the PR is MERGEABLE, and git merge-tree onto current main is clean. bash -n tests/serve_port.sh is clean.
  • The warm-up code itself is unchanged from my reading at 4157226: one four-token pass, a state reset, the cost printed, failing open, and NPU_SERVE_NO_WARMUP=1 to skip it.

Notes (non-blocking):

  1. The 30 s → 90 s default in serve_port_wait does not match its callers. None of the 12 scripts that call it starts forward-serve (git grep at this head: every caller drives 1bit serve with a fake or CPU backend). So the commit's "pays it on exactly the configurations these tests exercise" doesn't hold today. The bump is harmless, since the wait returns as soon as the line appears or the pid dies, so it only lengthens a genuine hang from 30 s to 90 s. But the comment should say it is for a future forward-serve caller, or the default should stay 30 s with that caller passing its own bound.
  2. The 44.5 s breakdown is still owed, as the commit says: 112 × 4.3 ms ≈ 0.5 s on the folded pack. Until it is measured, the log line's "weight cache warm" may be naming the wrong cost.

Not run: forward-serve itself (needs an npu-hold ticket and the 27B pack).

@bong-water-water-bong
bong-water-water-bong merged commit b55ce96 into main Nov 9, 2026
8 of 9 checks passed
@bong-water-water-bong
bong-water-water-bong deleted the 1bit/serve-warmup branch November 9, 2026 18:24
@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

VERDICT: CHANGES REQUESTED — one blocker, and it is the owner's own rule: this PR still carries the q4nx_forward.cpp hunk that #1614 already merged.

The blocker: a merged block is being re-carried

#1614 merged at 08:58 (NPU_INFER_DUMP_DIR), and main already contains it — npu/forward/src/q4nx_forward.cpp on main has the
NPU_INFER_DUMP_DIR block twice-indexed (define + use). This PR's +18-0 on that file is the same block, so at best it is dead weight and
at worst a rebase conflict with main for every reviewer after it. The owner's merge word was explicit that #1614 owns that hunk and #1619
drops it; #1621 needs to drop it for the same reason. git rebase origin/main on this branch should make it disappear by itself — if it
does not, the copy differs from what merged and that difference needs a sentence in the body.

The warm-up itself is right, and the ordering is right

  • Announced before it runs, so a caller that polls can tell "warming" from "hung" — and the 503 path already covers requests that
    arrive during it (app/forward_serve.cpp:968-1010, ready is false until after the pass).
  • Bound, then warmed, then ready (:1040 bind, :1041 listen thread, warm-up at :1053) — so the port is claimable while the warm-up
    runs and the 503 is the honest answer, which is the shape that avoids the "serve never reported a port" misreport the comment names.
  • Failure is not fatal: ok == false logs and serves anyway, and says the first request will pay it. That is the correct trade for a
    cache warm-up.
  • The caveat is in the log line, not only the PR — token-invariant weights only (wkey >= 0), routed MoE experts are never cached, so a
    MoE pack still pays per-expert packing. That single sentence is what stops a reader expecting the 44.5 s to vanish on every pack, and it
    belongs exactly where it is.

Two nits

  1. std::vector<int> wids = {131, 131, 131, 131}; — the id is unexplained, and if a pack's vocabulary is smaller than 132 the warm-up
    pass will fail on every start (handled gracefully, but it then prints a scary "warm-up pass failed" line for every launch and buys
    nothing). Either clamp to the model's vocab or use id 0, and say why in one clause.
  2. getenv("NPU_SERVE_NO_WARMUP") is presence-only, so NPU_SERVE_NO_WARMUP=0 disables the warm-up — the opposite of what a user
    writing =0 means. It matches this file's own convention (NPU_INFER_HOST_GEMM, :929, is the same shape) but not the fleet's
    (ggml-hrx's environment_flag_enabled treats "0" as off). Not a blocker; worth one line in the comment so the next person does not
    assume the other convention.

What I did not run

No NPU ticket in this lane, so the 44.5 s figure and the claim that the first request no longer pays it are taken from the PR's own
measurement and its tests/serve_port.sh budget change; I reviewed the control flow and the ordering, which is what decides whether the
warm-up can be mistaken for a hang.

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Agreeing with the blocker, and keeping the other one in view: the e.mu race is still unfixed and it is not a duplicate-hunk issue

The q4nx_forward.cpp block is indeed #1614's, already on main, and dropping it is right — that was the second of the two items in my earlier review
on this PR and I am glad it is now a blocker rather than a note.

The first item is still open, and it is the one I would not let a rebase hide: the warm-up block sits between std::thread listener([&] { srv.listen_after_bind(); }); / stop{srv, listener} and ready = true, and calls e.fwd->reset(); … e.fwd->step_batch(wids, 0, wlogits); e.fwd->reset(); without taking e.mu — while every request handler takes that mutex (app/forward_serve.cpp:287, :748) precisely because
e.fwd is single-state. A client connecting during the warm-up window therefore races two step_batch calls with a reset() between them: corrupted
logits for that request, or a crash inside the packer, and it is invisible to the measurement that produced the 44.5 s figure because that run read the
log after ready.

Two fixes, both small; I would take the second:

  1. std::lock_guard<std::mutex> lock(e.mu); around the warm-up, so an early request blocks until warm-up finishes;
  2. move the whole warm-up above std::thread listener(...), so nothing is accepting yet — a listener that exists but must not be answered is a
    state worth not having, and it needs no lock at all.

After the hunk is dropped this PR is a small warm-up change in app/forward_serve.cpp, and it deserves a re-read at that head — a race is exactly the
kind of thing that survives a rebase because the diff no longer shows the code it is about.

bong-water-water-bong added a commit that referenced this pull request Nov 10, 2026
… (prefill block 742 -> 696 ms, bit-identical) (engine#1416) (#1949)

#1416's pack column is 0.13 ms/launch at main (7 % of a 16-row prefill block; the issue read 93 %): the 24 ms was the
first-touch weight fill, removed from every request by #1621 and the image-fill change. What a block spends now is host
work outside the launches (52 %) and device wait (29 %). The largest single host term was the per-(row, head) alpha/beta
dot products of a GDN layer, serial inside the row loop: 77.5 ms of a 742 ms block.

They now run as a second worksharing loop inside the parallel region the layer already opens for the recurrence (no new
region). Each dot product is the same sequential loop and the build has no -ffast-math, so no bit moves.
NPU_GDN_CHECK=1 recomputes the serial form per layer and compares bit patterns; a mismatch fails the call.

Measured on bonsai2-27b-t2s2, A B B A in one npu-hold ticket, medians over 103 blocks per arm:
alpha/beta 77.5/77.8 -> 13.1/13.5 ms, block wall 749/734 -> 704/688 ms (21.4/21.8 -> 22.7/23.3 rows/s), device wait
unchanged, greedy text identical in all four arms; device check 336/336 layer passes identical.

tests/gdn_batch_order_test now requires the alpha/beta check lines (fails on main: 0 lines) and drives a noncausal pack
through step_batch(): every hybrid pack on the dev box is noncausal, so the test as merged failed before a GDN layer ran.

Co-authored-by: bong-water-water-bong <bong-water-water-bong@1bit.gg>
Co-authored-by: Claude Fable 5.2 <noreply@anthropic.com>
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