fix(skippy): never block status reads on the inference lock - #1129
Conversation
RuntimeState is held for the entire duration of a decode loop:
{ let mut rt = runtime.lock(); for _ in 0..max_new_tokens { rt.decode() } }
SkippyRuntimeHandle::status() locked that same mutex purely to read
session_stats(), so every status/readiness/dashboard read queued behind
the in-flight turn. On a large model with a long prompt that is tens of
seconds. Worse, the dashboard context-usage tick calls it from an async
task every 250ms, so a blocking acquire also parks a tokio worker for the
length of a generation.
Measured on a gemma-4-E4B node with a randomized ~30k-token prompt
(cache-miss, ~25s prefill), probing throughout:
before after
/v1/models 3009ms timeout 0.5-9ms 200
/api/status 3002ms timeout 2.4-3.4ms 200
Inference is unaffected (same prefill duration, same token counts, replies
still correct); status payloads stay accurate mid-turn (inflight=1, correct
hosted model).
Session stats are advisory, so serve them without ever waiting: take the
runtime lock only when it is free — refreshing a cached snapshot when we
get it — and otherwise return the last published value. Extracted as
read_without_blocking() so the behaviour is unit-testable.
Waiting for a turn to finish is correct backpressure for another inference
request. It is not correct for an observability read that needs no GPU and
touches no inference state.
Refs #1126
📝 WalkthroughWalkthrough
ChangesRuntime statistics caching
Estimated code review effort: 3 (Moderate) | ~25 minutes Possibly related PRs
Suggested reviewers: Sequence Diagram(s)sequenceDiagram
participant Status as status
participant Handle as SkippyRuntimeHandle
participant Runtime as RuntimeState
participant Model as SkippyModelStatus
participant Local as llama_slots_snapshot
Status->>Handle: request session statistics
Handle->>Runtime: attempt non-blocking lock
Runtime-->>Handle: live statistics or lock contention
Handle-->>Status: statistics and capture timestamp
Status->>Model: populate sessions_captured_at_unix_nanos
Model->>Local: provide session capture timestamp
Local-->>Model: last_success_unix_ms
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
There was a problem hiding this comment.
🧹 Nitpick comments (1)
crates/skippy-server/src/embedded.rs (1)
432-433: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winCorrect the fallback contract in this doc comment.
Lines 432-433 state that
V::default()is returned only when the cache is poisoned. Both constructors initialize the cache withRuntimeSessionStats::default(). Ifsourceis contended before a successful refresh, Lines 447-450 return that default cached snapshot. The test at Lines 496-503 confirms this behavior.State that contention before the first refresh returns the initialized default snapshot. Describe cache poisoning as a separate fallback condition.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@crates/skippy-server/src/embedded.rs` around lines 432 - 433, Update the documentation comment for the cache read method near the `source` contention handling to state that contention before the first refresh returns the initialized default snapshot; describe cache poisoning as a separate fallback condition rather than implying it is required for `V::default()`.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Nitpick comments:
In `@crates/skippy-server/src/embedded.rs`:
- Around line 432-433: Update the documentation comment for the cache read
method near the `source` contention handling to state that contention before the
first refresh returns the initialized default snapshot; describe cache poisoning
as a separate fallback condition rather than implying it is required for
`V::default()`.
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro Plus
Run ID: aa07b8f8-e177-48a5-9fc1-187b5afe8e67
📒 Files selected for processing (1)
crates/skippy-server/src/embedded.rs
|
This pull request is currently a draft. Reviews will not take place until the PR is marked as ready for review. |
Review follow-ups on the non-blocking status read: - Poisoning: `Err(_)` conflated `WouldBlock` with `Poisoned`, so a poisoned runtime would have reported a healthy node with cached stats while inference was failing. Match `TryLockError` explicitly and keep panicking on `Poisoned`, exactly as the previous `lock().expect(..)` did. - First read: the cache started at `default()`, so a read that lost the race to the very first generation published zero lanes and zero usage for that whole turn. Prime it during construction while the runtime is still unshared and uncontended, and drop the now-unneeded `Default` bound. - Docs: the helper claimed staleness was bounded to one turn and that it never blocks. Neither is true — under sustained load an opportunistic read can lose indefinitely, and the fallback does take the (uncontended) cache lock. Say so, and state plainly that nothing may gate a decision on these stats. Re-measured after the changes: /v1/models 0.6-7.6ms, /api/status 2.5-3.2ms during a ~25s prefill; startup unaffected by priming.
The existing tests exercised `read_without_blocking` generically over a `Mutex<u32>`. Nothing asserted that `status()` actually calls it, so reverting `status()` to the old blocking `lock()` left all three tests passing and the regression fully reintroduced. Add three tests over a real `SkippyRuntimeHandle`: - `status()` returns while the runtime lock is held (the regression); - construction primes the stats cache, so a read that never wins the lock reports real lanes rather than zeros; - an idle runtime is still read live. The contended probe runs on a detached thread and asserts via `recv_timeout`. It deliberately does not join: a blocking regression never returns, so joining would hang the suite instead of failing it. `session_stats()` is pure Rust over lane bookkeeping, so this needs no GGUF — `RuntimeState::new_modelless_for_test` builds one over `StageModel::new_dummy()`, which drops safely on a null handle. Handle assembly moves into `SkippyRuntimeHandle::ready`, shared by both loaders, so priming lives in one place and the tests cover the real construction path rather than a copy of it. Mutation-checked, both failing fast rather than hanging: - `status()` back to a blocking `lock()` -> contention test fails on timeout in 5.01s; - priming back to `default()` -> priming test fails on lane_count 0. cargo test -p skippy-server: 334 passed / 0 failed; fmt and clippy clean.
Status reads take the inference lock opportunistically and fall back to a cached snapshot, so `EmbeddedRuntimeStatus.sessions` can be frozen while the runtime is busy inside a native call. Nothing recorded when that snapshot was taken, and `llama_slots_snapshot` stamped every tick with `last_success_unix_ms: now`. A node wedged in native code therefore published "Ready", "0/N slots busy" and a success timestamp one second old, refreshed every 250ms, forever. The dashboard only flags staleness when attempt > success, so it could never fire. That is the exact signal needed to diagnose the stall this branch fixes. Carry the capture time with the cached value and propagate it, so a wedged runtime shows a success time that stops advancing. - `EmbeddedRuntimeStatus.sessions_captured_at_unix_nanos` (new field) - `SkippyModelStatus.sessions_captured_at_unix_nanos` - `llama_slots_snapshot` reports it instead of `now` Mutation-checked: stamping `now()` on the cached branch fails both `read_without_blocking_serves_cache_instead_of_waiting_on_inference` and `status_does_not_claim_a_fresh_capture_while_the_runtime_is_busy`. skippy-server 335 passed; mesh-llm-host-runtime 1853 passed; fmt and clippy clean on both.
Fixes #1126.
Status and readiness reads no longer stall while a model is busy. Previously, hitting
/api/statusor/v1/modelson a node that was mid-prefill would hang for tens of seconds; now both answer in milliseconds regardless of what inference is doing. The dashboard stays responsive during long turns, and — because the blocking acquire was happening on async executor threads — the node stops parking tokio workers for the length of a generation.Problem
SkippyRuntimeHandle::status()lockedMutex<RuntimeState>purely to readsession_stats(). That is the inference lock, and a single native call holds it for as long as that call runs — a large model with a long prompt can sit inside one prefill for ~25s.The dashboard context-usage tick (
DASHBOARD_CONTEXT_USAGE_REFRESH_INTERVAL, 250ms) reachesstatus()viarefresh_dashboard_context_usage → ctx_used_tokens, from inside atokio::select!loop. So this was a synchronous blocking acquire on an async executor thread.Caught live in a stack sample during a stall:
Waiting on that lock is correct backpressure for another inference request. It is not correct for an observability read that needs no GPU and touches no inference state.
Fix
Session stats are advisory, so read them without ever waiting: take the runtime lock only when it is free — refreshing a cached snapshot when we get it — and otherwise serve the last published value. Extracted as
read_without_blocking()so the behaviour is unit-testable independently of a loaded model.Because a cached read can be arbitrarily stale, the snapshot carries the time it was actually taken, and callers propagate that instead of stamping it as freshly observed. Without this, a runtime wedged inside a native call would publish
Ready,0/N slots busyand a one-second-old success timestamp every 250ms, forever — the dashboard only flags staleness whenattempt > success, so it could never fire. That is precisely the signal needed to diagnose the stall this PR fixes, so getting it wrong would have traded a slow control plane for a lying one.No API removals, no behaviour change for inference.
Scope: which lock sites change
I audited every
runtime.lock()site inskippy-server.status()was the only observability reader; the rest are inference or session lifecycle, where waiting is correct and must stay:frontend/decode_batcher.rs:192run_batchfrontend/embedded_execution.rs:83frontend/generation_flow.rs:402,1023generate_multimodal_text,generate_split_multimodal_textbinary_transport/.../prefill_recording.rs:97record_full_prefill_with_activationsbinary_transport/.../connection.rs:223,301,359handle_binary_connectionfrontend/local_generation.rs:1021cleanup_local_generation_sessionfrontend/prefix_cache.rs:1175drop_embedded_split_restorefrontend/embedded_generation/lifecycle.rs:387drop_embedded_runtime_sessionhttp.rs:326,360,383,422,444,463,470,599message,text_entrypoint,maybe_lookup_prefillservepath)Note on the last row: the
http.rshandlers do hold the runtime lock across a wholefor _ in 0..max_new_tokensdecode loop (http.rs:462), and they do it inside async Axum handlers. That is the same bug class on a different surface. It is not fixed here because that surface is the legacyskippy-server servesubcommand, which the shippedmesh-llmbinary never reaches — host-runtime usesstart_binary_stageandstart_openai_backend,start_stage_httphas no callers, and no release artifact ships theskippy-serverbinary. Its only live consumer is theskippy-benchlocal harness, issuing sequential single requests. Worth a separate look at whether that path should exist at all rather than widening this change.Architecture
EmbeddedRuntimeStatusgainssessions_captured_at_unix_nanos, threaded throughSkippyModelStatustollama_slots_snapshot, which now reports it aslast_success_unix_msrather thannow. Withinsessions,lane_countremains authoritative — it comes fromStageConfigand never changes; every other field is display-only observability that may be frozen. Nothing in-tree gates admission, routing, eviction, or shutdown on these values (lane exhaustion is checked insideRuntimeState::session(); admission uses the semaphore and token budget), and none of it is gossiped.Staleness is deliberately unbounded rather than bounded: under sustained load an opportunistic read can keep losing the race. The architecturally cleaner design is a snapshot published by the runtime owner after each batch and lifecycle change, carrying its own capture time, which would make status lock-free and staleness bounded. That is a larger change and deliberately not folded in here.
Measured
Standalone
serve,unsloth/gemma-4-E4B-it-GGUF:Q4_K_M, randomized ~30k-token prompt (cache-miss, ~25s prefill), probing throughout with a 3s timeout:/v1/models/api/statustcp_connectReproduced across repeat runs (6/6 probes fast). Both endpoints recover, including
/v1/models, which uses async locks rather than this mutex — consistent with the blocking acquire having starved executor threads.Inference is unaffected: same prefill duration and token counts (24.0s/28738 before, 26.0s/30471 and 25.1s/29480 after — variance is prompt randomisation), and replies remain correct (
7+5→12,finish_reason: stop).Re-measured after the follow-up commits:
/v1/models0.6–7.6ms,/api/status2.5–3.2ms during a ~25s prefill; startup unaffected by the priming lock.Tests
Seven unit tests. On
read_without_blocking():now;On
status()itself, over a realSkippyRuntimeHandle:session_stats()is pure Rust over lane bookkeeping, so these need no GGUF:RuntimeState::new_modelless_for_testbuilds one overStageModel::new_dummy(), which drops safely on a null handle.Mutation-checked, each failing fast rather than hanging:
status()→ blockinglock()default()lane_count0now()try_lock()→lock()in the helpercargo test -p skippy-server335 passed / 0 failed.cargo test -p mesh-llm-host-runtime --lib1853 passed / 0 failed. fmt and clippy clean on both crates.Review follow-ups
An independent review of the first cut (
121749bc) found three defects, fixed in419de7b1:Err(_)conflatedWouldBlockwithPoisoned, so a poisoned runtime would have reported a healthy node with cached stats while inference was failing. Now matchesTryLockErrorexplicitly and still panics onPoisoned, exactly as the previouslock().expect(..)did. Pinned by a#[should_panic]test.default(), so a read that lost the race to the very first generation published zero lanes and zero usage for that entire turn. The cache is now primed during construction, while the runtime is still unshared and uncontended.A second review round found two more, fixed in
e53e1bcbandd122ad95:read_without_blockinggenerically over aMutex<u32>; nothing asserted thatstatus()called it, so revertingstatus()to a blockinglock()left every test passing. Now covered at the call site.llama_slots_snapshotstampedlast_success_unix_ms: nowunconditionally, so cached data was republished as freshly successful every tick — see Fix above.Also corrected in this description: the original claimed
RuntimeStateis held "for the entire duration of a decode loop" and quoted a decode loop as evidence. That quote is fromhttp.rs:462, the legacy path. The live path locks per decode batch (decode_batcher.rs:192). The stall was real; the mechanism is one long native call under the lock, not a whole-turn hold.