Close queue.wait at dequeue so it measures a wait #120

Merged

coilysiren merged 1 commit from queue-wait-measures-the-wait into main

2026-08-13 18:11:24 +00:00

coilyco-ops commented

2026-08-13 18:08:41 +00:00

Member

Bug

Fixes #105.

The issue opened on a 16.6s gap between queue.wait's p50 and the resilience.attempt p50 inside it, then settled it by measuring 29 traces individually:

	value
`queue.wait` range	1.89s .. 46.58s (25x spread)
admission delay median	1.51 ms
admission delay max	4.52 ms

queue.wait is a sibling of resilience.attempt, not its parent, and it stayed open for the whole request - tracking request.chat to within a millisecond at every point. The 16.6s gap was a percentile artifact (resilience.attempt emits one span per attempt, so retries skew its population).

That cost the investigation a wrong turn and a retracted claim in two other issues. It also makes the span unusable for the question its name invites: a saturated proxy and a slow model look identical when the span tracks total request duration either way.

Fix

Job carries a dequeued future the worker resolves on pickup. submit waits on that alongside the result future, so a job that fails before any worker takes it cannot leave the wait hanging.
The span closes there. What remains inside it is enqueue to dequeue, and request.chat - queue.wait - resilience.attempt now decomposes.
The result attributes are removed from it. Token counts and finish reason describe the response, and a span ending before the response exists has no business reporting them - they are already on resilience.attempt and request.chat. In their place: agentproxy.queue.admitted.
asyncio.wait does not pass cancellation through to the futures it watches, so submit now cancels the job future by hand. Without that a cancelled waiting job kept its queue slot, which test_cancelled_waiting_job_releases_queue_slot already pins.

How to verify

ward exec test - test_queue_wait_ends_at_dequeue_not_at_completion holds a job in dispatch and asserts the span has already closed with admitted: True, and that it does not reopen or duplicate when the response arrives.
test_cancelled_waiting_job_releases_queue_slot still passes, which is what caught the asyncio.wait cancellation gap.

Test plan

Regression test for the span lifetime
Existing tests still pass (328 passed)
ward exec format-check, lint, typecheck, pre-commit all clean

Risk

Low, but it is an observability contract change. Any dashboard or query reading gen_ai.usage.* or response.finish_reasons off queue.wait will stop finding them; those attributes live on request.chat and resilience.attempt. Anything reading queue.wait duration as request duration will see it collapse to milliseconds - which is the fix, not a regression.

One existing assertion changed: a queue.wait span for a cancelled request no longer carries outcome=cancelled, because by then it has been closed for the whole dispatch. The cancellation is still recorded on the three spans that were open when it happened.

Note on #107

This does not answer the queue-versus-shed question in #107. It makes the burst test's key measurement readable: admission delay is now the span's own duration rather than a subtraction.

Note

Branched off cancel-abandoned-work (#119). Review #118 and #119 first; this branch contains their commits.

## Bug Fixes #105. The issue opened on a 16.6s gap between `queue.wait`'s p50 and the `resilience.attempt` p50 inside it, then settled it by measuring 29 traces individually: | | value | | --- | --- | | `queue.wait` range | 1.89s .. 46.58s (25x spread) | | admission delay median | **1.51 ms** | | admission delay max | 4.52 ms | `queue.wait` is a **sibling** of `resilience.attempt`, not its parent, and it stayed open for the whole request - tracking `request.chat` to within a millisecond at every point. The 16.6s gap was a percentile artifact (`resilience.attempt` emits one span per attempt, so retries skew its population). That cost the investigation a wrong turn and a retracted claim in two other issues. It also makes the span unusable for the question its name invites: a saturated proxy and a slow model look identical when the span tracks total request duration either way. ## Fix - `Job` carries a `dequeued` future the worker resolves on pickup. `submit` waits on that alongside the result future, so a job that fails before any worker takes it cannot leave the wait hanging. - The span closes there. What remains inside it is enqueue to dequeue, and `request.chat - queue.wait - resilience.attempt` now decomposes. - The result attributes are removed from it. Token counts and finish reason describe the response, and a span ending before the response exists has no business reporting them - they are already on `resilience.attempt` and `request.chat`. In their place: `agentproxy.queue.admitted`. - `asyncio.wait` does not pass cancellation through to the futures it watches, so `submit` now cancels the job future by hand. Without that a cancelled waiting job kept its queue slot, which `test_cancelled_waiting_job_releases_queue_slot` already pins. ## How to verify 1. `ward exec test` - `test_queue_wait_ends_at_dequeue_not_at_completion` holds a job in dispatch and asserts the span has already closed with `admitted: True`, and that it does not reopen or duplicate when the response arrives. 2. `test_cancelled_waiting_job_releases_queue_slot` still passes, which is what caught the `asyncio.wait` cancellation gap. ## Test plan - [x] Regression test for the span lifetime - [x] Existing tests still pass (328 passed) - [x] `ward exec format-check`, `lint`, `typecheck`, `pre-commit` all clean ## Risk Low, but it is an observability contract change. Any dashboard or query reading `gen_ai.usage.*` or `response.finish_reasons` off `queue.wait` will stop finding them; those attributes live on `request.chat` and `resilience.attempt`. Anything reading `queue.wait` duration as request duration will see it collapse to milliseconds - which is the fix, not a regression. One existing assertion changed: a `queue.wait` span for a cancelled request no longer carries `outcome=cancelled`, because by then it has been closed for the whole dispatch. The cancellation is still recorded on the three spans that were open when it happened. ## Note on #107 This does not answer the queue-versus-shed question in #107. It makes the burst test's key measurement readable: admission delay is now the span's own duration rather than a subtraction. ## Note Branched off `cancel-abandoned-work` (#119). Review #118 and #119 first; this branch contains their commits.

coilyco-ops added 2 commits

2026-08-13 18:08:41 +00:00

Bound one request's total upstream time and record what the caller got

ci / quality (pull_request) Successful in 22s

Details

ci / smoke (pull_request) Successful in 8s

Details

2bfd472b26

Issue #112 measured an inverted timeout ladder: sirens-echo gives up at 180s,
agent-proxy at 240s, litellm's request span at 600s, its server span at ~1004s.
The caller goes first and the abandoned upstream request runs on for another 7
to 13 minutes with nobody to receive its answer. Issue #106 records the same
shape from the far end: litellm generated for 207 seconds after agent-proxy
stopped waiting, then returned 500.

The caller is not the problem and raising its deadline does not fix this.
sirens-echo builds its request with http.NewRequestWithContext on its turn
deadline, so it does disconnect at 180s. Whatever the caller's number is, a
caller that has gone away should stop costing inference.

PROXY_REQUEST_TIMEOUT was per attempt, so with retries and a fallback chain
nothing bounded the request as a whole. PROXY_REQUEST_DEADLINE is a wall clock
for all of it: queue wait, every retry, every fallback. Past it no further
attempt starts, and the in-flight attempt is cut by asyncio.wait_for, which
closes the httpx request and with it the upstream connection. The route answers
504 rather than folding a timeout into 502 backend-unavailable. It defaults to
0, off, so nothing changes for a deployment that does not set it.

A caller that knows its own budget sends X-Request-Deadline-Ms. It may only
shorten the configured deadline, never lengthen it, because an operator ceiling
a caller can talk past is not a ceiling. Set below the caller's own timeout it
closes the connection while the caller is still listening, rather than leaving
the upstream generating for someone who has already left.

POST /v1/completions had no disconnect watcher at all, while the chat surface
has had one. Same resilience path, none of the cancellation. Both now share
_until_disconnect. The body is read to completion before the watcher starts,
since the two would otherwise race for the same ASGI receive channel.

For the measurement half of #106: every terminal response now stamps
http.response.status_code on the request span. The trace in that issue carried
an empty status and has_error false on all six agent-proxy spans against an
upstream 500, which is the reason its 0.74% error rate could not be trusted. The
upstream-span half of that landed with #114.

What this does not do is make litellm stop. Closing the connection is the only
cancellation signal HTTP offers, and whether the far end acts on it is litellm's
own behaviour to verify.

closes #112
closes #106

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-authored-by: Kai Siren <coilysiren@gmail.com>
Co-authored-by: Claude <noreply@anthropic.com>

Close queue.wait at dequeue so it measures a wait

ci / smoke (pull_request) Successful in 6s

Details

ci / quality (pull_request) Successful in 23s

Details

5a25e38837

Issue #105 opened on a 16.6-second gap between the p50 of queue.wait and the
p50 of the resilience.attempt inside it, then measured 29 traces individually
and found the gap was not queueing at all. queue.wait is a sibling of
resilience.attempt, not its parent, and it stayed open for the whole request:
1.89s to 46.58s across the sample, tracking request.chat to within a
millisecond at every point, while the real admission delay held between 0.71ms
and 4.52ms through a 25-fold spread in the span it was supposedly measuring.

That cost the investigation a wrong turn and a claim retracted in two other
issues. It also makes the span unusable for the one question its name invites:
a saturated proxy and a slow model look identical when the span tracks total
request duration either way.

The span now closes the moment a worker claims the job. Job carries a dequeued
future the worker resolves on pickup, and submit waits on that alongside the
result future, so a job that fails before any worker takes it cannot leave the
wait hanging. What remains inside the span is enqueue to dequeue, which is what
it always claimed to be, and request.chat minus queue.wait minus
resilience.attempt now decomposes.

The result attributes are gone from it. Prompt and completion token counts and
the finish reason describe the response, and a span that ends before the
response exists has no business reporting them; they are already on
resilience.attempt and request.chat. In their place is
agentproxy.queue.admitted, false when the job ended before admission.

asyncio.wait does not pass cancellation through to the futures it watches, so
submit now cancels the job future by hand when its caller is cancelled. Without
that, a cancelled waiting job kept its queue slot, which is the behaviour
tests/test_queue.py already pins.

A queue.wait span for a cancelled request no longer carries outcome=cancelled,
because by then it has been closed for the whole dispatch. The cancellation is
recorded on request.chat, resilience.attempt, and upstream.chat, which are the
spans that were open when it happened.

closes #105

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-authored-by: Kai Siren <coilysiren@gmail.com>
Co-authored-by: Claude <noreply@anthropic.com>

coilyco-ops requested review from coilysiren

2026-08-13 18:08:41 +00:00