visualserver: prevent silent wedge from embed-cache stalls - #2
Open
sufubao wants to merge 4 commits into
Open
Conversation
…to_*
Instrument `_commit_to_cpu_cache` and `_commit_to_afs` with unconditional
START/DONE debug logs around the three steps that can hang without raising:
- `image.cuda_event.synchronize()` — C++ CUDA-runtime call, no Python
exception if the stream wedges.
- `cache_client.root.set_items_embed(uuids)` — synchronous RPyC.
- `image.event.set()` — unblocks the visualserver event loop's
`to_thread(event.wait)`; if this never fires the visual recv loop
eventually goes silent via default-executor thread-pool exhaustion.
Existing `_log_latency(stage=...)` only logs when latency > 0.02s, so a
step that never returns leaves no trace in the log. Bracketed logs make
the stuck step identifiable from a post-mortem: the last START without
matching DONE pinpoints the wedge.
Per-image md5 included so concurrent flows can be disambiguated.
Replace the unbounded `await asyncio.to_thread(event.wait)` in `handle_images` with a 60-second deadline. When the wait times out, mark the shm_req aborted and forward to the next module so the slot is released downstream rather than pinned at refcount=1. Without a deadline, a hang in `_commit_to_cpu_cache` (cuda_event sync, `set_items_embed` RPyC, or `event.set`) leaves each affected request holding one default-executor thread via `to_thread(event.wait)`. After ~12-32 stuck waits the executor is exhausted and the next `to_thread(zmq_recv_socket.recv_pyobj)` in `loop_for_netio_req` queues forever - visual recv goes silent for the whole process. This matches the prod incident shape: VIT halts together with visual recv silence, no Python-level exceptions logged, shm slots fill until 503. The `client-disconnect-abort` path landed in a20d078 catches reqs whose clients give up first, but doesn't help when load-balancer keepalives hold the connection open. This deadline plus aborted-forward ensures the shm slot is reclaimed in either case.
`get_need_infer_images` calls `cache_client.root.get_items_embed(...)` synchronously, on the event loop. Any embed-cache slowdown (lock contention, GC pause, slow disk on cache server) blocks the entire visualserver event loop - including `loop_for_netio_req`'s `to_thread(zmq_recv_socket.recv_pyobj)`, since while the loop is blocked synchronously no other task progresses. Make `get_need_infer_images` async and run the RPyC call via `asyncio.to_thread`, which offloads the wait to the default executor without blocking the loop. Update both callers (`VisualManager.handle_group_indexes` and `ProxyVisualManager.handle_group_indexes`). This is defense-in-depth and orthogonal to the b034c2a fix - the prod incident wedged via the SET path (`_commit_to_cpu_cache`), but the GET path is the same architectural pattern and would wedge the same way under a different stall mode.
The exception handler in `_store_worker` re-raised, terminating the worker thread. After one failed commit (e.g. RPyC `result expired` from a slow embed-cache server) the per-DP store thread is dead and every subsequent image piles up in `store_queue` indefinitely - their `image.event` never gets set, and visualserver's `handle_images` has to wait the full 60s deadline (now bounded by b034c2a) for each one. Catch the exception, log it with image count, set `image.event` for the in-flight batch so handle_images returns immediately, release the semaphore, and continue looping. The worker survives transient embed- cache failures and recovers when the cache server does. Setting event on commit failure is safe: the actual embed tensor data was already copied into shared CPU memory by `_store_to_cpu_cache` before the failed RPyC call. Only the cache-server metadata flag was not set, which means future `get_items_embed` calls will return False for these UUIDs and the requests will redo VIT inference - harmless, no data corruption.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
When the embed-cache RPyC server stalls (hung-but-alive), the visualserver pipeline silently wedges: VIT inference halts,
loop_for_netio_reqstops draining zmq, shm slots accumulate torunning_max_req_size, and the service flips unhealthy. Recovery requires a process restart.This PR adds:
Bracketed
START/DONEdebug logs at the three silent-wedge candidates in_commit_to_cpu_cache(cuda_event.synchronize,set_items_embed,image.event.set). Existing_log_latencyonly fires when latency > 0.02s, so a step that never returns leaves no trace; bracket logs let post-mortem identify the wedge from the last unmatchedSTARTline.A 60-second deadline on
handle_images.event.wait. Without this, each stuck request holds one default-executor thread (viato_thread(event.wait)); after ~12-32 stuck waits the executor exhausts and the nextto_thread(zmq_recv_socket.recv_pyobj)queues forever — visual recv goes silent for the whole process. On timeout, the request is marked aborted and forwarded so downstream releases the shm slot rather than pinning it at refcount=1.get_items_embedruns off the event loop. The synchronous RPyC call previously ran on the asyncio event loop, so any embed-cache slowdown could wedgeloop_for_netio_req. Wrapped inawait asyncio.to_thread(...). Defense-in-depth — same architectural pattern as the SET path that triggered the original incident._store_workersurvives commit failures. The exception handler re-raised, terminating the per-DP worker thread. After a single RPyCresult expired, the thread was dead and every subsequent image piled up instore_queue— itsimage.eventnever fired, andhandle_imageshad to wait the full 60s deadline for each. Now it logs the exception, signals events for the failed batch (so visualserver returns immediately), releases the semaphore, and continues looping. The actual embed tensor data was already in shared CPU memory before the failed RPyC call; only the cache-server metadata flag is missing, which is harmless (future requests redo VIT — no data corruption).Validation
Reproduced the prod-shape outage by injecting a permanent stall in
exposed_set_items_embedafter a brief warmup, then comparing patched vs. unpatched behavior under identical multimodal load (Qwen3-VL-8B,--visual_dp 3, 20 reqs / 4 concurrent)./healthreturns Error)/healthafter stallRegression test on healthy traffic (1000 reqs / 200 concurrent / 3 imgs / cpu_cache enabled): 1000/1000 success, p50 5.9s, p95 11.9s — within noise of unpatched baseline (p50 5.4s, p95 8.6s). No false positives on the new timeout / commit-failure paths.
Test plan
set_items_embedstall — verify timeout + abort path releases shm slotset_items_embedstall — verify_store_workersurvives RPyCresult expiredLIGHTLLM_LOG_LEVEL=debug— START/DONE pairs match