The Health Checker Was Manufacturing the Stalls It Detects

98% of our request log was liveness probes, consuming 63% of prefill GPU time and creating the sessions that froze real requests for up to 520 seconds.

Summary

Requests to our Mac inference server would hang for two to three minutes and then work fine. We blamed weight paging, then model contention. Both wrong. Generation was never slow — the server's own log showed 30–45 tok/s on every completed request. The stalls were scheduler starvation caused by 60 accumulated anonymous sessions, and those sessions were minted, one per probe, by our own gateway health checks. The monitoring designed to detect stalls was creating them.

Two wrong theories first

The symptom: an idle server takes 90 to 213 seconds to produce a first token, then behaves normally. Classic cold-start signature.

Theory one: MLX weight paging. The model is ~40 GB; the OS pages it out when idle; the first request pays to bring it back. Plausible, matches the shape exactly.

Theory two: duplicate model contention. The machine was, in fact, running the model twice — two service definitions, one of them orphaned with no gateway alias pointing at it. Real problem, 39.8 GB reclaimed by disabling it. Not the cause.

The log killed both:

"event": "mtplx_stream_silence", "elapsed_s": 91.48, "completion_tokens": 0,
"seconds_since_last_token": 91.48, "scheduler_active_kind": "foreground",
"scheduler_foreground_pending": 2, "scheduler_idle_pending": 3

postcommit cross-session yield {"count": 91,
  "reason": "cross_session_foreground_preempted", "sessions": [...91 anon ids...]}

Generation itself: elapsed_s: 0.86–3.5, tok_s: 30–45 on every completed request. Always.

The same response logged silence at 30 s → 91 s → 152 s → 213 s with zero tokens produced. 308 such events in one log.

Not paging. Not contention. The scheduler was doing background maintenance work across 91 live sessions, and that work was preempting foreground generation.

The definitive disproof

A controlled restart settled it:

A server that has just cold-loaded 40 GB of weights answers in 1.71 seconds. There is no load penalty at all.

That's the whole cold-start theory dead in one measurement. Latency tracks session count and nothing else.

Worth noting the trap that made the wrong theory so attractive: back-to-back requests read 1.0 s while an idle-then-first request reads 150 s. That looks exactly like paging from the outside. Don't infer cold start from wall-clock latency alone — the shape is shared by several unrelated mechanisms.

Where the sessions came from

For a while we treated periodic restarts as the answer and wrote "sessions accumulate at roughly 3/hour, this will recur" as an open problem.

The rate was wrong and so was the source. The real number is 60 per hour, and the minter was our own gateway:

litellm_settings:
  background_health_checks: true
  health_check_interval: 120

One machine backed two gateway deployments — a load-balanced pool member and a direct pin. Two probes every 120 seconds is 60 probes per hour.

The server only reuses a session when the prompt shares at least 4,096 tokens of prefix with an existing one. A tiny health probe never matches anything, so every single probe mints a fresh anonymous session. The bank's idle timeout is 3,600 seconds. Sixty arrive per hour, roughly sixty stay alive.

Which is exactly the sixty live sessions we measured, all anonymous.

And those sessions are precisely what the scheduler does cross-session maintenance across — the work that preempts real generation. The worst silence we recorded was 520.8 seconds with zero tokens, well past the client's own 240-second watchdog. So the health checker caused a stall long enough that the client gave up, which in this server also leaks a scheduler slot (the abandoned-request post).

The health checker was manufacturing the stalls it exists to detect, and then the detection failure caused a second failure.

The log is 98% monitoring

Separately, we went looking for the real prefill bottleneck by reading the server's request log — 66 MB, about 4,761 records with timing.

The last 4,000 requests break down as: 1,679 "What's 1 + 1?", 1,669 "Hey how's it going?", 531 "ok", 30 "Say OK".

About 90 are real work.

Any conclusion about server performance drawn from that log without filtering is a measurement of the monitoring system. Which we'd done, more than once.

It gets worse. Those 3,909 sub-32-token probes consumed 4,883 seconds — 63% of all prefill GPU time.

And the mechanism behind that number is almost funny. The two probe prompts alternate, so each one evicts the other's cached prefix. cached_tokens cycles 16 → 3. About half the probes therefore take 2.1 seconds instead of 0.14. The probe latency distribution is bimodal for this reason: median 0.20 s, mean 1.16 s.

Two alternating probe prompts cost about six times more than one repeated prompt. Use a single fixed probe string, or probe an endpoint that doesn't run the model.

What we actually changed

Opted out of background health checks on every affected deployment. One of them serves with a single-slot parallelism setting, where a probe every 120 seconds takes its only slot — that one was strictly worse than no monitoring at all.

Two deployments already carried the opt-out flag, so this was house practice that hadn't been applied consistently. Liveness is now covered by an on-demand fleet check instead.

Three candidate fixes we explicitly discarded:

• Periodic restarts — a stopgap, and it treats an accumulation rate as if it were an accumulation event.
• Purging the session bank — the bank is bounded and self-evicting. It was at 47 of 48 entries. Not the problem.
• Having clients send a stable session id — there is no such path at this server's OpenAI-compatible endpoint. Session identity is resolved purely by prefix matching. A plausible-sounding fix that doesn't exist.

The actual fix is to cut the creation rate, which is a gateway config line.

A statistics warning from the same log

While segmenting the 67 real requests over 10k tokens, we hit a median that's worth showing:

That 5% median cache reuse is misleading, and we nearly quoted it. The distribution is bimodal: 36 requests under 10%, 30 requests over 85%, and exactly one in between.

The median describes no actual request. Half the workload gets an almost-perfect cache hit and half gets nothing, and the summary statistic reports a condition that essentially never occurs.

Segment before quoting a median. A bimodal distribution is common in caching, routing, and any system with a hit/miss structure — which is most systems.

Prefill throughput turned out to be fine at 256–345 tok/s. The problem was how many tokens needed re-prefilling. That trail led to the prefix-cache post, where the answer was a mutating tool catalog at token 1,067, and roughly 27× of TTFT.

Monitoring that manufactures the very stalls it exists to detect is more common than you'd think — it's on the setup audit checklist.

Key takeaways

1. Read the server's own log before theorizing. Ours said generation ran at 30–45 tok/s throughout, which eliminated two theories immediately.
2. A cold server answering in 1.71 seconds disproves cold start. One controlled restart, one number.
3. Wall-clock latency shape is not a mechanism. Idle-then-slow looks identical for paging, session starvation, and several other causes.
4. Health checks that can't share a cache create per-probe state. Sixty an hour, each one permanent for an hour, was our entire problem.
5. Alternating probe prompts thrash each other. Ours cost about 6× a single fixed prompt, and 63% of all prefill GPU time.
6. Filter monitoring traffic out of every log analysis. 98% of ours was probes, and we'd drawn conclusions from the unfiltered version.
7. Check for bimodality before quoting a median. Ours reported a 5% cache reuse rate that described one request out of 67.