The P100 that was exactly 1.00 seconds

Posted on Edited on In
Integer tail latencies are human constants: a periodic spike traced to a cache timeout hiding inside a rate-limiter plugin.

Also in Chinese: 中文版

Symptom

One tenant’s detection API showed P100 pinned at exactly 1.00 s, spiking every 5–10 minutes. P50 through P95 stayed at a healthy 1–2 ms. Several tenants sharing the same ingress layer were affected in the same windows. Nothing was down; something was periodically stealing exactly one second from the slowest request.

Investigation

Three lines ran in parallel: access-log/error-log cross-correlation, a full configuration audit of the ingress layer (global config → rendered server config → per-route annotations), and pod-level metrics.

The first turn: upstream_response_time was normal (20–30 ms) on the slow requests. That exonerated both the upstream service and the client — the wait was happening inside the proxy layer itself.

The second turn killed the intuitive hypothesis. The config audit found exactly one “1s” anywhere in the rendered configuration, and it was a rate-limiter’s sliding-window parameter, not a proxy timeout. The obvious suspect did not exist.

The decisive evidence came from the error log: the rate-limiting plugin’s in-line cache lookups — against a single-replica memcached — were timing out, and every timeout aligned with a slow request’s timestamp and client IP. The plugin’s client library carries a default read timeout of 1,000 ms. A request that hit a stalled cache lookup waited out the full timeout, then proceeded. Exactly one second, by definition. Supporting signals: the cache was one replica with 10 worker threads, and its file-descriptor count stepped from 24 to 54 as the timeouts began.

Fix and what the loop learned

The delivered fix plan: scale the cache out of single-replica life, raise its thread pool, and — most importantly — cut the plugin’s read timeout from 1,000 ms to 100–200 ms so the worst case degrades to a fast, bounded miss instead of a one-second stall. An exporter went in for the component that had been a monitoring blind spot.

An integer tail latency is a human constant, not physics. When P100 lands on a round number, search the configs before the graphs.

That heuristic is now a standing rule in my triage playbook, and the cache layer that hid for years inside a plugin is on a dashboard.