Part of Home Server →
A 22-second search, traced
The obvious culprit had a timeout that matched the symptom almost exactly. It was not the cause. The time was going into code that draws a badge.
The number that matched, and was a coincidence
Search was intermittently taking 22.1 seconds while neighbouring terms answered in under half a second. The search path fans out to two external catalogues, and one of them had a 20-second timeout configured, a near-perfect match for the symptom. It had also been returning server errors for hours the previous day.
Timing both upstreams directly from the same machine gave 0.15 to 0.44 seconds each. The hypothesis was wrong, and acting on the coincidence would have meant tuning a timeout that was never firing while the real cost stayed exactly where it was.
It was the badge
The expensive call decided whether to draw an “already have this” marker on a result. It cached per user for five minutes, and on a miss it ran two library queries, run sequentially, though they had never depended on each other, at 3.1 to 11.5 seconds and 3.4 to 10.4 seconds. So exactly one search every five minutes paid the whole bill before anything came back.
The payloads were 278 KB and 87 KB, so this was query cost on a loaded machine rather than transfer. That also means no amount of query tuning would have held: the same flag that helped one query hurt the other, and both effects sat inside the run-to-run variance.
The two-second delay that mattered
The fix was to run the two queries in parallel, serve a stale value immediately, and refresh behind the request. That still cost the caller 2.78 seconds, even though the stale value had returned instantly.
The refresh’s two queries went out on the same HTTP/1.1 connection pool, and the caller’s own search queued behind them. Head-of-line blocking, self-inflicted, on a request that had already been answered. Deferring the refresh by two seconds, past the request that triggered it, removed it.
Post-timeout searches went from 9–22 seconds to 0.596. Warm sits at 0.21. Badge correctness was re-checked afterwards, because a performance win that quietly breaks a badge is worse than none: near-miss titles still correctly report not-owned.