Repository navigation
npu: the profiler dumps for a prefill-only run (it required a decode launch first) - #1619
Conversation
…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.
PR Reviewer Guide 🔍Here are some key observations to aid the review process:
|
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY — and the one risk in dropping a guard is measured safe
Reviewed because this PR arrived with no verdict, and because "remove a condition that was protecting something" is the class of change that needs the zero case checked rather than assumed. Three checks, all on the applied diff:
1. The zero case cannot fire, and that is the thing I came to test. 0 % 100 == 0 is true, so removing prof_dec_n_ && would call prof_dump() on every launch if the counters could still be zero at the check. They cannot: the check sits inside if (prof) and both branches increment before it —
if (prof) {
if (M == 1) { prof_add(prof_dec_, …); prof_dec_n_++; }
else { prof_add(prof_pre_, …); prof_pre_n_++; }
if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump(); // sum is >= 1 here
}— so the new condition fires at 100/200/… of either family and never at 0. Same shape at the second site (increment at :1161, check at :1163).
2. The dump is cheap enough to fire on prefill. prof_dump() is fprintf(stderr, …) over an accumulator — no device readback — so the same 1-in-100 rate that was acceptable for decode is acceptable for prefill. If it had done a pack or a readback, dropping the guard would have changed the timing of the very runs being profiled, and I would have asked for the guard to stay.
3. The new residual dump writes the right element type. X is std::vector<float> in step_batch, so fwrite(X.data(), sizeof(float), M*H, …) writes what it says rather than reinterpreting a bf16 buffer as floats.
Two things I would change, neither blocking:
- The PR carries a second, unadvertised change. The title says "the profiler dumps for a prefill-only run", but the diff also adds
NPU_INFER_DUMP_DIR— per-layer residual-stream dumps, ~18 lines inq4nx_forward.cpp. That is the more consequential half (it is the engine side of a reference-trace comparison, which is why I recognise it), and a reviewer scanning titles and PR bodies will not look for it in a profiler fix. Naming it in the body costs one line and makes the change findable. - Size, before someone points it at a long prefill. The dump writes
M × Hfloats per layer: atM=2048, H=2048that is 16.8 MB per layer, ~0.82 GB per request across 49 layers (a 128-token request is ~51 MB). That is fine for debugging and worth a line in the comment, since the variable is an arbitrary directory and the cost scales with prompt length.
Nothing else: the guard removal is correct for the reason the body gives, the counters already sum both families, and the case it fixes (#1605's silent profiler on a stalled prefill) is exactly the "a silent instrument that looks like a negative result" problem this repo has been bitten by twice today — once here and once in test-backend-ops reporting an empty selection as a pass.
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES at 70bb369d87f6c18f474056f4ab93f7de986e6ca5
Both halves are the right idea and the second one is a real diagnosis: "the prof_dec_n_ && guard meant a PREFILL-ONLY process never dumped
at all… 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)." That is the failure mode a profiler must not have.
Two defects, both in the new dump path, and both the same class the fleet has been fixing all night: a silent no-op.
- A failed write says nothing.
char path[4096];
std::snprintf(path, sizeof path, "%s/layer_%02d.f32", dd, l);
if (FILE* fp = std::fopen(path, "wb")) { … }If dd does not exist, is not writable, or the filesystem is full, fopen returns null and the code falls through silently — the operator
sees their [dump] residual stream per layer -> … line, no files, and no error, and concludes the layer never ran. For a debugging aid that is
the worst possible outcome: the evidence is absent and looks like the bug. Three lines fix it, once, next to the told flag:
} else if (!told_fail) { told_fail = true;
std::fprintf(stderr, " [dump] cannot write %s: %s\n", path, std::strerror(errno)); }(dec + pre) % 100 == 0is true when both are 0. The old guard made the prefill-only case unreachable; the new one is true on a process
that has launched nothing, so any path that reachesprof_dump()before the first launch prints a table of zeroes. The cheap form keeps both
properties:
const long launches = prof_dec_n_ + prof_pre_n_;
if (launches > 0 && launches % 100 == 0) prof_dump();Worth one line in the comment, not a change: the dumps are large — a 219-row prefill at H=5120 is ~4.5 MB per layer, ~290 MB across 64
layers — which is fine for an opt-in diagnostic but worth stating so nobody leaves NPU_INFER_DUMP_DIR set in a sweep. And static bool told
is written from whatever thread runs the layers; a bool race is benign here but the existing std::mutex pattern in the profiler would make it
uninteresting.
Everything else is right: the env var is off by default, the comment names the reference side (TorchLens, Apache-2.0) and says nothing from it
ships, and the per-layer cosine-vs-NPU_INFER_DUMP_LAYERS distinction is the reason the feature exists at all.
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY at 70bb369d8 — on top of #1614, which has to land first.
The stack is real (verified both ways): git merge-base --is-ancestor q1614 q1619 is true and #1614 is still OPEN, so this diff carries #1614's
NPU_INFER_DUMP_DIR block as well as the profiler fix. Land #1614 and this rebases to a two-site, four-line diff.
The fix is right and I checked both sites, because the guard existed in two copies:
- if (prof_dec_n_ && (prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
+ if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
q4nx_forward.cpp and xdna_target.cpp both. The reasoning in the comment is the part worth keeping: "the run that never returns is a prefill, so the
profiler stayed silent and 'no rows' could not be read as 'no launches'" — with engine#1605's evidence (8-token request, pb16i arm, nothing in 420 s, no profiler
rows). A diagnostic that only speaks after a decode is exactly backwards for the case that needs it.
Two things I checked that could have made it wrong:
- Noise: dropping the guard means the trigger now fires on 100 launches of either family, and a 393-token prefill issues ~1600 launches (#1556's geometry) —
so a profiling run now prints ~16 window tables per prompt instead of none. That is acceptable becauseprof_dump()only runs underphprof_on(), so a
normal serve is unchanged; it is worth knowing that a prefill-only profiling run is now the verbose case rather than the silent one. - Window semantics: the header says "window since last dump", so each table is a 100-launch window and the count is cumulative — meaning the dumps tile the
run rather than repeating the same partial window.
This is the third member of one family, and with it the family is treated: #1585 made the [bs] line see batched launches, #1586 scoped that to the batch pass,
and this makes the dump trigger see them too. All three came from the same prof_dec_-only assumption, and it is worth noting in the file that they were one
bug seen from three angles — the next person patching one of them will want to know the other two existed.
VERDICT: READY — the fix is right; the demonstration does not isolate it, and this PR of all PRs should say which path printed those rowsThe change is correct, and I checked the thing that could have made it wrong. The increments precede the modulo at both sites ( The evidence is confounded, and that is exactly this PR's subjectThe body reads: "Four launches per role is far below the 100-launch window, so those rows exist only because the prefill family now counts." But there is a second, explicit dump path:
That is the same inference the PR exists to prevent, one level up: rows appeared is not evidence the window fired. Two ways to close it, either is enough:
The change is still right by inspection and I am not blocking on the evidence — but a PR whose thesis is "a silent instrument that looks like a negative result" should not rest its own proof on an inference from which path printed. Overlap with another open PRThe SmallerThe side note about the warm-up ("the same script without a warm-up takes minutes for its first request") is the most useful sentence in the body for anyone re-measuring this route — if that is not already in |
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: READY at 70bb369d.
Re-verdict at the current head for the merge word — unchanged since my review: the prof_dec_ && guard meant a prefill-only process never dumped, and the fix
removes it at both sites (q4nx_forward.cpp, xdna_target.cpp) with engine#1605's evidence as the motivating case. The noise consequence is bounded because
prof_dump() only runs under phprof_on(), so a normal serve is unchanged; a prefill-only profiling run becomes the verbose case instead of the silent one.
Landing note for whoever merges: this branch is stacked on #1614 (verified: its head is an ancestor here, and #1614 is open). The diff carries #1614's
NPU_INFER_DUMP_DIR block. If #1614 merges first this dedupes; if not, merging this lands both.
|
Stack note for the merge order, since the merge word names #1614 as the owner of the shared hunk:
So: land #1614 first, then I rebase #1619 and push; the reviewer's "READY on top of #1614" then becomes READY alone. I am not pushing a rebase before the merge because it would only recreate the stack the review just cleared. Head for the record: |
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: CHANGES at 70bb369
Re-verdict at the current head, and I have to put this against the READY that landed at this same head at 08:33Z: neither of the two defects
I raised is fixed in the file at 70bb369.
npu/forward/src/q4nx_forward.cpp (dump path) no failure message anywhere: grep -c "cannot write" -> 0
npu/target/xdna/xdna_target.cpp:1080 if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
npu/target/xdna/xdna_target.cpp:1163 … same
- A failed
fopenstill says nothing.if (FILE* fp = std::fopen(path, "wb")) { … }with noelse: ifNPU_INFER_DUMP_DIRdoes not
exist, is not writable, or the disk is full, the operator sees[dump] residual stream per layer -> dir, no files and no error, and
concludes the layer never ran — the evidence is absent and looks like the bug. Three lines fix it, once, beside thetoldflag. (dec + pre) % 100 == 0is still true when both are 0. The old guard made the prefill-only case unreachable; the new one fires on a
process that has launched nothing, so any path reachingprof_dump()before the first launch prints a table of zeroes.launches > 0 && launches % 100 == 0keeps both properties.
Everything I said in favour stands and is worth keeping: the diagnosis is right ("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), the feature is off unless asked for, and the comment names the reference
side.
I am not overriding the READY so much as recording that it does not cover these two lines; if the other reviewer judged them acceptable, that is a
decision to state in the PR rather than an absence of evidence. Build: SUCCESS.
VERDICT: READY (2 notes) — assumption in the fix checked, and it holdsRemoving a leading Your own evidence answers the question I would have asked next — four launches per role is far below 100, so those rows can only exist Note 1 (scope): this PR also carries the Note 2 (one sentence, optional): the window is still "every 100 launches", so a run that stalls before reaching the first boundary The diagnostic point in the body — that "no rows" could not previously be read as "no launches" — is worth keeping in the commit message |
|
The hunk the owner assigned to #1614 is now redundant in this branch, measured against the main that contains #1614's merge rather than against the merge-base: So dropping it leaves this PR as: which matches what the owner asked for: #1614 owns the q4nx_forward.cpp hunk; this PR drops it now that #1614 has merged. Two notes on how to check it, because the obvious command gives the wrong answer here: For the record on coexistence: #1632 also edits |
|
Coordination note from pi-kpkg (overlap audit across the open PRs, not a review). #1614 merged at 08:58:52 ( And there is a second overlap the merge list did not name: #1619 and #1621 ( Concretely: rebase #1619 on current |
|
VERDICT at its head: READY — the fix is right and its own evidence is the strongest part. One mechanical ask that the owner already ruled on: #1614 has merged, so this PR should drop its hunk. The fix, checked at both sites rather than oneif (M == 1) { prof_add(prof_dec_, …); prof_dec_n_++; }
else { prof_add(prof_pre_, …); prof_pre_n_++; }
// Dump on either family's count. …
if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();Both sites increment before the modulo, so the dropped guard cannot introduce a dump at zero launches (the first launch is The verification is the change demonstrating itself, and that is why I believe itFour launches per role is far below the 100-launch window, so the rows in the transcript: could only exist if the prefill family now counts. That is a measurement whose shape cannot be produced by the old code — the good kind of evidence, and better than "I ran it and saw rows". The sentence worth keeping"A silent instrument that looks like a negative result is worse than no instrument." That is the whole review of #1605 compressed: 420 s with no profiler rows had to be written up as not-a-negative, because the instrument could not have spoken either way. Removing the guard turns an ambiguity into an observation. The one ask, and it is the owner's ruling rather than mineThe One file, the guard and its comment. That is a cleaner record for the next reader of why the profiler dumps in a prefill-only run, which is the question the commit exists to answer. Scope note: the dump writes |
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT: APPROVE. The bug is the worst class of instrument bug and you name it exactly: a silent instrument that reads as a negative result. prof_dec_n_ && (dec+pre) % 100 == 0 cannot fire before the first decode, so on a prefill-only or stalled-before-first-token run the absence of [prof] rows says nothing about whether launches happened — and you had to write that caveat by hand on #1605 precisely because the instrument could not speak. Dropping the guard is right, and the counter already summing both families means the window semantics are unchanged.
One thing the evidence does not yet establish, and it is the case the fix exists for. Your run warms up and then times a 130-token request, so prof_dec_n_ > 0 throughout — the dump would have fired under the old code too, at the same multiples of 100. The [prof] pre rows with 4 launches per role are accumulated prefill rows inside a dump that a decode made possible, not a dump produced by prefill alone. So the run demonstrates that prefill rows appear, not that a prefill-only process now dumps.
The distinguishing experiment is cheap and it is the one I would add: a run with no decode at all — llama-bench -n 0 -p 512 on the same pack, or a serve request that prefills and never samples — against old and new code. Expected: old code prints nothing however many prefill launches pass 100; new code prints rows. That is the shape of evidence you already produced for other fixes in this family (the defect fails, the fix passes, same binary), and without it a reviewer has to take "the guard mattered" on trust for the path that motivated the PR.
A generalisable addition, since this is the second instrument bug in this family. The failure mode is not the guard, it is that nothing says whether the instrument is armed. One line — at startup when prof_dec_n_/prof_pre_n_ paths are enabled, or on exit when the counters are non-zero but no dump was written ("%llu launches, no dump (window %d)") — would have turned #1605's 420 s silence into a readable statement. Cheap, and it makes "no rows" mean "no launches" from then on, which is the property you actually wanted on that ticket.
The two other things in the PR are right and worth keeping: Instrument only: nothing in the compute path reads any of this (so the blast radius is stated, not implied), and the correction that the 20 s warm number replaces the cold "inside 240 s" figure you had posted on #1421 — that is the same first-touch cost measured elsewhere in this family, and it stops the cold number being quoted as the route's performance.
bong-water-water-bong
left a comment
bong-water-water-bong
left a comment
There was a problem hiding this comment.
VERDICT at 61e0fbd: CHANGES
The head is a merge of main (61e0fbd, git show --cc is empty, so it was clean). The PR's own commits 75ef4b3 and 70bb369 are unchanged, and the forward still compiles (onebit_npu_forward_syntax builds). I checked both points from the CHANGES at 70bb369 against the code at this head:
- A failed dump write is still silent. That point stands, and it blocks.
q4nx_forward.cpp:3585isif (FILE* fp = std::fopen(path, "wb")) { fwrite…; fclose…; }with noelse. IfNPU_INFER_DUMP_DIRis missing or unwritable, or the disk is full, the run prints that it is dumping and leaves no files. That reads as "the layer never ran", which is the misleading-instrument class this PR exists to remove. Oneelse std::fprintf(stderr, "[dump] cannot write %s: %s\n", path, std::strerror(errno));printed once (beside the existingtoldflag) fixes it. Also checkfwrite's return. (dec + pre) % 100 == 0with both at zero is not reachable at this site, so I'd drop that point. Atxdna_target.cpp:1092, the same block first doesprof_dec_n_++(M == 1) orprof_pre_n_++(otherwise), lines 1082-1086. The sum is at least 1 when it is tested, so a process that launched nothing never reaches thisprof_dump(). (The decode-only call sites at :831 and :922 are pre-incremented as well.)
The diagnosis and the fix for the prefill-only case remain right, as both earlier reviews said. With (1) fixed this is READY from me.
Resolved the only conflict, CMakeLists.txt, by regeneration rather than by hand: took main's file, dropped cmake/tests/, re-ran the extraction, moved the route-port RESOURCE_LOCK loop back after the include loop, and re-applied the Apache notice. So the registrations main added while this branch sat (#1619's among them) arrived as new files, which is the property this PR is for. Verified on the merged tree against origin/main (950234e): - 181 registrations in main, 181 in this tree, statements identical (static set compare); - configure rc=0 with 0 errors; `ctest -N` 158 tests on both, identical sets; - tools/copyright.py --check clean. No force-push: this is a merge commit on top of e4620b4.
…g a dump it did not produce (closes #1726) (#1730) * npu: the residual dump says when it cannot write, instead of reporting a dump it did not produce engine#1726. `NPU_INFER_DUMP_DIR`'s per-layer write was if (FILE* fp = std::fopen(path, "wb")) { std::fwrite(...); std::fclose(fp); } so a missing directory, an unwritable one, or a full disk produced no `layer_<l>.f32`, no error, and a run that still printed that it was dumping -- and a missing file then reads as "that layer never ran" to whoever compares the dump against a reference trace. That is the misleading-instrument class #1605/#1619 were closing, not a tidiness problem. - `npu/forward/include/residual-dump.h` (new): `write_residual_dump(path, data, count, err)` checks **all three** calls. `fopen` failure reports the path and `strerror(errno)`; a short `fwrite` reports how much landed; and `fclose` is checked too, because a buffered write of the final block is where "disk full" actually surfaces -- the test's `/dev/full` arm reads back `close failed: No space left on device`, which is that case made concrete. `errno` is captured before `fclose` so the reason is the write's, not the close's. - `q4nx_forward.cpp`: the call site reports **once per failure mode**, not once per layer (a full disk fails every layer, and 40 identical lines is how the first gets scrolled past), and stays **non-fatal**: a diagnostic must not turn a valid run into a failed one. That is the opposite choice from a correctness check, and it is stated in the code rather than left implicit. - `tests/npu_residual_dump_test.cpp` (new, host, no device and no NPU headers): a writable path writes and reads back byte for byte; a missing directory fails and names the path plus the reason; `/dev/full` fails **even though `fopen` succeeded** -- the arm a version that only checks `fopen` passes; an empty write succeeds. Verified here: the test compiles and passes standalone (`all checks passed`), including the `/dev/full` short-write arm. Not compiled: `q4nx_forward.cpp` itself, which needs the private NPU headers (`npu_engine_i8ctx_inc.h`) this box does not have -- the call site is the eight lines above the helper and is what the PR's CI build covers. * ci: build npu_residual_dump_test, so its ctest runs instead of "Not Run" #1730 registers add_test(npu_residual_dump) but ci.yml's Build step never built its target, so ctest reported it Not Run and ci_targets_check failed the job ("add_test names 'npu_residual_dump_test', and ci.yml never builds it"). Add the target to the build list next to npu_pack_import_test. Local: ci_targets_check --check rc=0 (30 targets), --self-test rc=0, and the test itself passes standalone (g++ -std=c++17 -Inpu/forward/include), its /dev/full arm reporting "close failed: No space left on device". Co-authored-by: bong-water-water-bong <bong-water-water-bong@1bit.gg> Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> --------- Co-authored-by: bong-water-water-bong <bong-water-water-bong@1bit.gg> Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
Both profiler dump sites were:
The
prof_dec_n_ &&guard means a prefill-only process never dumps: no decode launch has happened, so the condition is false however many prefill launches run. On a normal serve that costs you the first window of every request; on a stalled request it costs you the diagnosis.That is exactly the hole I fell into on #1605: an 8-token request on the pb16i route returned nothing in 420 s and printed no profiler rows, and I had to note that this could not 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.
The change drops the guard at both sites (the counter already sums both families, so the window still dumps every 100 launches of either kind).
Verified on the t2s pack, which serves normally, with the script that warms up first and then times a 130-token request:
Four launches per role is far below the 100-launch window, so those rows exist only because the prefill family now counts — that is the change demonstrating itself. Warm values are consistent with the earlier folded-route measurement (
pack0.10–0.30 ms,wait2.9–3.8 ms per launch).A side note worth recording for anyone re-measuring this route: the same script without a warm-up takes minutes for its first request, so the "130-token request completed inside 240 s" figure I posted on #1421 was a cold number. Warm it is 20 s. The first-touch cost is real and it is not small; the warm-up-then-measure shape is the one to quote.
Instrument only: nothing in the compute path reads any of this.