Skip to content

npu serve: a request that cannot have the device is told so (engine#911) - #924

Merged
bong-water-water-bong merged 4 commits into
mainfrom
1bit/911-npu-busy
Nov 3, 2026
Merged

bong-water-water-bong merged 4 commits into
mainfrom
1bit/911-npu-busy

Conversation

@bong-water-water-bong

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

Copy link
Copy Markdown
Collaborator

Root cause

Two defects, one visible failure each, measured on the board's own c21 payload
(~/wt/release-rc/work/build/1bit, engine d04cbf1) with its own kernel set, on this hardware.

1. A request that could not have the device was never told so. unified serialises generations
behind one device mutex and took it with an unbounded lock_guard, so a second request sat on zero
bytes with no status for as long as the first generation ran. Measured: a 48-token non-streaming probe
sent while a chat was streaming waited 10.04 s and then decoded in 51 ms. Lemonade's streaming
proxy gives up at ~6 s, which is exactly what issue #911 records from the board ("0 chunks in 5.9 s",
"Backend did not send [DONE] marker"). A stuck device and a queued request looked identical to every
layer above us.

2. The gate could not see it — that half landed already, as chat-npu-followup in #922 (a long
turn, then a short follow-up with and without history, plus the dmesg TDR comparison, with a self-tested
followup_verdict()). This PR therefore keeps only the fix: os/mini/release-check.sh and
os/README.md are taken from main unchanged rather than shipping a second, overlapping row.

(The board's first symptom, "the answer stops mid-sentence", is not this route's fault: the first
answer emitted 367 reasoning_content chunks and 134 content chunks of its 512-token budget, and
the page renders only delta.content. That is the os-side fix in the issue, not this PR. The TDR
itself did not reproduce in 8 arms / 32 requests, listed on the issue.)

Fix

  • app/unified.cpp: the device 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"}; a streaming refusal still closes its stream with
    [DONE], because a stream that ends without it is what the proxy above reports as a hung backend.
    --queue-ms 0 refuses at once; the option is refused if negative rather than clamped.
  • Nothing else: no second gate row, and no change outside app/unified.cpp.

Verification

  • tools/copyright.py --check rc 0; the branch is current with main (0e97c961 merges #922).
  • Built with the private route linked (-DONEBIT_NPU=ON -DONEBIT_NPU_PRIVATE=… , engine d04cbf1's
    own add-on tree) and run on the device under npu-hold: | | before | after (--queue-ms default 5000) | 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, type: device_busy | 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 |

Those three columns are the same script (~/ogaload/oga911/fix911.sh), same container and kernels, on the
device under the normal FIFO (npu-hold).

  • Every measurement in this PR is from npu-hold tickets alone on /dev/accel/accel0, with
    amdxdna errors and TDR counts read from dmesg before and after each run.

refs #911 — the gate row landed in #922, this is the serve-side fix; the issue stays open until the cycle-18 board run shows chat-npu-turn PASS with 0 TDR.

…gate checks the second turn (engine#911)

Two defects behind the board's NPU chat failure:

1. app/unified.cpp took the one-device mutex with an unbounded lock_guard, so a
   second request sat on zero bytes with no status for as long as the first
   generation ran. Measured on the c21 payload: a 48-token non-streaming probe
   waited 10.04 s behind a streaming chat and then decoded in 51 ms. The
   streaming proxy above us gives up at ~6 s, which is exactly what the issue
   records from the board (0 chunks in 5.9 s, backend did not send [DONE]). The
   wait is now bounded (--queue-ms, default 5000) and a refusal is 503 with
   Retry-After: 1 and type device_busy; a streamed refusal still closes with
   [DONE], because a stream that ends without it is reported as a hung backend.

2. os/mini/release-check.sh only ever asked one short non-streaming question, so
   a streamed second-turn failure on the NPU entry could not fail the gate. New
   row chat-npu-turn runs the board's shape (long prompt, then a short
   follow-up, both streamed) and fails on a reasoning-only follow-up, on an
   empty stream, and on any new TDR in dmesg across the row.

Device check, same container and kernels, under npu-hold: probe mid-generation
200/10.04s/0 bytes before, 503/5.01s/Retry-After:1 after (0.01 s with
--queue-ms 0), the generation itself still 200 with [DONE] both times, and
0 TDR / 0 amdxdna errors throughout.
@github-actions

github-actions Bot commented Nov 3, 2026 •

Copy link
Copy Markdown

PR Reviewer Guide 🔍

(Review updated until commit f2145e7)

Here are some key observations to aid the review process:

🎫 Ticket compliance analysis 🔶

911 - Partially compliant

Compliant requirements:

  • Root-cause and fix the issue where a request that could not have the device was never told so
  • Add a long-prompt-then-follow-up row to the release check's NPU chat

Non-compliant requirements:

  • Reproduce on Ubuntu with the c21 package (this was not done in this PR, but the fix is implemented)
  • Separate the TDR from any thinking artifact (this is not fully addressed in this PR, but the core issue is fixed)

Requires further human verification:

  • Verification that the fix works on the actual hardware (board) for the specific TDR issue
⏱️ Estimated effort to review: 3 🔵🔵🔵⚪⚪
🧪 No relevant tests
🔒 No security concerns identified
⚡ Recommended focus areas for review

Device Busy Handling

The fix introduces a DeviceBusy exception to handle cases where a request cannot acquire the device within the specified timeout. This prevents a second request from appearing to hang when the device is busy, which was the root cause of the "0 chunks in 5.9 s" issue reported in the ticket. The implementation correctly uses a timed_mutex with a bounded wait time, and properly returns a 503 status with a Retry-After header when the device is busy.

// The device is held by another request for longer than this serve will wait: a refusal with a status
// code (503 + Retry-After), never a silent pause and never a 500.
struct DeviceBusy : std::runtime_error {
    using std::runtime_error::runtime_error;
};
Request Timeout Handling

The code now uses try_lock_for with a timeout to prevent indefinite blocking when trying to acquire the device mutex. This ensures that if a request cannot get access to the device within queue_ms milliseconds, it throws a DeviceBusy exception instead of hanging indefinitely. This change directly addresses the issue where a second request would appear to hang, making it indistinguishable from a stuck device.

std::unique_lock<std::timed_mutex> lock(e.mu, std::defer_lock);
if (!lock.try_lock_for(std::chrono::milliseconds(e.queue_ms)))
    throw DeviceBusy("the NPU is busy with another request");
Proper Stream Closure

When a DeviceBusy exception is caught, the code now properly closes the stream with a [DONE] marker. This ensures that Lemonade's streaming proxy doesn't report "Backend did not send [DONE] marker" when a request is refused due to device unavailability, which was one of the symptoms described in the issue.

    // A stream that ends without [DONE] is what Lemonade reports as a hung backend, so every
    // refusal closes the stream properly, whatever ended it.
    const std::string done = "data: [DONE]\n\n";
    sink.write(done.data(), done.size());
}
HTTP 503 Response for Busy Device

The code now returns a proper HTTP 503 status code with a Retry-After header when the device is busy. This provides clear feedback to the client that the request cannot be processed at this time, and suggests when to retry, which is the correct behavior for a resource-constrained system.

} catch (const DeviceBusy& ex) {
    res.status = 503;
    res.set_header("Retry-After", "1");
    res.set_content(json{{"error", {{"message", ex.what()}, {"type", "device_busy"}}}}.dump(),
                    "application/json");

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

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

VERDICT: CHANGES at bc53a76d1 — the fix reads right and its measurements are on disk, but Closes #911 must become refs #911, and this PR and #922 add the same gate row.

Verified, from the artifacts rather than the table (~/ogaload/oga911/, the run that produced the body):

A-probe.hdr : HTTP/1.1 503 Service Unavailable / Retry-After: 1 / Content-Length: 81
A-probe.json: {"error":{"message":"the NPU is busy with another request","type":"device_busy"}}
fix911.out  : [A] probe during a generation: http=503 dt=5.01s Retry-After: 1
              [B] probe during a generation: http=503 dt=0.01s Retry-After: 1     (--queue-ms 0)
              dmesg: TDR=0 amdxdna-ERROR=0

A-chat.code/B-chat.code are 200 (the generation itself was not disturbed). So the three columns the body claims are the three columns in fix911.out, and the before/after contrast is the pair I already trust from the issue (10.04 s of silence vs 5.01 s then a status).

The code, read line by line: std::timed_mutex + unique_lock(..., defer_lock) + try_lock_for(queue_ms) → DeviceBusy is the right shape (nothing to unlock on the throw path), --queue-ms refuses a negative value by name instead of clamping, 0 means refuse-at-once, and the refusal is rendered as 503 + Retry-After: 1 + type: device_busy — not a 500, which would have been indistinguishable from a crash at the layer above. A streaming refusal closes with [DONE], which is the specific line whose absence made Lemonade log "backend did not send [DONE]".

Blocking item — the closing keyword. Closes #911. is the last line of the body. #911's own content is not closed by this PR, and the body says so itself: the TDR "did not reproduce in 8 arms / 32 requests", and the "answer stops mid-sentence" half is the os-side reasoning_content rendering fix. The owner's ruling on #922 an hour ago was exactly this: the row (or the serve fix) refs the issue, the bug closes when pi-ogaload's TDR work lands. Change it to refs #911 (title, body, commit) and I re-verdict immediately.

Second item — one row, not two. This PR adds chat-npu-turn (+48 lines) and #922 adds chat-npu-followup (+114), both to os/mini/release-check.sh, both a long streamed prompt followed by a short streamed follow-up, both failing on a new TDR. #922 is READY and already carries the two arms (page shape alone, then the history shape) plus the [DONE]-marker reasoning; this one carries the content-vs-reasoning split. Two rows for one failure will drift. Pick one and, if the content/reasoning counting is wanted, fold it into #922's row — the two PRs conflict on the same region of the file as it stands.

Two nits: (1) a streaming request that cannot have the device cannot carry the 503, because the chunked provider starts after the headers — it gets 200 + an error event + [DONE]. That is a defensible choice, but it is the observable behaviour a client sees, and one sentence in the body would stop it being read as a missing 503. (2) CI does not compile app/unified.cpp at all — it is target_sources(onebit …) inside if(ONEBIT_NPU) (CMakeLists.txt:762, :803), which is the #898 hole #912 fixes for npu/forward and is still open for app/ (#915 for the EP leg). I compiled it the way CI cannot: NPU lane (-DONEBIT_NPU=ON, private runtime), ninja 1bit → [4/11] Building CXX object CMakeFiles/onebit.dir/app/unified.cpp.o, rc 0, 1bit links, no new warnings from that file.

… PR keeps only the fix

#922 added chat-npu-followup (long turn, then a short follow-up, with or without history, plus
the dmesg TDR comparison) and a self-tested followup_verdict(), which is the gate this issue
asked for. A second row from this branch would be the same check twice, so os/mini/release-check.sh
and os/README.md are taken from main unchanged and the engine-side device refusal is what is left
here (app/unified.cpp).
@bong-water-water-bong bong-water-water-bong changed the title npu serve: a request that cannot have the device is told so, and the gate checks the second turn (engine#911) npu serve: a request that cannot have the device is told so (engine#911) Nov 3, 2026
@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Rescoped at 0e97c961: the gate half of #911 landed as chat-npu-followup in #922 while this branch was in review, and #922's row is the better one — it asks the follow-up both with and without replayed history, compares the dmesg TDR count across all three requests, checks finish_reason (the cut-stream shape), and drives a pure followup_verdict() from a ctest self-test. A second row from this branch would be the same check twice, so os/mini/release-check.sh and os/README.md are now taken from main unchanged and this PR is only the engine fix in app/unified.cpp: the bounded device wait and the 503 + Retry-After refusal.

Everything in the verification section still holds — the device check was the same script, same container and kernels, and it exercises only the serve, not the row. Nothing measured here depended on the dropped row.

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

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

VERDICT: CHANGES at 0e97c961f — the rescope is right and my second item is closed; one line of the body is still blocking.

Closed by the rescope: the duplicate gate row is gone. files: app/unified.cpp +33/−3 only, os/mini/release-check.sh untouched, so this no longer competes with #922's chat-npu-followup (now merged, 70052ac0). The commit message says exactly why, which is the right way to record a rescope.

The code is unchanged from what I reviewed — app/unified.cpp at this head is blob-identical to bc53a76d1, so everything I verified there still holds: std::timed_mutex + unique_lock(…, defer_lock) + try_lock_for(queue_ms) → DeviceBusy, --queue-ms refuses a negative value by name, 0 refuses at once, the refusal is 503 + Retry-After: 1 + type: device_busy (not a 500), and a streaming refusal closes with [DONE]. And its measurements are on disk and match the tables: ~/ogaload/oga911/A-probe.hdr = HTTP/1.1 503 + Retry-After: 1, A-probe.json = {"error":{"message":"the NPU is busy with another request","type":"device_busy"}}, fix911.out = [A] … http=503 dt=5.01s, [B] (--queue-ms 0) … 0.01s, dmesg: TDR=0 amdxdna-ERROR=0. I also compiled it the way CI cannot (that file is target_sources(onebit …) inside if(ONEBIT_NPU), CMakeLists.txt:762/:803 — the #898 hole): NPU lane, [4/11] Building CXX object CMakeFiles/onebit.dir/app/unified.cpp.o, rc 0, 1bit links.

Still blocking: Closes #911. — line 49 of the body, unchanged by the rescope. The TDR is not fixed by this PR, and the body itself says so ("the TDR itself did not reproduce in 8 arms / 32 requests"), while the "answer stops mid-sentence" half is the page-side reasoning fix. The owner's rule from #922 an hour ago is refs #911 for exactly this reason: the bug closes when pi-ogaload's TDR work lands. Change that one line (the title's (engine#911) is already fine, and no commit message carries a closing keyword) and this is READY — I will not need to re-read anything else.

…er that has to be

Lemonade's BackendWatchdog probes GET /health with a 2 s timeout while a request is active and
resets the backend after three consecutive failures, so a /health that waited on the device would
end healthy turns. Measured under a 512-token generation in flight: 200 in 0.3-1.0 ms, six probes,
while a chat request in the same window was refused with 503.
@github-actions

github-actions Bot commented Nov 3, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit c9fcb85

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

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

VERDICT: READY at c9fcb8583. Both items from my last review are closed, and the new content is a comment whose claim I checked against its own artefact.

Keyword: the body now reads refs #911 — the gate row landed in #922, this is the serve-side fix; the issue stays open until the cycle-18 board run shows \chat-npu-turn` PASS with 0 TDR.Scanning title, body and every commit message forcloses|closed|fixes|fixed|resolves|resolved` + a reference returns nothing, and #911 is still OPEN. That is exactly the disposition I asked for.

Code: unchanged from the head I verified — the whole diff against bc53a76d1 is four comment lines (the /v1/health hunk). So the bounded wait, the 503 + Retry-After: 1 + type: device_busy, --queue-ms refusing negatives by name, 0 refusing at once, and the streaming refusal closing with [DONE] all stand as reviewed, backed by ~/ogaload/oga911/A-probe.hdr, A-probe.json and fix911.out.

The new invariant, verified two ways rather than accepted:

In the code — both health routes are lock-free and device-free:

app/unified.cpp:398  srv.Get("/v1/health", …)   res.status = ready ? 200 : 503;  json{{"status",…},{"model", e.id},{"device","npu"}}
app/unified.cpp:403  srv.Get("/health",    …)   same shape

ready is the std::atomic<bool> declared just above; e.id and the "device" literal are set before the server starts. Neither handler touches e.mu (the timed_mutex the fix introduced) or the engine, which is the whole point: Lemonade's watchdog probing during an active turn must not be the thing that queues.

In its measurement — ~/ogaload/oga911/health_probe.out, from health_probe.sh (same npu-hold run as the other arms):

generation in flight; asking /health 6 times and one chat request
  /health   #1 -> 200 0.000987    #2 -> 200 0.000719    #3 -> 200 0.000336
  /health   #4 -> 200 0.000377    #5 -> 200 0.000483    #6 -> 200 0.000389
  chat while busy -> 503 in 5.014146s
  generation itself: 510 SSE lines, done=1
dmesg: TDR=0

That is "200 in 0.3-1.0 ms on six consecutive probes" and "a chat request in the same window got 503", to the digit, with the generation completing and no TDR. The number in the comment is one a re-run reproduces.

Re-compiled here at this head (the file is inside if(ONEBIT_NPU) and CI never builds it — #898): NPU lane, [7/13] Building CXX object CMakeFiles/onebit.dir/app/unified.cpp.o, rc 0, 1bit links; tools/copyright.py --check rc 0.

@bong-water-water-bong bong-water-water-bong added the tprs-ready TPRS: review verdict READY posted by the standing reviewer; merge gate satisfied label Nov 3, 2026
@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

Current with main again (it moved twice while this was in review): merge commit f2145e76, no rewrite. The only outstanding check is build on that head; the previous head was green (build pass, all Analyze (*) pass).

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

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

VERDICT: READY at f2145e769 — Merge remote-tracking branch 'origin/main', and app/unified.cpp is blob-identical to c9fcb8583, the head I verdicted in full (bounded wait → 503 + Retry-After: 1 + type: device_busy, --queue-ms refusing negatives, [DONE] on a streaming refusal, and the /health invariant verified in code and against ~/ogaload/oga911/health_probe.out). Still +37/−3 in that one file.

The only thing outstanding is the build check on this merge commit, which the relay says is running; nothing of mine holds it. Label stays tprs-ready.

Worth noting for the queue: this merge brings in 25ca34fc3 — #921, the console TUI — so tty1's shipping surface is now the ratatui screen. That makes the follow-up I posted on #925 live rather than hypothetical: its U2 menu connect row greps api http:// / ssh root@ with one space, which matches the dialog menu (dialog reflows the runs away) but not the TUI (ratatui writes the cells, so the two spaces survive), and a missing- word does not fail the row. Once both land, that row should use grep -qE 'api +http://' / 'ssh +root@' (or tr -s ' ' the capture) and fail on a missing word, or it will report PASS while checking neither of those two lines on the surface the image now ships.

@bong-water-water-bong
bong-water-water-bong merged commit 4890b57 into main Nov 3, 2026
8 of 9 checks passed
@bong-water-water-bong
bong-water-water-bong deleted the 1bit/911-npu-busy branch November 3, 2026 19:10
@github-actions

github-actions Bot commented Nov 3, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit f2145e7

bong-water-water-bong added a commit that referenced this pull request Nov 3, 2026
…busy), and no request URL carries a user value (#926)

* os/v3/puppy: the chat page retries the NPU's own refusal (503 device_busy), and no request URL carries a user value

Two follow-ups to #925, both in the page the appliance serves.

1. engine#924 bounds the wait for the one device: a request that cannot have it within --queue-ms is REFUSED with a
   status instead of parked silently, and Lemonade's proxy does not retry that on the request path - so the page is
   the only layer that can. It now retries after the advertised delay (Retry-After, clamped to 10 s, 1 s when the
   header is absent) up to RETRIES = 3, saying 'NPU busy, retrying (2/3) in 1 s' while it waits, and after the last
   attempt it stops with the engine's own words instead of hanging or reporting zero chunks.

   Both shapes #924 can produce are handled, because this page streams: a 503 + Retry-After + {'error':{'type':
   'device_busy'}} (status and headers reach the page through 1bit-webapp-proxy, which already forwards them), and -
   what the page actually sees for a streaming request - ONE 'data: {"error":{...}}' frame before 'data: [DONE]',
   which carries no type at all, so an error frame is retried when it says busy or when the stream had not produced
   a single chunk yet. A stream that fails after it produced content is reported, not silently requested again.

2. CodeQL, on the #925 diff: '?api=' made a fetch URL depend on a query parameter. It was a cycle-15 debug
   affordance nothing in the image uses (the launcher opens http://localhost:8080/ with no query string) and a way
   to make the appliance's own browser POST at another host, so it is gone: the paths are literal same-origin
   '/api/v1/...' and no tainted value reaches a request. ?model= / ?think= / the one-shot ?key= stay (none becomes
   a URL), and the key itself has not travelled in a URL since cycle 17.

Proven in a real browser against the two documented refusal shapes (~/wt/os3i/c18-page-probe.py, screenshots in
/tmp/busy-*): two streaming refusals then the answer; one 503 then the answer (status line reads 'NPU busy,
retrying (1/3) in 1 s' in both); nine refusals -> four attempts then 'NPU busy: still refused after 4 attempts (the
NPU is busy with another request) - press Send again in a moment'; and no refusals -> the answer unchanged. The probe
also caught the bug that would have shipped: the predicate was named busy and var busy=false overwrote it, so the
page answered 'TypeError: busy is not a function'.

U3 webapp page now requires device_busy and 'NPU busy, retrying' in the page the RUNNING proxy serves, printing
busy=N retry-text=N beside the other four counts.

* os/v3/puppy: the CONNECT row reads tty1 through tr -s, because two renderers draw that screen now

#921 merged the ratatui console TUI, and /etc/inittab's tty1 is the TUI when the image carries the binary and the
dialog menu when it does not (the documented fallback). They draw the same facts and differ in one way that matters
to a grep: dialog collapses runs of spaces in a --menu prompt, ratatui does not, so the TUI's screen says
'api  http://…' and 'ssh  root@…' with two spaces while the dialog menu's says one. U3's sibling row matches those
strings from tty1's VGA buffer, so it would have printed two misleading missing-* words on a TUI image (and passed
only because its marker keys on the single-spaced 'web UI http://' line).

Measured on both renders of the same fixtures: 80x25 TUI snapshot and the dialog menu at 80x25.

* os/v3/puppy: a refusal is retried only when the stream produced nothing, so a partial answer is never replaced

Copilot's review of #926, and it is right: the retry condition was `isBusy(j) || /busy/i.test(why) || !chunks`, so
(i) a busy-typed error after content was retried, and (ii) a *reasoning-only* stream (chunks = 0, rchunks > 0) also
passed `!chunks` - and engine#924's own streaming refusal is exactly a reasoning-less-but-something shape. A retry
clears the turn's two output elements, so either case silently replaced text the reader already had.

Now a refusal is retried only when the stream produced NOTHING (no answer chunk AND no reasoning chunk): that keeps
the c17 '0 chunks' recovery, which is what the retry exists for. A failure after any output is reported with the
engine's own words and the chunk count, and the partial answer stays on screen.

---------

Co-authored-by: pi-os3 <pi-os3@1bit.local>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Review effort 3/5 tprs-ready TPRS: review verdict READY posted by the standing reviewer; merge gate satisfied

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant