[Bugfix][Router] release request-stats slot in finally, not just on success#1001
[Bugfix][Router] release request-stats slot in finally, not just on success#1001phil-ent wants to merge 1 commit into
Conversation
…uccess RequestStatsMonitor.on_request_complete() was only called on the success path inside process_request()'s try block. Any exception talking to the backend (a torn-down engine returning aiohttp.ServerDisconnectedError being the common case) skipped the release entirely, permanently leaving that request counted in in_prefill_requests/in_decoding_requests -- observed in production as vllm:num_requests_running climbing steadily (121->264 over 6h with no router restart) while real per-engine load stayed flat. - Move the release into a finally block, guarded to fire exactly once, so it always runs regardless of success, timeout, disconnect, or a client-abandoned stream (GeneratorExit). - on_request_complete() gained a reached_decode flag so it releases the bucket the request is actually sitting in. Previously it always decremented in_decoding_requests -- a request that fails before its first token is still in in_prefill_requests, so the old code silently no-opped (clamped at 0) on the bucket that actually needed releasing. - request_start_time/first_token_time are now popped on completion. Neither was ever released on any path before; first_token_time is write-only (never read elsewhere in the router), so every single request left one or two permanent dict entries for the life of the process. This looks like the same root cause reported in vllm-project#707. New regression tests in test_request_stats_leak.py cover both buckets, the default-argument backward-compat path, and dict cleanup. Signed-off-by: phil-ent <phil.baumann@ent.ai>
There was a problem hiding this comment.
Code Review
This pull request addresses request-tracking memory and slot leaks in the router by ensuring that request slots are always released via a finally block, properly distinguishing between prefill and decoding requests during completion, and cleaning up tracking dictionaries. It also adds comprehensive regression tests. The review feedback correctly identifies two important issues: a potential leak if an exception occurs before the main try block, and an inconsistency in on_request_complete where time.time() is used for latency calculations instead of the passed timestamp parameter.
| try: | ||
| async with request.app.state.aiohttp_client_wrapper().request( |
There was a problem hiding this comment.
The on_new_request method is called at line 276, but the main try...finally block only starts at line 323. If an exception occurs between these lines (for example, if json.loads(body) raises a JSONDecodeError on line 281, which then raises an HTTPException on line 286), the finally block at line 389 is never reached. This results in a permanent leak of the request slot in in_prefill_requests.\n\nTo prevent this, we should move the on_new_request call to be inside the try block (e.g., right before the aiohttp request is made). This ensures that early validation failures do not register a request in the stats, and if a request is registered, the finally block is guaranteed to execute and release the slot. Please also remember to remove the duplicate on_new_request call from line 276.
try:\n request.app.state.request_stats_monitor.on_new_request(\n backend_url, request_id, start_time\n )\n async with request.app.state.aiohttp_client_wrapper().request(| if request_start_time := self.request_start_time.get((engine_url, request_id)): | ||
| self.latency_monitors[engine_url].update( | ||
| timestamp, time.time() - request_start_time | ||
| ) |
There was a problem hiding this comment.
In on_request_complete, the latency is updated using time.time() - request_start_time instead of timestamp - request_start_time. Since timestamp is passed to the function as the completion time, using time.time() is inconsistent and can lead to incorrect latency metrics (especially in tests or if there is any processing delay).
if request_start_time := self.request_start_time.get((engine_url, request_id)):\n self.latency_monitors[engine_url].update(\n timestamp, timestamp - request_start_time\n )
What
RequestStatsMonitor.on_request_complete()was only called on the success path insideprocess_request()'stryblock. Any exception while talking to the backend (a torn-down engine returningaiohttp.ServerDisconnectedErrorbeing the common case in our setup) skipped the release entirely, permanently leaving that request counted inin_prefill_requests/in_decoding_requests. Observed in production asvllm:num_requests_runningclimbing steadily (121→264 over 6h with no router restart) while real per-engine load stayed flat and bounded.Two fixes, both in this PR:
services/request_service/request.py,process_request: move the release into afinallyblock, guarded to fire exactly once, so it always runs regardless of success, timeout, disconnect, or a client-abandoned stream (GeneratorExiton the async generator).stats/request_stats.py,on_request_complete: added areached_decodeflag (defaultTrue, fully backward-compatible with existing callers) so the release hits the bucket the request is actually sitting in. The old code always decrementedin_decoding_requests— a request that fails before its first token is still inin_prefill_requests, so the old code silently no-opped (clamped at 0) on the counter that actually needed releasing, while the real bucket kept leaking.While in there, also fixed a second, independent leak in the same function:
request_start_time/first_token_time(keyed by(engine_url, request_id)) were never popped on any path, success or failure — every single request left one or two permanent dict entries for the life of the process.first_token_timeis write-only (never read anywhere else in the router). This looks like the same root cause reported in #707 ("potential router memory leak" — steady RSS growth under plain RoundRobin with predictable traffic, no disconnects needed to trigger it), so this PR should close that too.Test plan
src/tests/test_request_stats_leak.py: both buckets release correctly depending onreached_decode, the default-argument path stays backward compatible, and both dicts get popped on completion (including the case where a request never reaches decode).src/tests/, 169 tests, run without GPU-only extras) still passes unmodified — 174 total with the new tests added.pre-commit run --all-files(black/isort/ruff/codespell) clean on the changed files.Related: #707