coilyco-flight-deck/agent-proxy

Watch

Median turn spends 20s to do 3.4s of work — establish what queue.wait actually measures, then fix it #105

New issue

Closed

opened 2026-08-12 20:34:59 +00:00 by coilyco-ops · 3 comments

coilyco-ops commented

2026-08-12 20:34:59 +00:00

Member

Observation

24h window, scalar aggregates:

Span	p50	p99
`POST /v1/chat/completions`	20.11s	147.14s
`request.chat`	20.09s	147.13s
`queue.wait`	20.09s	147.13s
`resilience.attempt`	3.44s	145.56s
`upstream.chat`	3.43s	145.56s
`litellm_request` (litellm)	3.42s	233.71s

At p50 there is a 16.6s gap between queue.wait and the resilience.attempt nested inside it. At p99 the same two spans are only 1.5s apart.

What I am not claiming

If queue.wait is the parent of resilience.attempt, its duration spans admission through completion rather than time spent waiting, and the name is then misleading rather than the behaviour being wrong. Percentiles across different requests do not decompose, so p50-minus-p50 is not a per-request wait and I cannot settle this from aggregates.

The p50 and p99 rows disagree about which reading is right, which is itself the reason to look: a consistent story would show the same relationship at both.

Why it matters either way

If it is real queueing, the median turn waits ~16.6s to perform ~3.4s of work — a 6× amplification on every ordinary turn, and the most likely explanation for user-visible Discord latencies of 20–80s on queries whose model work is a few seconds (coilyco-gaming/sirens-echo#160).
If it is a span-naming artifact, then queue.wait is unusable for exactly the question people will ask it, and the queue-position signal proposed in #104 has less to report than that issue assumes.

Both outcomes change what gets built next, which is why this is worth an hour before the heartbeat work rather than after.

Suggested first step

Read 5–10 individual traces rather than aggregates: confirm the parent/child relationship, and measure enqueue→first-attempt-start per trace. That is a direct measurement of admission delay and settles it.

Acceptance

The parent/child semantics of queue.wait are documented, and its name matches what it measures.
Per-trace admission delay is measurable without subtracting percentiles.
If real admission delay is confirmed at the p50 scale above, a follow-up issue carries the fix.

#104 — SSE heartbeats, which would carry queue position if there is queueing to report
coilyco-gaming/sirens-echo#162 — where these numbers were first gathered

## Observation 24h window, scalar aggregates: | Span | p50 | p99 | | --- | --- | --- | | `POST /v1/chat/completions` | 20.11s | 147.14s | | `request.chat` | 20.09s | 147.13s | | `queue.wait` | 20.09s | 147.13s | | `resilience.attempt` | 3.44s | 145.56s | | `upstream.chat` | 3.43s | 145.56s | | `litellm_request` (litellm) | 3.42s | 233.71s | At p50 there is a **16.6s gap** between `queue.wait` and the `resilience.attempt` nested inside it. At p99 the same two spans are only 1.5s apart. ## What I am not claiming If `queue.wait` is the **parent** of `resilience.attempt`, its duration spans admission *through* completion rather than time spent waiting, and the name is then misleading rather than the behaviour being wrong. Percentiles across different requests do not decompose, so p50-minus-p50 is not a per-request wait and I cannot settle this from aggregates. The p50 and p99 rows disagree about which reading is right, which is itself the reason to look: a consistent story would show the same relationship at both. ## Why it matters either way - If it is real queueing, the median turn waits ~16.6s to perform ~3.4s of work — a 6× amplification on every ordinary turn, and the most likely explanation for user-visible Discord latencies of 20–80s on queries whose model work is a few seconds (`coilyco-gaming/sirens-echo#160`). - If it is a span-naming artifact, then `queue.wait` is unusable for exactly the question people will ask it, and the queue-position signal proposed in #104 has less to report than that issue assumes. Both outcomes change what gets built next, which is why this is worth an hour before the heartbeat work rather than after. ## Suggested first step Read 5–10 individual traces rather than aggregates: confirm the parent/child relationship, and measure enqueue→first-attempt-start per trace. That is a direct measurement of admission delay and settles it. ## Acceptance - The parent/child semantics of `queue.wait` are documented, and its name matches what it measures. - Per-trace admission delay is measurable without subtracting percentiles. - If real admission delay is confirmed at the p50 scale above, a follow-up issue carries the fix. ## Related - #104 — SSE heartbeats, which would carry queue position if there is queueing to report - `coilyco-gaming/sirens-echo#162` — where these numbers were first gathered

coilyco-ops commented

2026-08-12 20:49:58 +00:00

Author

Member

Resolved by direct measurement: there is no admission delay, and `queue.wait` is misnamed

Read two traces end to end. Both give the same structure, and it is not what the aggregates implied.

`queue.wait` is a sibling of `resilience.attempt`, not its parent

POST /v1/chat/completions              (root)
└─ request.chat                        b4fe5c1cbe5d5b2e
   ├─ queue.wait                       parent = request.chat
   └─ resilience.attempt               parent = request.chat
      └─ upstream.chat
         └─ POST → litellm

I guessed parent/child in the issue body. It is neither — they are siblings that both span the whole request.

Admission delay, measured per trace

Time from queue.wait start to resilience.attempt start:

Trace	`queue.wait` start	`resilience.attempt` start	delay
`724205380aa14e8fa7806c0ab789f19a` (fast, 1.16s)	`20:40:05.719525566`	`20:40:05.723550857`	4.03 ms
`8ea6619aa21aacae118b2d310a658f11` (slow, 240.0s)	`20:03:18.218518971`	`20:03:18.219062706`	0.54 ms

Sub-5ms in both, including the 240-second request. There is no queueing to report.

And the durations confirm the naming problem: queue.wait 1.160102s against request.chat 1.161064s in the fast trace, 239.9856s against 239.9864s in the slow one. It tracks the whole request to within a millisecond.

Where the 16.6s p50 gap came from

A population artifact, as feared. resilience.attempt emits one span per attempt, so retries put multiple short spans into its population — the 19 response_validation_failed attempts in this window are ~3s each. queue.wait emits once per request. Comparing p50s across span names with different per-request cardinality is invalid, and that is exactly what I did.

Retracting the claim that the median turn spends ~17s queueing to do ~3.4s of work. It does not. Correction posted to coilyco-gaming/sirens-echo#162, where I made it most strongly.

What this changes downstream

#104's heartbeat payload should drop queue position. There is no queue depth worth reporting. The attempt n of 3 signal survives and is now the main justification — retries are real, they are invisible from outside, and 19 of them happened in 24h.

Recommended fix here

Rename queue.wait, or delete it. It measures the same interval as request.chat while carrying a name that asserts something false about where time goes — which cost this investigation a wrong turn and a retracted claim in two other issues. If admission delay is worth measuring, the span should cover only enqueue→dequeue, which by this data would be a sub-millisecond span most of the time.

A separate and more serious finding from the slow trace

Filing separately: in 8ea6619aa21aacae118b2d310a658f11, litellm ran for 447.25s and returned 500, while agent-proxy's client span ended at 239.99s marked has_error: false. Upstream kept working 207s after the caller stopped listening, and the failure is invisible on the agent-proxy side.

## Resolved by direct measurement: there is no admission delay, and `queue.wait` is misnamed Read two traces end to end. Both give the same structure, and it is not what the aggregates implied. ### `queue.wait` is a sibling of `resilience.attempt`, not its parent ``` POST /v1/chat/completions (root) └─ request.chat b4fe5c1cbe5d5b2e ├─ queue.wait parent = request.chat └─ resilience.attempt parent = request.chat └─ upstream.chat └─ POST → litellm ``` I guessed parent/child in the issue body. It is neither — they are **siblings that both span the whole request**. ### Admission delay, measured per trace Time from `queue.wait` start to `resilience.attempt` start: | Trace | `queue.wait` start | `resilience.attempt` start | **delay** | | --- | --- | --- | --- | | `724205380aa14e8fa7806c0ab789f19a` (fast, 1.16s) | `20:40:05.719525566` | `20:40:05.723550857` | **4.03 ms** | | `8ea6619aa21aacae118b2d310a658f11` (slow, 240.0s) | `20:03:18.218518971` | `20:03:18.219062706` | **0.54 ms** | Sub-5ms in both, including the 240-second request. **There is no queueing to report.** And the durations confirm the naming problem: `queue.wait` 1.160102s against `request.chat` 1.161064s in the fast trace, 239.9856s against 239.9864s in the slow one. It tracks the whole request to within a millisecond. ### Where the 16.6s p50 gap came from A population artifact, as feared. `resilience.attempt` emits **one span per attempt**, so retries put multiple short spans into its population — the 19 `response_validation_failed` attempts in this window are ~3s each. `queue.wait` emits once per request. Comparing p50s across span names with different per-request cardinality is invalid, and that is exactly what I did. **Retracting the claim** that the median turn spends ~17s queueing to do ~3.4s of work. It does not. Correction posted to `coilyco-gaming/sirens-echo#162`, where I made it most strongly. ### What this changes downstream **#104's heartbeat payload should drop queue position.** There is no queue depth worth reporting. The `attempt n of 3` signal survives and is now the main justification — retries are real, they are invisible from outside, and 19 of them happened in 24h. ### Recommended fix here Rename `queue.wait`, or delete it. It measures the same interval as `request.chat` while carrying a name that asserts something false about where time goes — which cost this investigation a wrong turn and a retracted claim in two other issues. If admission delay is worth measuring, the span should cover **only** enqueue→dequeue, which by this data would be a sub-millisecond span most of the time. ## A separate and more serious finding from the slow trace Filing separately: in `8ea6619aa21aacae118b2d310a658f11`, litellm ran for **447.25s** and returned **500**, while agent-proxy's client span ended at 239.99s marked `has_error: false`. Upstream kept working 207s after the caller stopped listening, and the failure is invisible on the agent-proxy side.

coilyco-ops referenced this issue

2026-08-12 20:50:19 +00:00

Upstream 500 after 447s is recorded as a non-error, and litellm keeps working 207s after the caller is gone #106

coilyco-ops commented

2026-08-12 20:55:33 +00:00

Author

Member

Narrowing my own conclusion: I measured no contention, not no queue

I wrote "there is no queueing to report." That is stronger than the evidence supports, and since it drove a recommendation to drop queue position from #104, correcting it now.

The traffic makes an empty queue the expected result either way

Agent-proxy's own 24h figures: 407 requests, avgDuration 23.7s.

arrival rate      = 407 / 86,400s        = 0.0047 req/s
mean service time = 23.7s
average concurrency (Little's law) = 0.0047 × 23.7 ≈ 0.11

At ~0.11 average concurrency there is almost never more than one request in flight. A fully functional queue would show sub-millisecond admission delay under that load — indistinguishable from an inert one. My two traces are consistent with:

Queueing active and simply never contended
Queueing configured but not wired to the request path
No queue at all, span emitted unconditionally

Span data cannot separate these. I should have said so rather than picking the strongest reading.

What still holds

Unchanged, because it does not depend on load:

queue.wait is a sibling of resilience.attempt, not its parent
Its duration tracks request.chat to within a millisecond, so it does not measure a wait whatever the queue is doing
The 16.6s p50 gap is a retry-population artifact, and the retraction of "median turn waits ~17s" stands

The naming problem is real regardless of which of the three explanations is correct.

What changes

Withdrawing "drop queue position from #104." The correct statement is narrower: queue position carries no information at current traffic levels. Whether it carries information under concurrency is untested — and the concurrency case is the one that matters, because several people hitting the bot at once is precisely the August 19 scenario.

The test that settles it

A concurrency burst against agent-proxy, reusing #164's methodology (that issue ran a 30-way burst against the Echo-side limiter and got 8 admitted / 22 rejected with 429). Two questions, both answered by one run:

Under N concurrent requests, does admission delay rise above the sub-5ms floor? If yes, queueing is live and #104 should carry position.
Does agent-proxy shed (429) rather than queue? If so, queue.wait can never show a wait by construction, and the span should be deleted rather than renamed.

Worth doing before the heartbeat work, not after — same argument as the original issue, now with a sharper test.

## Narrowing my own conclusion: I measured no contention, not no queue I wrote "there is no queueing to report." That is stronger than the evidence supports, and since it drove a recommendation to drop queue position from #104, correcting it now. ### The traffic makes an empty queue the expected result either way Agent-proxy's own 24h figures: **407 requests**, `avgDuration` **23.7s**. ``` arrival rate = 407 / 86,400s = 0.0047 req/s mean service time = 23.7s average concurrency (Little's law) = 0.0047 × 23.7 ≈ 0.11 ``` At ~0.11 average concurrency there is almost never more than one request in flight. A **fully functional** queue would show sub-millisecond admission delay under that load — indistinguishable from an inert one. My two traces are consistent with: 1. Queueing active and simply never contended 2. Queueing configured but not wired to the request path 3. No queue at all, span emitted unconditionally Span data cannot separate these. I should have said so rather than picking the strongest reading. ### What still holds Unchanged, because it does not depend on load: - `queue.wait` is a **sibling** of `resilience.attempt`, not its parent - Its duration tracks `request.chat` to within a millisecond, so it does not measure a wait *whatever* the queue is doing - The 16.6s p50 gap is a retry-population artifact, and the retraction of "median turn waits ~17s" stands The naming problem is real regardless of which of the three explanations is correct. ### What changes **Withdrawing "drop queue position from #104."** The correct statement is narrower: queue position carries no information *at current traffic levels*. Whether it carries information under concurrency is untested — and the concurrency case is the one that matters, because several people hitting the bot at once is precisely the August 19 scenario. ### The test that settles it A concurrency burst against agent-proxy, reusing #164's methodology (that issue ran a 30-way burst against the Echo-side limiter and got 8 admitted / 22 rejected with 429). Two questions, both answered by one run: 1. Under N concurrent requests, does admission delay rise above the sub-5ms floor? If yes, queueing is live and #104 should carry position. 2. Does agent-proxy **shed** (429) rather than queue? If so, `queue.wait` can never show a wait by construction, and the span should be deleted rather than renamed. Worth doing before the heartbeat work, not after — same argument as the original issue, now with a sharper test.

coilyco-ops referenced this issue

2026-08-12 21:19:13 +00:00

Concurrency burst test: does agent-proxy queue or shed, and should heartbeats carry queue position #107

coilyco-ops referenced this issue

2026-08-12 22:35:09 +00:00

Tag spans with backend operating regime — percentiles are unreadable across a shared GPU #109

coilyco-ops commented

2026-08-13 10:49:31 +00:00

Author

Member

Ran the per-trace measurement this issue asks for. It settles the question: queue.wait is a span-lifetime artifact, not real queueing.

Parent/child, settled

queue.wait is not the parent of resilience.attempt. They are siblings, both children of request.chat:

request.chat            cf71a9e22e18d1dc   17.4694s  @ .684542
├─ queue.wait           d45acf572f0f0918   17.4686s  @ .684793
└─ resilience.attempt   7d3ee70312e05f41   17.4670s  @ .686347
   └─ upstream.chat     29fe6e5a91855a8c   17.4667s  @ .686547
      └─ POST -> litellm f4099e1497b40cca  17.4654s

Trace 5d8cdf1209b63818179bd7af3b608b8d. queue.wait starts 1.55 ms before resilience.attempt and ends 46 us after it. It stays open for the whole request instead of closing at dequeue.

Per-trace admission delay, 29 traces

Because the two siblings end together, queue.wait - resilience.attempt is the per-trace admission delay, with no percentile subtraction:

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

The delay stays inside a 0.7-4.5 ms band while queue.wait itself varies 25-fold:

queue.wait  1.89s -> admission 1.48 ms  (0.078% of the span)
queue.wait 17.47s -> admission 1.60 ms  (0.009%)
queue.wait 35.77s -> admission 0.99 ms  (0.003%)
queue.wait 46.58s -> admission 1.63 ms  (0.004%)

That constancy is the proof. Were queue.wait genuine waiting and resilience.attempt the work, the two would be sequential and their difference would scale with load. A near-constant few-ms difference across a 25x duration spread is the signature of two spans that start milliseconds apart and end together.

So queue.wait reports admission delay plus the entire attempt. Reading it as wait time overstates queueing by three to four orders of magnitude.

What this does to the p50 gap

The 16.6s p50 gap in the issue body is not 16.6s of queueing. It is the same end-alignment seen through percentiles that do not decompose. The method above computes it per trace, which is what the acceptance criteria asked for.

Worth noting this run was not contention-free, so the low numbers are not an idle-system artifact: the window holds 29 agent-proxy traces against only 12 model calls from the battery, so other traffic was in flight, including one 46.6s request. Admission delay still never exceeded 4.52 ms.

Suggested fix

End the queue.wait span at dequeue rather than at request completion. It then measures what its name claims, and request.chat - queue.wait - resilience.attempt decomposes cleanly. Until that lands, no dashboard or alert can use queue.wait for saturation: it tracks total request duration within ~1 ms at every percentile, so a saturated proxy and a slow model look identical.

This also revises what the heartbeat work can report. Queue position at #104 has close to nothing to carry while real admission delay sits at 1.5 ms. The user-visible 20-80s Discord latencies referenced from coilyco-gaming/sirens-echo#160 are upstream inference time, not admission, so they need a different line of attack.

Provenance

Sirens Deep battery, ward exec eval-deep, route sirens-echo/deepseek, 10/10 cases pass, exit 0, 12 model calls all HTTP 200. Window 1786617849573-1786617990000. Client was kais-macbook-pro over the tailnet against ser8:8080. Measured through the SigNoz MCP against traces, not logs.

Ran the per-trace measurement this issue asks for. It settles the question: **`queue.wait` is a span-lifetime artifact, not real queueing.** ## Parent/child, settled `queue.wait` is **not** the parent of `resilience.attempt`. They are **siblings**, both children of `request.chat`: ``` request.chat cf71a9e22e18d1dc 17.4694s @ .684542 ├─ queue.wait d45acf572f0f0918 17.4686s @ .684793 └─ resilience.attempt 7d3ee70312e05f41 17.4670s @ .686347 └─ upstream.chat 29fe6e5a91855a8c 17.4667s @ .686547 └─ POST -> litellm f4099e1497b40cca 17.4654s ``` Trace `5d8cdf1209b63818179bd7af3b608b8d`. `queue.wait` starts 1.55 ms before `resilience.attempt` and **ends 46 us after it**. It stays open for the whole request instead of closing at dequeue. ## Per-trace admission delay, 29 traces Because the two siblings end together, `queue.wait - resilience.attempt` **is** the per-trace admission delay, with no percentile subtraction: | | value | | --- | --- | | traces | 29 | | `queue.wait` range | 1.89s .. 46.58s (25x spread) | | admission delay min | 0.71 ms | | admission delay median | **1.51 ms** | | admission delay max | 4.52 ms | The delay stays inside a 0.7-4.5 ms band while `queue.wait` itself varies 25-fold: ``` queue.wait 1.89s -> admission 1.48 ms (0.078% of the span) queue.wait 17.47s -> admission 1.60 ms (0.009%) queue.wait 35.77s -> admission 0.99 ms (0.003%) queue.wait 46.58s -> admission 1.63 ms (0.004%) ``` That constancy is the proof. Were `queue.wait` genuine waiting and `resilience.attempt` the work, the two would be sequential and their difference would scale with load. A near-constant few-ms difference across a 25x duration spread is the signature of two spans that start milliseconds apart and end together. So `queue.wait` reports **admission delay plus the entire attempt**. Reading it as wait time overstates queueing by three to four orders of magnitude. ## What this does to the p50 gap The 16.6s p50 gap in the issue body is not 16.6s of queueing. It is the same end-alignment seen through percentiles that do not decompose. The method above computes it per trace, which is what the acceptance criteria asked for. Worth noting this run was **not** contention-free, so the low numbers are not an idle-system artifact: the window holds 29 agent-proxy traces against only 12 model calls from the battery, so other traffic was in flight, including one 46.6s request. Admission delay still never exceeded 4.52 ms. ## Suggested fix End the `queue.wait` span at dequeue rather than at request completion. It then measures what its name claims, and `request.chat - queue.wait - resilience.attempt` decomposes cleanly. Until that lands, no dashboard or alert can use `queue.wait` for saturation: it tracks total request duration within ~1 ms at every percentile, so a saturated proxy and a slow model look identical. This also revises what the heartbeat work can report. Queue position at https://forgejo.coilysiren.me/coilyco-flight-deck/agent-proxy/issues/104 has close to nothing to carry while real admission delay sits at 1.5 ms. The user-visible 20-80s Discord latencies referenced from https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/160 are upstream inference time, not admission, so they need a different line of attack. ## Provenance Sirens Deep battery, `ward exec eval-deep`, route `sirens-echo/deepseek`, 10/10 cases pass, exit 0, 12 model calls all HTTP 200. Window `1786617849573`-`1786617990000`. Client was `kais-macbook-pro` over the tailnet against `ser8:8080`. Measured through the SigNoz MCP against traces, not logs.

coilyco-ops referenced this issue from coilyco-gaming/sirens-echo

2026-08-13 10:59:50 +00:00

Roughly 15 percent of Deep turns silently pay a doubled model call because the 900-token base budget is below the model's reasoning floor #360

coilyco-ops referenced this issue from a pull request that will close it,

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

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

coilyco-ops referenced this issue from a commit

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

Close queue.wait at dequeue so it measures a wait