TL;DR. Our summarization endpoint holds a p99 under 3 seconds. On 21/05 our provider degraded: median call time went from 620ms to about 4.3 seconds, roughly 7x. Our p99 went to 35 seconds, roughly 25x, and it stayed there for 52 minutes. The provider was slow for 12 of those minutes. The other 40 were us draining a queue we had never bounded and could not see. Every arrival became an in-flight task, in-flight peaked near 9,000 across 12 pods, and the latency budget went on queue wait rather than on the provider. CPU sat at 7%, so the autoscaler never moved: the workers were I/O-bound, parked on a socket, burning no CPU at all. More pods were never the answer. What worked: a bounded queue, a concurrency semaphore, a wait budget that drops requests whose caller already left, and two metrics where we previously had one. Queue wait and provider latency are different numbers. Report them as one and you will blame your provider for your own queue.
Our summarization endpoint has one SLO anyone cares about: p99 under 3 seconds, 99% of the month. It held for two quarters. On 21/05 it missed for 52 minutes and burned about 13% of a 28-day error budget in an afternoon.
The provider was slow for 12 minutes.
That gap is the whole post. A 12-minute problem upstream became a 52-minute problem for us, and the extra 40 minutes were self-inflicted. All numbers here are ours, rounded, from our incident. The code at the bottom runs.
The shape of it
14:14, latency alert: p99 over 3s for five minutes. I opened the provider's status page, which was green, and our dashboard, which said p99 31s and climbing.
Nothing had deployed since 09:40. Error rate was 0.02%, which is normal. The endpoint was returning 200s. Slowly, but returning them.
Our provider-latency graph had gone from 620ms median to about 4.3s. Real degradation, and 7x. I filed a ticket with them and started the incident note with "upstream provider degradation" as the cause, because that is exactly what it looked like.
Then the arithmetic stopped working.
7x on a 620ms call gets you 4.3s. Our p99 was 35s. Even if every request paid the full degraded latency twice, that is 9s, not 35. Something was adding twenty-five seconds that was not the provider.
At 14:24 the provider recovered. Median went back to 640ms. I watched our p99 and it did not move. It sat at 35s for another forty minutes, on a healthy provider, with a green status page, while the alert kept firing.
At 15:06 I restarted the deployment. That dropped every queued request on the floor, and p99 was back under 3s within ninety seconds. A rolling restart is a crude, indiscriminate load-shed, and it is the only thing that ended the incident. I did not enjoy learning that.
A service still broken forty minutes after its dependency is healthy is not suffering from its dependency. It is suffering from what it did while its dependency was unhealthy. We had built a backlog, and the backlog had to clear before anybody got a fast answer. The provider's 12 bad minutes bought us 40 of our own.
Why the autoscaler sat still
First thing I checked was the HPA. CPU: 7%. Target: 70%. Nothing was computing, so the autoscaler had never had a reason to act and by its own logic it was right: every pod was sitting on await, holding a socket open to a provider taking four seconds to answer.
I wrote up the general version of this a couple of weeks ago, the week we found our autoscaler tracking request rate while the bill tracked tokens, so I will spare you the re-derivation and give you the line that transfers: scaling on a signal your incident cannot move is the same as not scaling at all. Here it would also have hurt, because more pods means more concurrent calls into a provider that was already saturating for us.
The saturation signal for an I/O-bound LLM service is in-flight requests against a concurrency limit, and queue depth against a queue bound. We had neither number, because we had neither limit.
The queue I could not see
Here is what I shipped, simplified to the shape that matters:
@app.post("/summarize")
async def summarize(req: Request):
body = await req.json()
resp = await client.post(PROVIDER_URL, json=build(body)) # httpx.AsyncClient
return parse(resp)
No queue in that code. That is the problem: there is no queue in that code that I can name, measure, or bound. There are three, and I wrote none of them.
The event loop's task list is the first. Uvicorn accepts a connection, schedules a coroutine. At 40 requests per second with each parked for 4.3 seconds, you are holding about 172 at once. Nothing in that handler stops the number growing.
The second lives inside httpx. A default AsyncClient carries Limits(max_connections=100, max_keepalive_connections=20) (documented here; I also checked httpx._config.DEFAULT_LIMITS on 0.28.1 to be sure). The 101st concurrent request does not fail and does not reach the provider. It waits for a free connection, inside the pool, with no metric on it. We were timing await client.post(...), which includes that wait. So our "provider latency" graph was never measuring the provider. It measured the provider plus however long we sat in our own connection pool, and during the incident the second term dominated.
Third is the kernel accept queue, which I will not pretend I looked at.
None of these are bugs. Each is a sensible default doing exactly what it documents. Together, with 40 rps arriving and no admission control anywhere, they add up to a queue that grows without bound and reports itself to you as "the provider is slow."
What it cost
Close to nothing on the invoice, so this section is short: the provider bills tokens, and a slow call costs the same as a fast one. Financially this incident was a rounding error. That is precisely why it ran for 52 minutes without anyone escalating on cost.
It was expensive in the budget that applied. At 40 rps, a 28-day window is roughly 97 million requests, so a 99% latency SLO permits about 970,000 breaches of the 3-second line. We put roughly 125,000 requests over it in 52 minutes: about 13% of a month's error budget, in under an hour, caused by a dependency that was unhealthy for 12 minutes.
Around 100,000 of those had already timed out at 30 seconds and gone. We computed responses in full and wrote them to closed sockets.
Little's Law, and the number I did not have
The arithmetic that explains all of this is 65 years old and fits on one line.
L = λW. The average number of items in a queuing system equals the average arrival rate times the average time each item spends in it. John Little published the proof in 1961 (A Proof for the Queuing Formula: L = λW, Operations Research 9(3), 383-387) and wrote a genuinely readable retrospective on its fiftieth anniversary: Little's Law as Viewed on Its 50th Anniversary, Operations Research 59(3), 2011. It assumes almost nothing. No distribution, no independence, no particular queue discipline, and it holds when arrivals are nonstationary, which is exactly what an incident is. It describes your service whether or not you have thought about it.
Healthy: λ = 40 rps, W = 0.62s, so L = 25 concurrent calls. Comfortable. It is why nobody had ever needed a concurrency limit to exist.
Degraded: W = 4.3s, so holding 40 rps requires L = 172 concurrent calls. Twelve pods at 100 pooled connections each gave us room for 1,200, so we could physically open 172. We did. And that is what did the damage, because the provider would not serve 172 of our calls at once. Their effective throughput for us fell to about 27 rps.
Now the law runs the wrong way. Arrivals 40. Departures 27. The queue grows at 13 per second, 780 per minute, and over 12 minutes that is about 9,400. We measured a peak near 9,000 in-flight. That agreement is the only reason I trust the reconstruction at all.
Then invert it. L = 9,000, λ = 40, so W = L/λ = 225 seconds. Our clients time out at 30. At the peak we were producing answers that were, on average, 195 seconds too late to be wanted, and we kept producing them for forty minutes after the provider was fine. Nothing recovers from that on its own, which is why a restart was the only lever left.
The fix: a queue you can name
More pods would not have helped. A longer timeout is the other reflex, and it is strictly worse: a longer timeout means the caller waits longer before leaving, which raises W, which raises L. Timeouts are not a capacity strategy.
Four things went in that week. Roughly in the order I would put them back:
- A concurrency semaphore. A hard cap on simultaneous provider calls, set below the point where the provider's latency curve bends. This is the one that stops 172 from ever happening. (asyncio.Semaphore is the whole implementation.)
- A bounded queue with fail-fast admission. Past the bound, refuse immediately: 429 plus Retry-After. That is the same contract as the token-budget admission gate from that same write-up, moved down a layer and re-denominated. That one bounded tokens in flight, because tokens were what saturated the GPU. This one bounds calls in flight, because concurrency is what saturates a provider you do not own. asyncio.Queue(maxsize=N) raises QueueFull from put_nowait the moment it is full, which is the behaviour you want (docs). A 429 in one millisecond is a kinder answer than a 200 in 225 seconds.
- A wait budget. When a worker picks a job up, check how long it sat. If it sat longer than the caller will wait, drop it and never call the provider. Calling on behalf of someone who has already hung up spends provider capacity that the callers still waiting need.
- Two timers instead of one. One extra perf_counter() call. Cheapest thing on this list and the reason I understood any of the rest, which is why I have given it room further down rather than a bullet.
The whole thing, runnable, no dependencies:
"""Bounded concurrency + admission control for LLM calls. python3 pool.py"""
import asyncio
import time
from dataclasses import dataclass, field
CONCURRENCY = 8 # simultaneous provider calls
QUEUE_MAX = 11 # admission buffer: drain rate x WAIT_BUDGET, not a vibe
WAIT_BUDGET = 2.0 # sec. waited longer than this and the caller is gone
class Shed(Exception):
"""Queue full at admission. -> 429 + Retry-After."""
class Stale(Exception):
"""Waited past budget. -> 503. Never reaches the provider."""
@dataclass
class Job:
rid: int
fut: asyncio.Future
enqueued_at: float = field(default_factory=time.perf_counter)
class BoundedPool:
def __init__(self, call, concurrency=CONCURRENCY, queue_max=QUEUE_MAX,
wait_budget=WAIT_BUDGET):
self.call, self.wait_budget, self._n = call, wait_budget, concurrency
self.q = asyncio.Queue(maxsize=queue_max)
self.sem = asyncio.Semaphore(concurrency)
self.wait_ms, self.provider_ms = [], []
self.ok = self.shed = self.stale = 0
async def __aenter__(self):
self._workers = [asyncio.create_task(self._worker()) for _ in range(self._n)]
return self
async def __aexit__(self, *exc):
for t in self._workers:
t.cancel()
await asyncio.gather(*self._workers, return_exceptions=True)
async def submit(self, rid):
job = Job(rid, asyncio.get_running_loop().create_future())
try:
self.q.put_nowait(job) # QueueFull once maxsize is reached
except asyncio.QueueFull:
self.shed += 1
raise Shed(f"req {rid}: {self.q.qsize()} already queued, refusing")
return await job.fut
async def _worker(self):
while True:
job = await self.q.get()
try:
async with self.sem:
# Everything above this line is our fault, not theirs.
waited = time.perf_counter() - job.enqueued_at
self.wait_ms.append(waited * 1000)
if waited > self.wait_budget:
self.stale += 1
job.fut.set_exception(Stale(f"req {job.rid}: {waited:.1f}s"))
continue
t0 = time.perf_counter()
try:
result = await self.call(job.rid)
except Exception as e:
job.fut.set_exception(e)
else:
self.ok += 1
job.fut.set_result(result)
finally:
self.provider_ms.append((time.perf_counter() - t0) * 1000)
finally:
self.q.task_done()
def pct(xs, p):
s = sorted(xs)
return s[min(int(round(p / 100 * (len(s) - 1))), len(s) - 1)] if s else 0.0
# A stand-in provider with a real ceiling: serves 12 at a time, never errors,
# and goes 7x slower two seconds in. Swap in your own client here.
_sem, START = None, 0.0
async def provider(rid):
async with _sem:
await asyncio.sleep(1.40 if time.perf_counter() - START > 2.0 else 0.20)
return f"resp-{rid}"
async def main():
global _sem, START
_sem, START = asyncio.Semaphore(12), time.perf_counter()
async with BoundedPool(provider) as pool:
async def one(rid):
try:
await pool.submit(rid)
except (Shed, Stale):
pass # in a request handler, return 429 / 503 here
tasks = []
for rid in range(400):
tasks.append(asyncio.create_task(one(rid)))
await asyncio.sleep(1 / 40) # 40 rps of arrivals
await asyncio.gather(*tasks, return_exceptions=True)
print(f"served={pool.ok} shed={pool.shed} stale={pool.stale}")
print(f"queue wait p50={pct(pool.wait_ms, 50):6.0f}ms p99={pct(pool.wait_ms, 99):6.0f}ms")
print(f"provider p50={pct(pool.provider_ms, 50):6.0f}ms p99={pct(pool.provider_ms, 99):6.0f}ms")
if __name__ == "__main__":
asyncio.run(main())
The stand-in provider has a ceiling (12 concurrent) and goes 7x slower two seconds in. It is not our incident in miniature, and I want to be precise about the gap: the stand-in never recovers, where ours did after 12 minutes and the backlog outlived it by forty. So the demo shows a backlog outliving its arrivals. It does not show one outliving the degradation that caused it, and that second thing is what made 21/05 confusing enough that restarting pods looked like the only lever. On my machine:
served=136 shed=255 stale=9
queue wait p50= 0ms p99= 2574ms
provider p50= 201ms p99= 1401ms
Run the same 400 arrivals with no pool, one task per request, the way we had it, and you get this instead, again on my machine:
served=400/400 peak in-flight=263 drained in 40s
end-to-end p50= 12273ms p99= 29696ms
Compare the provider numbers. The bounded run says the provider's p99 is 1,401ms, which is the truth: 1.4s is literally the constant inside the sleep. The unbounded run says 29,696ms. Same provider, same degradation, and a 21x difference in the number you would paste into a support ticket.
Watch the drain, too. Arrivals stop at 10 seconds; the unbounded run does not finish until 40. Three quarters of that run is backlog burning down after the last caller has arrived. Ours was forty minutes of drain on twelve minutes of degradation.
Timing our wait separately from their call
The highest-leverage line in that file is where the second timer starts.
async with self.sem:
waited = time.perf_counter() - job.enqueued_at # ours
...
t0 = time.perf_counter()
result = await self.call(job.rid) # theirs
Two timers, split at the moment we actually begin talking to the provider. Everything before is our queueing: admission, queue, semaphore. Everything after is theirs.
We had been exporting one histogram, llm_request_duration_seconds, wrapped around the whole handler. That histogram is worse than having none, because it is confidently wrong. It read 35 seconds while pointing at a provider that was answering in 4.3. I took that graph into a support ticket and asked a vendor to explain a number my own service had manufactured. That is embarrassing, and one extra perf_counter() call would have prevented it.
We now export three: llm_queue_wait_seconds, llm_provider_duration_seconds, and end-to-end. The first two should roughly sum to the third, and when they stop summing, the difference is time being spent somewhere neither timer covers. That divergence is its own signal.
The rule I would hand my past self: if a request waits inside your process before you do the thing, that wait is a metric. Any queue you are not measuring is unbounded, because you cannot bound what you cannot see.
What it misses at scale
Four things still wrong, in descending order of how much they bother me.
I cannot defend the queue depth. I derived QUEUE_MAX = 11 from Little's Law: useful depth = drain rate x wait budget, and the degraded drain rate is 8 permits / 1.4s = 5.7 rps, so 5.7 x 2.0 ≈ 11. But drain rate is not a constant, so the derivation is thinner than it looks. Healthy, it is 8/0.2 = 40 rps, so the right depth would be 80. A fixed number is wrong in one direction at all times. I ran the demo at both depths, several times each, on my machine: served never moved outside noise (135 to 141 at depth 32, 131 to 141 at depth 11) while stale dropped from the seventies to around ten. Your absolute numbers will move with load; the gap between the two columns does not. Depth buys you no throughput whatsoever. It only decides whether you refuse a request in one millisecond or waste two seconds of its life first. The wait budget is what actually protects the caller. The depth only decides how much memory the backlog is allowed to occupy while it waits.
The SRE book disagrees with my ratio and may well be right. Chapter 22 of the Google SRE book, Addressing Cascading Failures, recommends keeping queue size small relative to pool size, on the order of 50% or less, so that a server rejects early under sustained overload. Mine is 11 against 8 permits, about 1.4x. I picked that deliberately for bursty arrivals: a short burst that clears inside the wait budget should be absorbed rather than refused. If your traffic is steady rather than bursty, take their ratio over mine.
The concurrency limit is static. Ours is a number I chose by watching where the provider's latency curve bends, then re-chose twice. The honest version measures it continuously, because a provider's capacity for you is neither constant nor published. That is real work, and we have not done it.
Shedding is not free, and the demo is blunt about the bill: 255 shed, 9 stale, 136 served out of 400. A 66% rejection rate. No amount of engineering fixes that, because a pool draining at 5.7 rps cannot absorb 40 rps of arrivals. Physics gets a vote. The only decision available is who finds out, and how quickly. Shedding does not rescue the requests it drops. It moves the failure to a moment you picked in advance, while you can still answer in one millisecond with a status code the caller can act on. If you read one thing before this post, read Handling Overload, chapter 21 of the same book.
What I'd page on
I had four dashboards for this service on 21/05. Every one of them was green while the SLO burned, because all four watched CPU, error rate, request count, and provider latency: the two that cannot see queueing, and two that actively lie about it. Here is what replaced them. Copy the metrics. The thresholds are ours.
- Queue wait p99, alone, as its own series. Page when it exceeds half the wait budget. Not end-to-end, not provider latency: the wait, by itself. Had this existed on 21/05 it would have read 200 seconds while the provider graph read 4.3, and nobody would have spent nineteen minutes reading a status page.
- Shed rate and stale rate, separately, never summed. They mean opposite things. Shed climbing means admission control is working and arrivals exceed capacity: expected, page only if sustained past five minutes. Stale climbing means we admitted work we could not finish in time, which is an admission-control bug, and the queue is too deep for the budget. That distinction is what QUEUE_MAX = 11 is for, and stale is the metric that proves the number is right.
- Provider latency timed around the call and nothing else. Not the handler. Not the pool acquire. The call. This is the only number worth taking to a vendor, and until 21/05 we did not have it, which is why my support ticket was fiction.
- Backlog drain time, derived: queue depth divided by observed drain rate. L/λ, on a graph. It answers "if arrivals stopped right now, how long until we are clear," and it is the number that tells you a restart is the only remaining lever, roughly forty minutes before you work it out by hand.
I have written before about a green dashboard hiding a real problem, so rather than run that argument again I will mark what is different here. That one was a bill: every run passed, nothing errored, and the damage showed up on an invoice. This one is time. Our error rate on 21/05 sat at 0.02%, normal for us, and the provider's status page stayed green from the first alert to the last. Neither number was wrong. Neither number was about where the 195 seconds went, because we were measuring how much time a request took and never which queue it spent it in.
Three questions decide whether you are running my 21/05 service. What happens to the 173rd concurrent call? How long did the last request sit before we dialed anyone? If arrivals stopped this second, when would the backlog be clear? We could not answer any of the three, and it took a provider having a bad twelve minutes to show us.
Top comments (0)