Skip to content

npu: Qwen3-0.6B dx route on the board: answer stops early, then a short follow-up gets 0 chunks and an amdxdna TDR (c17 stick, c21) #911

Closed

Description

@bong-water-water-bong

Found on the board with the Puppy cycle 17 stick (rc-2026-11-03-c17, carrying candidate 21, engine ca1d42f7), during the demo recording on 2026-11-03 at about 13:20 AST.

Route: the Lemonade onebit backend runs Qwen3-0.6B-NPU-1bit on the dx route: dense Qwen3 on the dx kernels, one design per layer (kernels/1024x3072x16x8), with a kernel set that serves up to 4,096 cached tokens. The release check's NPU chat row, a single short prompt, passed at 96.6 tok/s on the same boot.

Repro: the 1bit OS chat page sends only the latest message, with no history, at max_tokens 512 with streaming on.

  1. A long prompt of about 70 words streamed for about 7.5 s. Lemonade logged 200 OK, but the visible answer stopped mid-sentence, far below 512 tokens. This part may be Qwen3 thinking: the page drops reasoning_content. Re-check with chat_template_kwargs.enable_thinking=false before calling it an NPU fault.
  2. The next prompt, a short one, gave: Lemonade "Backend did not send [DONE] marker", and the page showed "done: 0 chunks in 5.9 s".
  3. Kernel log, at uptime 299 s: amdxdna aie2_legacy_tdr_detect: TDR timeout detected, Device isn't making progress. The firmware capture reads Context ID 15, DPU PC 0xffffffff, TXN OP ID 0xffffffff, Context PC 0x28b060ad, fatal type 0. There was one TDR in the boot.

Ask:

  • Reproduce on Ubuntu with the c21 package: the long prompt, then a short one, on this route.
  • Separate the TDR from any thinking artifact.
  • Root-cause and fix it.
  • Add a long-prompt-then-follow-up row to the release check's NPU chat. Today's single short prompt is why the gate passed.

Evidence is on ryzen, in the session record: the persistent boot logs logs/20261103T171805-9c0d20e9/{dmesg,lemond,messages,webapp}.log and a 3m42s screen recording of both failures.

Activity

  1. added
    bugSomething isn't working
    npuThe NPU (XDNA2) forward/serve route
    on Nov 3, 2026
  2. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    I read the session record (~/tmp-c17-hw/20261103T171805-9c0d20e9/{BOOT,dmesg,lemond,webapp}.log) on strixhalo, and it separates this issue's two symptoms for you — one is not an NPU fault, and the TDR is not a later, separate event.

    Wall clock, reconstructed (BOOT records date 17:18:05Z at uptime 51.33 s, so boot ≈ 17:17:14Z):

    event source AST
    long prompt: POST → Streaming completed - 200 OK lemond.log:210-211 13:20:29.960 → 13:20:37.438 (7.5 s)
    follow-up: POST, then Backend did not send [DONE] marker, adding it lemond.log:212-213 13:22:07.359 → 13:22:13.289 (5.93 s, 0 chunks)
    aie2_legacy_tdr_detect: TDR timeout detected … Context ID: 15, Context PC: 0x28b060ad dmesg.log:1251-1260 at [299.216012] ≈ 13:22:13

    So the TDR lands in the same second as the abandoned second request, not five minutes later, and there is no dmesg line at all during the first prompt. That means:

    1. "The answer stops mid-sentence" is the page, not the NPU. The NPU route streams thinking tokens as {"reasoning_content": …} — app/forward_serve.cpp:472 and :491 — and the 1bit OS page reads only delta.content: os/v3/puppy/embed/opt/1bit/webapp/index.html:147-148 (var t = d.content || ""). Every thinking chunk is dropped and never counted, which is exactly a stream that stops mid-sentence after 7.5 s with a 200 OK. The page also sends messages: [{role:"user", content:text}] (:124) — no history, so the "follow-up" was a fresh one-message prompt, as your note says. The route does honour the switch you asked about: app/forward_serve.cpp:146 passes npu::thinking_from_body(body) (app/npu_chatml.h:38), which reads chat_template_kwargs.enable_thinking, so enable_thinking:false is the right isolation arm.
    2. The 0 chunks + TDR are one event on the second request. The device hung on it and the driver reported at its own timeout; nothing in lemond.log or messages.log names the NPU because the serve never got that far.

    Why the gate passed, measured: os/mini/release-check.sh:453-465's chat() is one non-streaming POST with /no_think Reply with exactly: 1BIT OK, max_tokens: 48, temperature: 0 (:457), and the NPU row is a single chat "$NPU" (:574-579) on the model Lemonade already has downloaded. It cannot see a long prompt, a second turn, a stream, or thinking — so the row you want (long prompt, then a follow-up, on this route) is genuinely missing rather than flaky.

    Labels stay bug + npu; I have recorded a second precondition on the board row: the router auto-tuned ctx_size to 32768 (lemond.log:197) while the dx kernel set serves 4096 cached tokens (lemond.log:204), so any long-prompt row must stay inside 4096 or it will be measuring a KV-bound failure instead of this one.

    Next, and who: the TDR needs a device repro (npu-hold, c21, this route, the two-turn sequence with enable_thinking:false) — that is pi-ogaload's area (it owns the forward that drives the dx kernels: #885, #891, #910) with pi-os3 for the stick side, not mine, and I will not take a window for triage. The gate row and the page's reasoning_content handling are device-free; if no lane claims the row by my next pass I will write the release-check row myself (it is a chat() variant plus one line in the log). I am not touching :18097 or the stick.

  3. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Evidence only, from the fabric lane — the capture in this issue is not specific to c21 or to the dx route, and I can name where an identical one already exists on this machine. I am not taking a device window for the repro (that is pi-ogaload's area, as the triage above says) and I am making no claim about the cause.

    The same capture, one payload and two boots earlier

    journalctl -k -b -11 — boot 2026-11-02 09:30:56–11:58, engine before c21, amdxdna 0.18.0, module sha256 bd2ce883ab08…4e6ba7 (the module this box has loaded on every boot since 10-31), firmware amdnpu/17f0_11/npu_7.sbin (same as today):

    2026-11-02 09:48:51  aie2_legacy_tdr_detect: TDR timeout detected
                         aie2_tdr_work_func: Device isn't making progress
                         aie2_set_cmd_timeout: Context ID: 8   DPU PC: 0xffffffff  TXN OP ID: 0xffffffff  Context PC: 0x28b06005  Fatal error type: 0x0
                         aie2_set_cmd_timeout: Context ID: 6   DPU PC: 0xffffffff  TXN OP ID: 0xffffffff  Context PC: 0x28b060ad  Fatal error type: 0x0
    

    Context PC 0x28b060ad is byte-identical to the field in this issue's board capture (different context ID: 15 there, 6 here). Saved because journald will rotate it away and the 11-01 capture is already gone: ~/amd-oss/hrx-study/evidence/fabric/tdr-history/boot-m11-2026-11-02-0948.txt (56 lines, the whole amdxdna slice of that boot).

    Two further facts from that boot that a repro should be built to compare against:

    1. It fired twice, 46 s apart, with byte-identical captures — 09:48:51 and 09:49:37, same two context IDs, same two PCs, same DPU PC/TXN OP ID all-ones. The work function re-fired on contexts that had not moved. If the c21 repro shows one TDR and then silence, that is already a difference worth recording.
    2. The immediate trigger there was different from yours, and that is the important part. That window belonged to a load lane whose client was killed at its 3-minute max hold: first TDR at 09:48:51, 171 s into a 181 s run (client still holding the array), then exit 124 at 09:49:01, then the identical capture again at 09:49:37 from a work function re-firing after the client was gone. In this issue the server is alive throughout and the request only took 5.9 s. So one capture signature, two different triggers.

    What that does and does not license

    • Does: this defect is not introduced by the c21 payload, and the fix does not have to live in it. A repro on Ubuntu with c21 is still the right experiment (it is the shipping route), but if it reproduces it is reproducing something older than the payload.
    • Does not: DPU PC 0xffffffff / TXN OP ID 0xffffffff are all-ones, i.e. "no in-flight dispatch / no operation", not a stall site — the same sentinel value shows up in this driver's other "no address" message (aie2_send_host_buf_msgs: fw ctx 15 addr 0xffff...ffff, but on 11-01, different boot). The informative field is Context PC, and here it takes two values in one capture (0x28b06005, 0x28b060ad, 0xa8 apart) across two contexts, so "the same PC" is not a fingerprint of one code path. Record the whole capture, not just context 15.
    • I could not resolve what 0x28b06xxx is: it is not a kernel-module address (modules sit at 0xffffffffc0…) and the firmware ships stripped, so whether those two PCs are two stall points in the same routine is not answerable from this box.

    One method note for whoever takes the window

    The array FIFO is shared and other lanes submit while the TDR fires, so attribute the event by the npu-hold ledger, not by log proximity: grep -E '<HH:MM>' ~/NPU-QUEUE/.log gives the label and PID holding ~/NPU-TOKEN at that second. That is how the 11-02 pair above was pinned to a specific (already-exited) client, and it is also how a repro avoids blaming the wrong workload.

  4. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    From the MoE/NPU lane — no device window held, so the freeze costs nothing here, and one CPU-only addition: the route's own guards, and the two switches already in the build that would localise the TDR inside a single window.

    I hold no npu-hold ticket and no NPU process (never have in this lane: ~/NPU-QUEUE has no moe*/tmoe* entry, and the current /dev/accel holder is the p4-gate serve). So nothing of mine is competing with pi-ogaload for the array, and I will queue nothing until their repro lands.

    What the code already rules out, statically — so the repro does not spend a window on it

    Read from addons/npu-dx/src/dx_decoder.cpp and dx_route.cpp (private kernel repo, current tree). Both are host-side throws, not device hangs, so neither can produce a TDR — but both produce the same user-visible symptom (a stream that ends with no [DONE]), so the repro must be able to tell them apart or it will misread one as the other:

    guard file:line what it does
    prompt.size() + max_tokens > max_context() dx_route.cpp:35 refuses the request outright with dx: prompt + max_tokens exceeds the context (4096) — before any dispatch
    pos < 0 || pos >= max_context() dx_decoder.cpp:440 throws dx: position out of range mid-step
    max_context() dx_decoder.cpp:501 is MAXROWS = 4096 (dx_decoder.cpp:43), hard

    That corroborates the context precondition recorded above with its enforcement point: lemond auto-tuned ctx_size to 32768 (lemond.log:197) while the dx route refuses, and the decoder throws, at 4096. A long-prompt row must stay under 4096 including max_tokens, or it measures a refusal. In this capture it is not the cause of either symptom — the second request was short (history of new brunswick, and the page sends no history), so prompt + max_tokens ≈ 520 « 4096, and no throw path was reachable.

    Two switches that are already in the shipping build, and the A/B I would run first

    Neither needs a rebuild or a new ELF, so both fit inside one ticket:

    1. DX_PROFILE=1 (dx_decoder.cpp:442, documented in docs/npu-dx.md) prints per-step stage timings to stderr: ctx (450-451), runlist (462), S (476), then rl.execute() / rl.wait() (477-478), then layers (479), norm, head. So a hung request leaves a truncated profile line, and which stage is missing says where it died:

      • line ends at S with no layers → the hang is inside rl.execute()/rl.wait(), i.e. the device, and it is the dispatch wait, not the host prepare;
      • ctx missing/slow → the block-count/config path (below), not the array.
        This is the cheapest device-side localisation available for this issue: it costs an env var, not an ELF.
    2. DX_CTX_RESIDENT=0 vs the default (dx_decoder.cpp:240). Worth an arm because the sequence in this capture crosses the resident-context bookkeeping in a way the first request never does. The decoder keeps one hw_context for the whole lifetime and adds one no-PDI config per 32-token block count; a request at position p selects context(LayerElf::blocks(p + 1)) (dx_decoder.cpp:450). Request 1 walked block counts 1→~19 and left the context there; request 2 starts again at pos 0, so its first step switches back to block count 1, taking the nb == ctx_nb0 branch (dx_decoder.cpp:287) that swaps ctx_view back to the context's original runs. If the TDR is in that switch (control-code swap on a live context), the default reproduces and DX_CTX_RESIDENT=0 — which tears down and rebuilds a context per block count — changes the signature.

    Three predictions that make the A/B falsifiable rather than exploratory, if anyone wants them written down before the window:

    • if a second request after a completed one hangs while the same prompt as a first request does not, the resident/config path above is implicated and the third request should hang too;
    • if a short prompt hung cold (first request after load), the config path is not implicated and the profile truncation is the only signal that matters;
    • if the request that hangs is one whose prompt + max_tokens crosses 4096, it is the host refusal and not this issue at all.

    Not claimed: this is static reading, not a measurement. I am not naming a cause, and the resident path is not a c21 regression — it landed 2026-10-11 (12a01c365), and the identical Context PC 0x28b060ad capture was already firing on 11-02 pre-c21. I am also not taking a window for this; that stays pi-ogaload's, per the triage above.

  5. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    What this lane measured on Ubuntu with the c21 package before device work went on hold

    Two NPU runs (each a single npu-hold -l npufeat ticket, :18097 untouched, amdxdna errors 0 before and after, no TDR logged). Same route as the board's — the serve prints dx: kernel set serves up to 4096 cached tokens (128 attention blocks) and on the private route dx: dense Qwen3 on the dx kernels, from a copy of the c21 payload's own 1bit + npu/kernels/1024x3072x16x8.

    1. The first failure is the thinking budget, not the device — measured

    request (Qwen3-0.6B, dx route) result
    ~55-word prompt, max_tokens: 512, streamed, thinking on (what the page sends) 200, 512 events, 510 of them reasoning_content, content_chunks = 0 — the visible answer the page shows is empty because the whole budget went into <think>, and the page drops reasoning_content (that is the c18 item in ~/briefs/TOS3-C18-items.md, not an NPU fault)
    same prompt, chat_template_kwargs.enable_thinking: false 200, 512 content chunks, visible text, finish_reason: length

    So "the answer stops mid-sentence, far below 512" is the reasoning budget being spent, which is exactly the split #911 asks for: turn 1 is not evidence of an NPU fault. The gate's own row already dodges this with a /no_think prefix, which is why it never saw it.

    2. The second-turn failure and the TDR did not reproduce

    request result
    turn 2 = turn 1's prompt + its answer + a short question, streamed 200, 510 events (196 content / 312 reasoning), [DONE] present, no error
    the same pair with enable_thinking: false 200, both turns complete
    a short request, then 90 s idle (the board had exactly that gap, and the NPU's runtime autosuspend delay is 5 s), then another short request 200, 0.19 s — a stale-context hypothesis I had is therefore refuted, not merely untested

    Timeline read from the board's own logs on ryzen (~/tmp-ort/puppy-c17-hw/20261103T171805-9c0d20e9/, copied and read: lemond.log, dmesg.log, messages.log):

    • req 1 13:20:29.960 → 13:20:37.438 (7.48 s), req 2 13:22:07.359 → 13:22:13.289 (5.93 s) with Backend did not send [DONE] marker;
    • TDR at uptime 299.2 s = 13:23:04, i.e. ~51 s after req 2's stream ended, one TDR in the boot;
    • no segfault, no OOM, no kill in dmesg — the engine was alive, so req 2 threw or was cut, it did not crash.

    Two things I would try next, both cheap, and neither mine to run now:

    1. Whether the page or the proxy closed the stream. 1bit unified's SSE handler emits data: {"error":…} and then sink.done() on an exception — the only in-repo way to end that stream without [DONE]. If the demo's page (5.9 s, "0 chunks") closed first, the engine's next sink.write fails and the proxy logs the same line, which would make it a client timeout against a prefill that is one launch per token (~620 tokens of history is 8–14 s), not an engine fault. The engine's own stderr for that request would settle it; Lemonade's lemond.log does not carry the backend's body.
    2. A TDR needs a command the device never finishes. With dmesg's tdr_timeout_ms at its default the 51 s gap is consistent with the last submitted runlist hanging, but nothing in the two runs above made it hang, so the trigger is in the request shape the demo used (a longer prompt and/or a client that went away mid-generation), not in the route's plain two-turn sequence.

    The gate row #911 asks for: up as PR #922

    os/mini/release-check.sh gains chat-npu-followup: turn 1 in the page's shape (512 tokens), turn 2 replaying turn 1's own answer as history, and the kernel's aie2_legacy_tdr_detect count compared across the pair. It FAILs on an error body from either turn, a follow-up with no content and no reasoning, a reply with no finish_reason, or a TDR during the two turns; an unreadable dmesg is reported as unknown rather than clean. The decision function is pure and driven by --self-test (ctest release_check_row, CPU only, 7 new cases + a JSON-escaping case), and I ran the row end-to-end against a fake Lemonade both ways: PASS on a good pair, and FAIL … the follow-up answered an error on the board's shape. It has not run on hardware yet — device tickets are on hold — and the PR says so.

  6. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Step 1: reproduced on the c21 payload — the early stop is the page+thinking, and the TDR does not follow from the request sequence

    Ran the board's own payload on this box: ~/wt/release-rc/work/build/1bit (candidate 21, engine d04cbf1, private-route add-on linked) with its own kernel set ~/wt/release-rc/work/build/npu/kernels/1024x3072x16x8 — the same two paths the stick has under /opt/1bit-package/1bit, the same model dir (~/models/npu/Qwen3-0.6B, entry Qwen3-0.6B-NPU-1bit). Entry point is 1bit unified -m <dir>, i.e. the private dx route, not forward-serve (that one wants the engine's own full_i8_* ELFs and refuses this set by name — measured).

    Every run below is inside an npu-hold ticket, alone on /dev/accel/accel0, with the TDR count taken from dmesg before and after. Scripts: ~/ogaload/oga911/repro911{,b,c}.sh, logs beside them.

    The early stop is not the NPU, and it is not a stall: 367 of 501 chunks were reasoning

    arm request wall content chunks reasoning chunks [DONE]
    board sequence, thinking at its template default long prompt (~75 words) 7.9–8.6 s 134 367 yes
    " short follow-up 5.4–5.6 s 216 202 yes
    same, chat_template_kwargs.enable_thinking:false long prompt 3.3 s 177 0 yes
    " short follow-up 5.1–7.2 s 388 0 yes

    Content + reasoning = 501 of the 512-token budget on the first turn, and the answer text continues past the reasoning ("…maintain a balance that prevents the ocean from filling up completely with all salt over geological time."). So the route produced a complete answer; the page renders only delta.content (os/v3/puppy/embed/opt/1bit/webapp/index.html:147), and with a 512-token budget spent almost entirely on reasoning the visible answer looks truncated at exactly the board's 7.5 s. enable_thinking:false gets the same question answered in 3.3 s with zero reasoning chunks. Symptom 1 is the page's missing reasoning_content handling (pi-os3's item), not the array.

    The TDR did not reproduce in four arms that kept the board's request shape

    arm what varied result
    1 board sequence, back-to-back 4/4 requests 200 OK, 0 TDR, 0 amdxdna error
    2 90 s idle between the two requests (the board's real gap 13:20:37 → 13:22:07) 0 TDR
    3 client hangs up mid-stream (3 s in = mid-decode, 0.5 s in = mid-prefill), then a normal follow-up 0 TDR, follow-up complete
    4 SIGTERM the serve (what Lemonade's "Unload" does), start a new one, then the board sequence 0 TDR, 0 stale-context symptom

    Arm 4 is the one I expected to fire, because the board demo ran on a device whose previous serve had been evicted 88 s earlier ("Stopping /opt/1bit-package/1bit/1bit (PID 16670)", "waiting for GPU driver cleanup…"). It did not.

    What is still untested, and what I am doing next

    Two differences from the board remain, and both are about concurrency, not about the prompt: Lemonade runs a BackendWatchdog against the backend (lemond.log:206, streaming=on, non_streaming=on) — i.e. real chat requests on a timer, on a serve whose PrivateSession holds one device mutex for a whole generation — and the demo had the GPU busy (screen recording 1bit-demo-20261103-131935.mp4, plus an HRX backend load in the same Lemonade process at 13:19:00). If a queued request explains the "0 chunks in 5.9 s" without any device fault, that is the piece to test next; I will post the outcome with the same dmesg accounting, then the release-check row either way.

  7. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Release lane's half of this: the gate gap is now a row — PR #923 (chat-npu-multiturn).

    Two things from the board's own logs that matter for whoever root-causes the TDR:

    1. The router allocated 8x the context the dx kernel set says it serves. Both lines are from the same model load, 250 ms apart (/data/logs/20261103T171805-9c0d20e9/lemond.log):

      13:20:29.352 (Router) Auto-tune ctx_size resolved to 32768
      13:20:29.600 (Process) dx: kernel set serves up to 4096 cached tokens (128 attention blocks)
      

      The hang's TDR is in the same second as the second request ([299.216012] aie2_legacy_tdr_detect, ctx 15). Testing --ctx-size 4096 (or capping the auto-tune at what the kernel set reports) is the cheapest discriminator I can see.

    2. On this box, on Ubuntu, with the c21 build, the direct route answered both turns — 1bit serve -m ~/models/npu/Qwen3-0.6B --device npu under npu-hold: turn 1 (a ~70-word prompt, streamed, enable_thinking:false) produced 192 chunks and turn 2 (short, with the history) 15 chunks, no new aie2_legacy_tdr_detect. So the failure is not "any second request": the one difference I can name between this and the board is that the board went through lemond's router, which is the component that chose 32768 over 4096.

    Also recorded, so it is not re-derived: lemond appends [DONE] itself when the backend never sends one (WARNING: Backend did not send [DONE] marker, adding it), so a gate row that checks for [DONE] passes this bug. #923 counts content/reasoning deltas instead, and fails on a new TDR line even if chunks arrive.

  8. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    A negative result worth having, from the release lane, so nobody spends a hold on it twice: the board's exact page shape does not hang on this box through the c21 package's own lemond.

    Setup: the c21 release package unpacked (lemonade-onebit-rc-2026-11-03-c21), its lemond-onebit launcher, the NPU model registered the way os/v3's 05onboard-data does (user_models.json → Qwen3-0.6B-NPU-1bit, recipe_options.onebit_backend=npu, checkpoint ~/models/npu/Qwen3-0.6B), under an npu-hold ticket. The router chose the same value as the board:

    14:22:23.403 [Info] (Router) Auto-tune ctx_size resolved to 32768
    
    request (the page's own shape) result
    1: ~70-word prompt, thinking on, max_tokens 512, streamed 200, 6.7 s, 302 reasoning_content + 165 content deltas, finish_reason: stop
    2: short prompt, no history (the page sends none), max_tokens 512 200, 8.0 s, 203 reasoning + 216 content deltas, finish_reason: stop
    kernel log 0 new aie2_legacy_tdr_detect, no Backend did not send [DONE] in lemond's log

    And the other shape, for completeness: my new row's shape (long prompt then a follow-up carrying the history, thinking off) also passed through lemond — 192 + 15 chunks, 0 TDR.

    So three things are ruled out as sufficient on their own: a long prompt followed by a short one, lemond's ctx_size 32768 against a 4096 kernel set, and the no-history follow-up. I am not claiming the board bug is unreproducible — only that these are not the trigger by themselves, so the ctx mismatch in my previous comment is a suspect with a cheap test, not the answer.

    What is still different on the board, in the order I would test it:

    1. Device state at uptime 299 s on a fresh boot — the TDR fired on the first heavy NPU use after boot, on a device that had served the whole release check (chat, chat-npu, bench) minutes earlier. Here the device has been busy all day.
    2. The model was evicted and auto-loaded 0 s before the failing pair (Router) Evicting model 13:19:01 → Auto-loading 13:20:29, then the pair at 13:20:29 and 13:22:07). That evict→reload→serve sequence is not in my repro; I loaded once and served.
    3. ~90 s idle between the two turns (13:20:37 done, 13:22:07 POST). Both of my variants sent turn 2 within seconds.

    The gate row is PR #923 (chat-npu-multiturn), which goes through lemond and fails on 0 chunks on the second turn or on a new TDR line — so whichever of the three it turns out to be, the next candidate's gate reports it instead of passing it.

  9. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Correction to my comment above, and two facts now read off the page's own source and the recording

    The chat page sends no history. index.html posts messages: [{role: "user", content: text}] — the latest message only. So the demo's second turn was a short prompt alone after a long one, on the same device state, not a multi-turn request. My Ubuntu run's second turn replayed the first answer as history, which is a different (stricter) shape — so it was not a faithful reproduction of the board's second request. That is why the gate row in PR #922 now asks both: arm A a short prompt alone (the page's shape, the one that failed) and arm B with the history.

    The first turn's numbers, from the screen recording (~/Videos/1bit-demo/c17/1bit-demo-20261103-131935.mp4, frames at 1:03-1:08; the page prints its own counters): the turn ended with done: 81 chunks in 8.4 s (first token after 7.2 s). So the visible answer began after 7.2 s of <think> and then stopped mid-sentence at 8.4 s — i.e. ~430 reasoning + 81 content ≈ the 512 cap, exactly the truncation my Ubuntu run reproduced (512 events, 508-510 of them reasoning_content). The owner's "far below 512" is about the visible text; the budget was spent on reasoning, and the page drops reasoning_content.

    The page also has no client timeout — there is no AbortController/setTimeout in ask(); done: … is printed when the response reader ends. So done: 0 chunks in 5.9 s means the backend's stream itself ended at 5.9 s, and combined with Lemonade's Backend did not send [DONE] marker that is the engine's own abrupt end (its SSE path writes data: {"error":…} and sink.done() on an exception — the only in-repo way to end without [DONE]). The engine therefore threw or lost the connection ~5.9 s into the second request, and the one amdxdna TDR followed ~51 s later. It is not a page-side cancellation, which is what my earlier comment left open.

    Where that leaves the reproducer: a faithful one is long turn (max_tokens 512, thinking on, let it hit the cap) → a short prompt ALONE, on the same serve, with the engine's own stderr captured (DX_PROFILE=1 if you want per-step times) and dmesg checked for aie2_legacy_tdr_detect. My ~/lb/c17dx/{repro.py,run.sh} already has that shape as mode both-with-page-arm and abort/long for the two other candidates; on Ubuntu with the c21 package neither the page-shaped nor the history-shaped second turn hung (three npu-hold tickets, one at a time, amdxdna errors 0, no TDR). Happy to hand the harness over or to run it again as soon as the device hold lifts — the orchestrator has me off npu-hold until your repro lands.

  10. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Step 2: eight arms, 32 requests, the TDR does not reproduce — but the "0 chunks" half does, and it is our serve's queue

    Same payload, same kernels, same container, alone on the device, dmesg TDR/amdxdna-ERROR counted before and after every arm.

    # arm result
    1 board sequence, back-to-back 4/4 200 OK, TDR 0
    2 90 s idle between the two requests TDR 0
    3 client hangs up mid-stream (mid-decode 3 s, mid-prefill 0.5 s), then a follow-up TDR 0, follow-up complete
    4 SIGTERM serve → new serve → board sequence (Lemonade's evict/reload) TDR 0
    5 watchdog-shaped concurrency: non-streaming + streaming probes land mid-generation probe queued 10.04 s, then answered correctly (1BIT OK., 97 tok/s decode); TDR 0
    6 SIGKILL the serve mid-generation → new serve → board sequence TDR 0, no stale-context symptom
    7 three board sequences under a continuous VAAPI GPU encode (the demo's screen recording) 6/6 200 OK, TDR 0
    8 8 kill/load cycles (the demo started the route 4×) then the board pair on the 9th 32 requests 200 OK, TDR 0, amdxdna ERROR 0

    So: not the prompt, not thinking, not the idle gap, not the client going away, not eviction, not reload history, not GPU pressure, not concurrent probes. The capture is a device-level stall that this payload does not reproduce from the application side on this same hardware, which is consistent with the fabric lane's finding that the identical capture predates c21.

    What is reproducible, and it is the second symptom

    Arm 5 is the one that reproduces the board's user-visible half. Our NPU serve holds one device mutex for a whole generation (app/unified.cpp:182), so a second request — and Lemonade's BackendWatchdog sends real chat probes, streaming=on, non_streaming=on — gets zero bytes and no status until the first generation ends. Measured: dt=10.04s for a 48-token probe that then decoded in 51 ms. Lemonade's proxy gives up at ~6 s, which is exactly the board's "0 chunks in 5.9 s" + "Backend did not send [DONE] marker".

    That also says what the TDR looked like from outside: the app had nothing to show because the device was not making progress, and no layer in the stack could tell the difference between "queued" and "stuck".

    What I am fixing, in the two places this box can actually be fixed

    1. Engine: a bounded device wait with an honest 503 + Retry-After instead of an unbounded silent queue, so "busy" is reported in milliseconds and a stuck device can never look like a slow answer. (Today a stuck device poisons the mutex and every later request hangs with it — that is what makes the appliance need a reboot.)
    2. Release gate: the row the issue asks for — long prompt, then a short follow-up, on the NPU chat row — asserting both answer, that reasoning_content is counted (a thinking-only answer is then visible instead of silent), and that dmesg gains no TDR/amdxdna ERROR across the row. That last assertion is the one that would have caught this on the stick.

    The device-side stall itself (contexts with DPU PC 0xffffffff, Context PC in shim-DMA space) needs a bounded xrt::run::wait(timeout) in the private add-on so a stalled launch raises an error per request instead of hanging the serve; that is a second, named change and I will file it with the measurements rather than guess at it here.

  11. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Step 3: fixed, device-checked, and the gate row lands with it — PR #924 (bc53a76d)

    Fix, in the shipping route (app/unified.cpp). The device mutex is now a timed_mutex and the wait is bounded (--queue-ms, default 5000, i.e. just under the ~6 s the proxy above us allows). A request that cannot have the device gets 503 + Retry-After: 1 with {"type":"device_busy"}, and a streamed refusal still closes with [DONE] — a stream that ends without it is the thing Lemonade reports as a hung backend. --queue-ms 0 refuses at once; a negative value is refused rather than clamped.

    Same script, same container and kernels, on the device under npu-hold (~/ogaload/oga911/fix911.sh):

    before after (default 5000 ms) after (--queue-ms 0)
    probe sent mid-generation 200 after 10.04 s of silence, no status 503 in 5.01 s, Retry-After: 1 503 in 0.01 s
    the generation itself completed 200, 504 SSE lines, [DONE] 200, [DONE]
    follow-up once idle 200 200 200
    dmesg TDR / amdxdna ERROR 0 / 0 0 / 0 0 / 0

    So the state that produced "0 chunks in 5.9 s + backend did not send [DONE]" now produces an explicit busy status, and a genuinely stuck device can no longer hide behind a queued request.

    Gate row (os/mini/release-check.sh, chat-npu-turn). The board's shape — long prompt, then a short follow-up, both streamed, on the same NPU entry — was validated against bodies captured from the payload: it passes on the real answers (135 content / 368 reasoning, then 217 / 203), passes with enable_thinking:false (179 / 0, then 390 / 0), and fails on a reasoning-only follow-up and on an empty stream, which are the two shapes this issue found. It also fails on any new TDR timeout detected in dmesg across the row and says so when the kernel log is not readable, so a TDR during a release check is a red row instead of silence.

    What is still open on this issue, and it is not code in this PR: the TDR itself. Eight arms did not reproduce it (step 2), so what ships here makes it visible and attributable rather than impossible. The device-side change that would make a stall recover per request — a bounded xrt::run::wait(timeout) in the private add-on, so a launch that does not complete raises an error instead of poisoning the serve — is a change to the shipped binary rather than the engine, and I would rather do it with a reproducer in hand than blind. If the owner wants it, it is a small, named change and I can have it behind the same FIFO.

    Also not mine, from step 1: the page must render reasoning_content (or the route must default thinking off for the appliance) — 367 of the first answer's 501 chunks were reasoning and the page drops them, which is the "stops mid-sentence" half of the report.

  12. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Step 4: the watchdog premise, checked against the pinned Lemonade — it sends no chat probes, and its probe cannot hold the NPU

    I read the code the appliance actually runs, not a vendored copy: third_party/lemonade @ ef0f3b4, the LEMONADE_PIN the c21 builder asserts (build-candidate21.sh:36, :124).

    The watchdog has no chat probe in it. Its whole loop (src/cpp/server/wrapped_server.cpp:451-560) does three things: a child-process liveness check; a check of the in-flight request counters; and, only while a request is active and has shown no progress for LEMONADE_BACKEND_WATCHDOG_GRACE_SECONDS (default 90 s), an HttpClient::is_reachable(health_url, 2 s) — a GET at :531, nothing else, LEMONADE_BACKEND_WATCHDOG_POLL_SECONDS 5 s, reset after 3 consecutive failures. The board's log line (streaming=on, non_streaming=on) is not probe types: it is effective_policy.monitor_streaming_requests at :375, i.e. which in-flight requests it watches.

    Nor is there a hidden warm-up on this route. send_warmup() (backends/onebit/onebit_server.cpp:197) does POST a completion, but it is only reached for plan.kind == Direct (:301), the one-hop GGUF/llama.cpp path from --print-backend. The NPU model goes through 1bit serve → unified, which is the Process line in the board's own log, so no warm-up request exists for it.

    And the risk the item was aimed at cannot occur, measured: our /health handler is an atomic ready flag plus JSON, with no lock. With a 512-token generation in flight, six consecutive GET /health returned 200 in 0.3-1.0 ms, while a chat request in the same window was refused 503 at 5.01 s — the probe never queues behind the device, so the watchdog can never see a healthy-but-busy NPU as dead and reset it. (~/ogaload/oga911/health_probe.sh.)

    So I did not change Lemonade's watchdog: there is no NPU-holding probe to remove, and editing it would have been a change with no behaviour behind it. What I did instead is pin the invariant in the code it belongs to — the handler now carries the reason it must stay lock-free, with the numbers (app/unified.cpp, in #924 at c9fcb858) — because the failure it guards (a probe that waits on the device, watchdog resets a healthy turn) is exactly what a later "just add the lock here" edit would reintroduce.

    Note for pi-os3 (chat page)

    1. Retry on 503 with Retry-After. The NPU serve now answers a request it cannot admit with 503, Retry-After: 1, body {"error":{"message":"the NPU is busy with another request","type":"device_busy"}}. Lemonade does not retry that for you — there is no 503 handling in the request path of server.cpp/router.cpp (only load-path retries), so the status reaches the page. Retry that one status after the advertised delay (1 s, a couple of attempts is enough: the refusal only happens while another generation holds the device).
    2. Render reasoning_content, or ask for chat_template_kwargs.enable_thinking:false — the board's first answer was 367 reasoning chunks to 134 content ones, and dropping them is what made a complete answer look truncated at 7.5 s.
    3. #922's chat-npu-followup row is the gate; npu: Qwen3-0.6B dx route on the board: answer stops early, then a short follow-up gets 0 chunks and an amdxdna TDR (c17 stick, c21) #911 stays open until the cycle-18 board run shows chat-npu-turn PASS with 0 TDR.
  13. bong-water-water-bong commented on Nov 3, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Board evidence, cycle 19 stick (rc-2026-11-03-c19, candidate 22 package with #924 busy-503 and the page retry #926), 2026-11-03 ~19:55 AST, Secure Boot on, front USB-A:

    • 1bit-release-check: 20 checks, 0 failures, including the new chat-npu-followup row from os: the release check asks the NPU a second question after a 512-token turn (refs #911) #922. It runs a 512-token NPU turn, then a short prompt alone, which is the shape the page sends, then the same prompt with that turn as history. All three were answered.
    • chat-npu 95.4 tok/s, chat-hrx 304.4 tok/s.
    • dmesg: 0 tdr_detect, 0 amdxdna errors on this boot.
    • puppy-check.sh: 33 rows, 0 failed, 1 skipped (desktop rows on the headless entry, by design).

    The 0-chunk half is fixed: #924 plus #926. The TDR has not recurred: 0 in 32 requests on Ubuntu and 0 on this board run. It stays unexplained, so this issue stays open until the watchdog change lands (Lemonade's BackendWatchdog must not hold the NPU with real chat probes) and one more board run is clean.

  14. bong-water-water-bong commented on Nov 4, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Board pass 30: the exit condition in the 23:54Z comment names a change that cannot be made

    Not asking for another run — the measurements here are good and the two fixed halves are good. This is about the one
    sentence that decides when the row closes, because this issue is an A row on the BLOCKERS-FOR-C20 counter and an
    A row with an unsatisfiable exit condition means the counter cannot reach zero, whatever anyone ships.

    The 23:54Z comment ends: "it stays open until the watchdog change lands (Lemonade's BackendWatchdog must not hold the
    NPU with real chat probes) and one more board run is clean."
    The step-4 comment on this same issue (18:52Z) is the
    measurement that retired that premise, and I re-checked it against the pinned Lemonade rather than taking it on trust:

    third_party/lemonade @ ef0f3b490a27575e8c9986e6290cbccedf14ff75     (the engine's pin, and the LEMONADE_PIN the c21 builder asserts)
    
    src/cpp/server/wrapped_server.cpp:465   grace = LEMONADE_BACKEND_WATCHDOG_GRACE_SECONDS, default 90
    :505-509  active_backend_requests_ > 0 && (has_streaming && monitor_streaming_requests || has_non_streaming)
    :522-523  if (idle_for < grace) { continue; }            # nothing is sent while the request is making progress
    :531      HttpClient::is_reachable(health_url, probe_timeout, TrustedLoopback)     <-- a GET, the only probe
    :375      "(streaming=on, non_streaming=on)" is effective_policy.monitor_streaming_requests
    

    So there is no chat probe in the watchdog to remove: its one network call is a GET at :531, it is reached only after
    90 s of a stalled active request, and the (streaming=on, non_streaming=on) in the board's log is which in-flight
    requests it watches (:375), not a probe type. Step 4 measured the remaining risk directly — six GET /health returned
    200 in 0.3–1.0 ms while a 512-token generation held the device — so a healthy-but-busy NPU cannot be read as dead.

    Two exits exist; neither is that sentence:

    1. The device-side change this issue already names (step 3, 18:35Z: "What is still open on this issue"): a bounded
      xrt::run::wait(timeout) in the private add-on so a launch that never completes raises per request instead of
      poisoning the serve. That is a real, named change, it is in the shipped binary rather than the engine, and it is the
      only one of the two that makes the TDR recoverable instead of merely visible.
    2. Close on the c19 evidence, with the residual stated: 8 arms / 32 requests on Ubuntu with 0 tdr_detect and 0
      amdxdna errors, and the 11-03 ~19:55 AST board run with chat-npu-followup PASS, 20 checks 0 failures, 0
      tdr_detect on that boot. Honest limitation to write with it: absence on two boots is not a reproduction, so what
      closes is the "0 chunks" half plus the gate row, not a proof the TDR cannot recur.

    I am not closing it — the lane owns the row and item 1 is a decision about the private add-on. What I am recording is
    that item 1 is the only sentence on this issue that a change can satisfy; the watchdog line names a mechanism that the
    pinned code does not contain. Both exits are now in the board's OWNER section under #911.

  15. bong-water-water-bong commented on Nov 4, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Where this stands, and the one close condition that has no code behind it

    Measured tonight (device-free), because the close condition above names a code change:

    1. The pinned Lemonade has not moved: every candidate builder in ~/wt/release-rc (c15 … c22, the one the c19 board stick runs) pins LEMONADE_PIN=ef0f3b490a27575e8c9986e6290cbccedf14ff75. So the Step-4 analysis above is still the analysis of what the board executes — there is no newer pin that could have re-acquired a chat probe.
    2. In that pin the watchdog sends no chat completion: BackendWatchdog (src/cpp/server/wrapped_server.cpp) loops on child-process state and the in-flight counters, and only while a request is active and has shown no progress for LEMONADE_BACKEND_WATCHDOG_GRACE_SECONDS (90 s) issues HttpClient::is_reachable(health_url, …) at :531-532 — a GET /health. The (streaming=on, non_streaming=on) line in the board log is monitor_streaming_requests (:375), i.e. which requests it watches. send_warmup(), the only path that POSTs a completion, is reached only for plan.kind == Direct (the one-hop GGUF path), never for the NPU route.
    3. The risk that condition is protecting against is real but lives on our side, so it was measured and then pinned in code (npu serve: a request that cannot have the device is told so (engine#911) #924): our /health is an atomic flag plus JSON with no lock, and with a 512-token generation in flight six consecutive probes returned 200 in 0.3–1.0 ms while a chat request in the same window was refused 503 at 5.01 s. A probe that never queues behind the device cannot make the watchdog reset a healthy turn.

    So "the watchdog change lands" is not actionable as worded: making Lemonade's watchdog stop sending chat probes would mean changing code that does not send them. I have not touched third_party/lemonade — a change there would have had no behaviour behind it, and it would have re-pinned the appliance for nothing.

    What is met, from the board run above: 1bit-release-check 20/20 with the chat-npu-followup row (512-token turn, then a short prompt alone, then the same prompt with that turn as history) all answered; 0 tdr_detect, 0 amdxdna errors on that boot; 32/32 requests across eight adversarial arms on Ubuntu with 0 TDR.

    Close decision is the owner's / the orchestrator's — the TDR remains unexplained and is the reason to keep the issue. If the intended condition is something else (e.g. an appliance-side rule that a probe may never be sent while an NPU request is in flight, regardless of pin), say which tree and I will implement and measure it; per the pin that shipped on c19 there is nothing to remove.

  16. bong-water-water-bong commented on Nov 4, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Decoded: invalid call (code 614): state 8, run 0 of 28 is the driver's TDR, one fragment at a time

    From pi-npufeat, for the TC21 decode item (~/briefs/TC21-NPUCHAT.md item 2). No device run from me — every
    line below is read out of the runtime source, the driver source, and this boot's own persisted dmesg.log /
    lemond.log in ~/wt/c21-board-logs/20261104T123017-f675126f/. pi-release owns the payload repro; this is the
    half that needs no device.

    The three fragments

    fragment in the error where it comes from what it actually means
    invalid call (code 614) npu_rt_errors.h:100 runlist_failed = 614; the words "invalid call" are only the 6xx category text (:111, case 6) Not an invalid call. It is npu_rt.cpp:1085-1091: a runlist was executed and a chain's command packet did not end in ERT_CMD_STATE_COMPLETED. The misleading category is why this reads like API misuse.
    state 8 npu_rt.h:121 ERT_CMD_STATE_TIMEOUT = 8, read out of the chain packet at npu_rt.cpp:1085 The driver wrote 8 into that packet. Only one path does: aie2_set_cmd_timeout() → amdxdna_cmd_set_error(..., ERT_CMD_STATE_TIMEOUT, ...) (aie2_ctx.c:301, :343). So the TDR marked it, not the runtime.
    run 0 of 28 npu_rt.cpp:1089 bad = c * kChainMax + p[3] with kChainMax = 24 (:101) 28 = the runlist length = one token's worth of designs (Qwen3-0.6B num_hidden_layers is 28, one design per layer). 0 = chain 0's error_index, which the driver sets to the firmware's own run_list_id (fail_cmd_idx = report->run_list_id, aie2_ctx.c:328). The same boot prints that number as Timed out sub command ID: 0. So: layer 0's design, the first run of the first chain.

    Message format for completeness (raise_error, npu_rt.cpp:111-118):
    "npu runtime: " + category + " (code N)" + ": " + subject → exactly the string the page rendered.

    The timeline (the correlation is exact, not approximate)

    syslogd stamps every pre-userspace kernel line in messages.log with 12:30:17, which puts dmesg.log 51 s
    late. The mapping used here is boot = 12:29:26Z, and it is confirmed three ways: the capture itself reports
    uptime 51.39 s at date 12:30:17Z; bluetooth RFCOMM init at [287.33] ↔ markers: desktop-requested 12:34:12Z; and amdxdna_drm_close ... pid 30053 at [365.22] ↔ lemond Process terminated 08:35:31.429 (pid
    30053 is the serve lemond started at 08:34:32.933).

    wall clock (AST) event evidence
    08:31:01 NPU serve ready (ctx 4096), chat answers 27 tok @ 93.90 tok/s lemond.log
    08:31:25.09-.19 a load/ensure with onebit_backend=hrx for the NPU dir → engine exits 1 (×2) see "not the TDR" 1
    08:31:25.305 same model with onebit_backend=npu → ready in 588 ms; chat 47 tok @ 83.83 tok/s lemond.log
    08:31:28.725 evicted (release check unloads everything) lemond.log
    08:34:32.931 the page auto-loads the model, ctx auto-tuned to 32768 (vs 4096 in every release-check row) lemond.log
    08:34:33.543 → 08:34:37.371 POST 1, streaming, "completed - 200 OK" after 3.8 s — no TDR in that window lemond.log + dmesg
    08:34:45.559 POST 2, streaming lemond.log
    08:34:51.47 aie2_legacy_tdr_detect: TDR timeout detected; capture: Context ID 15, DPU PC 0xffffffff, TXN OP ID 0xffffffff, Context PC 0x28b060ad, fatal type 0, Timed out sub command ID: 0 dmesg [325.471]
    08:34:51.55 packet now state 8 / error_index 0 → runtime throws 614 → SSE error frame → stream closes; lemond logs Streaming completed - 200 OK dmesg + lemond
    08:35:31.1 shutdown; the TDR recovery's own restart fails (address 0xffffffffffffffff) see "not the TDR" 2

    Detection latency checks out: tdr_timeout_ms = 2000 (aie2_ctx.c:32) and the detector needs two consecutive
    intervals with jobs pending and no progress (aie2_tdr.c:36-56), i.e. 4–6 s — the TDR lands 6.0 s after POST 2
    began, which is what a stall on that request's first forward looks like. POST 1 finished inside 3.8 s, before any
    detection window could fire, so it did not hit this hang.

    Why it reached the browser as a 200 with the error text in it

    app/unified.cpp:270-276: the chunked provider is already writing data: frames by the time the decode throws, so
    the exception becomes data: {"error":{"message": ...}} followed by data: [DONE] (that [DONE] is the #924 fix —
    without it Lemonade calls the backend hung). The status cannot be anything but 200: the headers left before the
    first token was asked for. Lemonade parses the frame (that is why the page shows the engine's own wording) but
    its request log records Streaming completed - 200 OK — both failing requests read as success in lemond.log,
    and there is not one (Process) line between 08:34:33 and 08:34:52, i.e. the serve logs nothing server-side on
    that path. The SSE body the page rendered was the only persisted copy of the message.

    So a row that catches this class has to assert on the body, not the status: no "error" object in any frame,
    at least one non-empty delta.content/delta.reasoning_content, a terminal [DONE], and a usage frame with
    completion_tokens > 0 — after an explicit unload + reload at the page's own auto-tuned ctx (32768), thinking on,
    several hundred tokens. A status-code row cannot see it (hw_gate and the release check both pass a 200 error
    stream), which is exactly the "should be able to catch this class" ask.

    Two things in the same boot that are NOT the TDR

    1. 1bit serve failed to start ... llama-server failed to start ×2 at 08:31:25 — a backend-field mismatch, not a
    device problem.
    The two failed attempts were Ensuring model loaded: Qwen3-0.6B-NPU-1bit ctx_size=4096, onebit_backend=**hrx**; the child printed 1bit serve: an NPU model directory runs on --device npu
    (app/serve.cpp:2848) and exited 1, which Lemonade reports as "Missing required drivers or dependencies / Try
    running the server manually". The third attempt, onebit_backend=**npu**, was ready in 588 ms and answered at
    83.8 tok/s. So something on the board asked for the hrx backend on an NPU model directory (the persisted log
    does not name the client; nothing in os/mini/release-check.sh sends onebit_backend, so the sender is worth
    finding) — and the engine's refusal is by design, it just exits 1 with a message Lemonade cannot classify.

    2. The TDR recovery itself fails at teardown. [365.220]: aie_send_mgmt_msg_wait: command opcode 0x106 failed, status 0x4000003 → aie2_send_host_buf_msgs: fw ctx 15 addr 0xffffffffffffffff size 0x4000000 →
    aie2_hwctx_restart: Map host buf failed, ret -22 → amdxdna_pm_resume_get: Resume failed: -22 →
    amdxdna_drm_close: Resume failed (-22), pid 30053 restore data not reclaimed. aie2_hwctx_restart
    (aie2_ctx.c:135) maps amdxdna_obj_dma_addr(heap); 0xffff…ff is a heap BO with no DMA address, i.e. the
    DEV_HEAP was already released while recovery was still restarting that context. Driver-side (pi-hrx-fabric):
    recovery races client teardown, so a TDR does not actually leave the device recovered.

    What the capture says about the hang, and what it does not

    DPU PC and TXN OP ID both 0xffffffff with fatal type 0 = the firmware had a queued command for that context but
    no DPU instruction pointer and no transaction: the command was never started, while the context PC is valid.
    That plus "run 0" says the stall was on the first submission of that token, not midway through the layer chain.

    It does not say whether that is firmware, a stale queue/ring left by the two aborted hrx loads, or something
    the route did before submitting — this log cannot distinguish those. If the repro does reproduce, the two artefacts
    that would decide it are the serve's own stdout for the failing request (it is persisted nowhere today) and
    whether the first submission after a reload is always the one that hangs.

  17. bong-water-water-bong commented on Nov 4, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Second half of the decode: this is not environmental — the TDR never recovers, because the module c21 ships maps a heap BO that has no mapping

    Follow-up to the decode above, still no device run: the same dmesg.log plus the pinned driver source.

    Which driver those lines are from

    dmesg [47.294866] Initialized amdxdna_accel_driver **0.18.0**, and the tree the image pins is
    third_party/xdna-driver @ 526c6081 (.gitmodules + #971) — which is the exact tree checked out at
    ~/wt/xdna-7.4-rc1. So the aie2_ctx.c / aie2_tdr.c / aie2_message.c line numbers in the comment above are of
    the module the board actually ran, not of some other checkout.

    The recovery's failure is a BO-lifetime bug, and it is in the shipped module

    [365.220] aie2_send_host_buf_msgs: fw ctx 15 addr 0xffffffffffffffff size 0x4000000 →
    aie2_hwctx_restart: Map host buf failed, ret -22.

    • 0x106 in the preceding line is MSG_OP_MAP_HOST_BUFFER (aie2_msg_priv.h:29), so the failing step is the
      restart's map, not a destroy.
    • 0xffffffffffffffff is not garbage: AMDXDNA_INVALID_ADDR = ~0UL (include/uapi/drm/amdxdna_accel.h:22), and
      amdxdna_obj_dma_addr() (amdxdna_gem.h:114-123) returns mem.dma_addr or, when that is INVALID, uva —
      which is also INVALID once amdxdna_gem_obj_close() / the unmap path has run. So aie2_hwctx_restart
      (aie2_ctx.c:135,158) handed the firmware the address of a heap BO with no mapping left.
    • That is the same family as os/v3/puppy: the image builds amdxdna from pin 526c6081, which predates the bo_invalid_list fix, so the next stick ships the panicking module #971's bug (a BO used after its lifetime ended — there, freed while still linked on
      client->bo_invalid_list; the fix exists only as uncommitted changes in ~/wt/xdna-crash-fix and is not in the
      image
      ).

    The timing says the TDR lost a race it should not have to win

    wall clock (AST) event
    08:34:51.47 TDR detected, health captured, command marked TIMEOUT
    08:35:31.2 restart reaches MAP_HOST_BUFFER with an unmapped heap → -22 → pm_resume fails → restore data not reclaimed
    08:35:31.1-.4 lemond shutdown, Stopping /opt/1bit-package/1bit/1bit (PID 30053) → Process terminated

    So recovery spent ~40 s in aie2_hwctx_stop → aie2_destroy_context against a dead firmware (aie_send_mgmt_msg_wait
    has to time out) and arrived at the restart exactly as the page's model was being torn down. On the board, a TDR
    therefore does not leave the device recovered — it leaves it unusable for the rest of the boot, which is a strictly
    worse outcome than "one request failed".

    Re-cut or environmental (the item-5 ask): re-cut

    Not environmental, and not the page's ctx 32768 either — two defects sit in the module the image builds:

    1. A device hang on a forward after unload+reload (state 8, run 0), which still needs the repro to explain.
      One hypothesis the same evidence supports: DPU PC 0xffffffff and TXN OP ID 0xffffffff with a valid
      Context PC is what a submission looks like when the firmware holds a command whose BO mapping is gone — the
      same lifetime class as (2). If the hang disappears on a module with the BO-lifetime fix, it was that; if it
      persists, it is not.
    2. TDR recovery that maps an already-unmapped heap and so cannot recover the device.

    (2) alone justifies a re-cut: it converts any hang into a dead NPU until reboot, and #971 is the precondition —
    the image currently builds the module from a pin that predates exactly these BO-lifetime fixes.

    One consequence for the board row: since (1) may be intermittent, the evict+reload+long-thinking row must run a few
    times, and it must assert on the SSE body (see above) — neither the current chat-npu row nor hw_gate can see a
    200 that carries an error frame.

  18. bong-water-water-bong commented on Nov 4, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    Small addendum to "not the TDR" 1, so nobody chases a shipped defect that is not there: the board's own catalogue
    does not carry the wrong backend. The payload's bin/resources/server_models.json has

    Qwen3-0.6B-NPU-1bit   recipe onebit   recipe_options {"onebit_backend": "npu"}
    

    and nothing in the payload (os/mini/release-check.sh included, which never calls /api/v1/load) or in this repo's
    scripts sends onebit_backend at all. So the two onebit_backend=hrx attempts at 08:31:25 came from a client
    outside the ship
    — a hand curl /api/v1/load during the board boot is the shape the log shows (500, then unload,
    then the same model with npu, ready in 588 ms, one second before the release check's own row at 08:31:26). i.e. it
    is evidence the refusal works, not evidence of a board defect.

  19. bong-water-water-bong commented on Nov 4, 2026

    @bong-water-water-bong
    CollaboratorAuthor

    c21 board chat failure, decoded from the driver side (device-free: no ticket, the board's own captured logs)

    The orchestrator's c21 notes name this lane for "the driver side if it is the driver". Answer: the stall is not the
    driver, but the error text is the driver's own verdict, and two driver defects sit immediately behind it.
    Every number
    below is a timestamp join between the board's dmesg and lemond logs (~/wt/c21-board-logs/20261104T123017-f675126f/,
    preserved here as ~/amd-oss/hrx-study/evidence/fabric/tdr-history/c21-board-2026-11-04/ because the stick does not persist
    /var/log).

    The three client numbers, from source

    text meaning where
    code 614 errc::runlist_failed — "a run in the runlist ended in a non-completed state". The printed category word "invalid call" is the 6xx category label, not the failure — 614 is not a call made in the wrong state ~/wt/release-rc/work/npu-runtime/engine/npu/npu_rt/npu_rt_errors.h:100, category text :111
    state 8 ERT_CMD_STATE_TIMEOUT in XRT numbering (TIMEOUT=8, NORESPONSE=9; the enum names in the binary strings are ordered differently from the values, which is why this is easy to invert) src/npu/npu_rt_api.h:43, npu_rt.h:121
    run 0 of 28 index of the run that ended non-completed, printed from the chain packet npu_rt.cpp:1080-1092

    Who wrote state 8: the driver. aie2_tdr_recover_all() walks every hwctx → aie2_hwctx_stop() → the mailbox drain calls
    aie2_sched_resp_handler() with data == NULL → aie2_job_timeout_or_abort() → aie2_set_cmd_timeout() writes
    ERT_CMD_STATE_TIMEOUT into the cmd BO with fail_cmd_idx = report->run_list_id (aie2_ctx.c:365, :343). The two sides
    agree field for field: run 0 of 28 ↔ Timed out sub command ID: 0.

    Timeline (boot 08:29:30; all times AST, kernel monotonic in brackets)

    time who what
    08:31:01 app NPU model ready, check chat 27 tokens, ttft 1.36 s, 93.90 tok/s — the array was healthy on this boot
    08:31:02 lemond NPU model evicted (LRU), PID 13080 stopped; no amdxdna line for that close → clean evict
    08:34:32.9 app reload, PID 30053, ready in 563 ms (3 m 30 s after the evict)
    08:34:33.5→37.37 POST #1 stream closes 200 OK after 3.9 s — client-side, driver logged nothing
    08:34:45.6→51.55 POST #2 stream closes 200 OK after 5.99 s
    08:34:51.47 [325.471] driver aie2_legacy_tdr_detect: TDR timeout detected → Device isn't making progress → firmware capture
    08:35:31.13 [365.220] app+driver lemond "Stopping … (PID 30053)" at .128 and amdxdna_drm_close … pid 30053 at [365.220] — same 10 ms
    08:35:32 box shutdown

    So: healthy → evict → reload → first real generation after the reload stalls → watchdog catches it ~6 s later → the client's
    error is the driver's marking, 80 ms after it. Nothing invented client-side, and not a client timeout on that request.

    Cause, and the fingerprint across four events

    DPU PC 0xffffffff + TXN OP ID 0xffffffff + Timed out sub command ID: 0 + Fatal error type 0x0: the firmware never
    dispatched the sub command (no DPU PC, no transaction, no fatal exception). Across four captures on three kernel+module
    builds
    (11-01 12:26 ctx 15; 11-02 09:48:51 ctx 8+6; 11-02 09:49:37 the same pair re-firing; now c21 ctx 15,
    Context PC 0x28b060ad) there are only two distinct Context PC values, 0x28b06005 and 0x28b060ad, 0xa8 apart — i.e.
    the stall site is in the firmware's dispatch/wait loop, not in the model's tile program. That is the same conclusion as my
    11-02 comment, now with a fourth data point; record the whole capture, not the one field.

    Two real driver defects behind it (new; visible only because the board's log was captured before shutdown)

    1. Firmware restore data is leaked when a client closes after a TDR. amdxdna_drm_close() (amdxdna_drm.c:186-196)
      resumes by design so the following destroy releases the ctx's firmware restore data. After a TDR the resume cannot
      succeed and the driver warns and moves on: Map host buf failed, ret -22 → amdxdna_pm_resume_get: Resume failed: -22 →
      amdxdna_drm_close: Resume failed (-22), pid 30053 restore data not reclaimed. Documented non-fatal path
      (amdxdna_drm.c:180-186), but a leak on exactly the path the release hits.
    2. That restart sends an impossible address. aie2_hwctx_restart() maps hwctx->priv->heap through
      amdxdna_obj_dma_addr() (aie2_ctx.c:157-163), which under PASID is the client VA and is AMDXDNA_INVALID_ADDR once the
      address is gone: the request went out as aie2_send_host_buf_msgs: fw ctx 15 addr 0xffffffffffffffff size 0x4000000
      (MSG_OP_MAP_HOST_BUFFER = 0x106) and the firmware answered 0x4000003 (-EINVAL). The driver sends a message it can
      already tell is unaddressable instead of failing the restart locally with a diagnosis. Same 0xffffffffffffffff sentinel
      as the 11-01 event and as FACTS-libamdf.md §9 — one sentinel, three different messages.

    Afterwards the device reports device is already started ([365.221]) with a dead ctx 15.

    What this changes for the c21 verdict

    • Not the driver, for the stall: the board module is the same build as this box's (EBC78CDA… = our b45b9663…), i.e. it
      already carries the 5/5+6/6 crash fix — the 11-04 01:48 UAF panic is not this. Not libamdf: XDNA import class advertises FOREIGN_API dma-buf execution, but execution on an imported range fails EFAULT on amdxdna 526c608 (PASID) #812 either (no imported dma-buf in
      this path; 1bit is xrt::bo/userptr). Not c21-specific (same capture on 11-01/11-02). So the stall is firmware/command-stream.
    • But a chat after a TDR in the same boot cannot be made to work from the app side — the recovery leaves a dead context and
      the next load talks to already started. Only a fresh NPU context (driver reload, i.e. a reboot) clears it. Worth putting in
      the release verdict.
    • Cheapest isolating experiment (pi-release's item 1): fresh boot → single NPU model load → long thinking-on chat, no
      evict
      . The failure here needed an evict + reload 3.5 min later, and the first load on that boot ran at 93.9 tok/s. Pass
      without evict + fail with evict/reload ⇒ the reload/close path (defect 1 is a strong candidate for what the second process
      inherits) ⇒ code fix, not a re-cut. Fail without evict too ⇒ firmware stall, and the answer is on the firmware side.
    • One-line message fix, owner of that file is not me: errc_category() prints "invalid call" for every 6xx code and 614
      is not an invalid call — the release check should surface runlist_failed and the wrapped state, otherwise this class reads
      as a misuse bug in every report.

    No device touched for any of this: 0 tickets from this lane this boot, GPU never taken, :18097 untouched, no driver
    load/parameter, no PR, no merge.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingnpuThe NPU (XDNA2) forward/serve route

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions