p99 latency is 25 seconds and the error rate is zero: histograms, histogram_quantile and timeouts

$ hey -n 100 -c 10 http://localhost:8080/api/orders
...
Latency distribution:
  10% in 0.0195 secs
  25% in 0.0271 secs
  50% in 0.0396 secs
  75% in 0.0413 secs
  90% in 19.1365 secs
  95% in 19.1447 secs
  99% in 19.1536 secs
...
Status code distribution:
  [200]	40 responses

Error distribution:
  [60]	Get "http://localhost:8080/api/orders": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

The page says: orders p99 over 20 seconds on every endpoint, error rate 0.0%, CPU 3%, database CPU normal. The load test above agrees on the slowness. It also shows something the dashboard can't: 60 of the 100 requests never got an answer at all. hey gave up on them after its 20-second timeout. And still the server-side error rate says zero.

What is actually happening

"Error rate" only counts the errors the server sent

The usual error-rate query divides responses with a 5xx status by all responses, using the server's own request counter:

$ promtool query instant http://localhost:9090 'sum(rate(http_server_requests_seconds_count{job="orders",status=~"5.."}[5m])) / sum(rate(http_server_requests_seconds_count{job="orders"}[5m]))'
{} => 0.00018008283810552856 @[1790107204.7]

A request that takes 25 seconds and then returns 200 is a success to that query. A request whose caller gave up after 20 seconds isn't an error either. The server never sent a 5xx. It logs whatever status it eventually writes, often a 200 nobody reads. The timeouts are real, but they live on the caller's side: in the load balancer, in the upstream service's client metrics, in the user's browser. An error-rate alert built only from server status codes is blind to "slow". It's the same reason a proxy in front can show 502s and gateway timeouts that the app's own metrics never see: the component that gave up is the one that records it.

p99 comes from buckets, and it's an estimate

A Prometheus histogram is a set of counters, one per bucket. _bucket{le="0.5"} counts the requests that took at most 0.5 s (le = less than or equal), up to le="+Inf", which counts them all. histogram_quantile turns bucket rates into a percentile:

$ promtool query instant http://localhost:9090 'histogram_quantile(0.99, sum by (le, uri) (rate(http_server_requests_seconds_bucket{job="orders"}[5m])))'
{uri="/api/orders"} => 0.9166071428571425 @[1790107204.5]
{uri="/api/checkout"} => 1.871071428571434 @[1790107204.5]
{uri="/actuator/health"} => 0.024749999999999998 @[1790107204.5]

Read it inside out: per-second rate of each bucket over 5 minutes, summed across instances while keeping le, then the 99th percentile per uri. Leave le out of the by and nothing is left to compute with: histogram_quantile(0.99, sum(rate(..._bucket[5m]))) returns an empty result. Two more traps:

• The precision is the bucket width. The function assumes requests spread evenly inside a bucket and draws a straight line. If the p99 lands between le="1.0" and le="2.5", all you really know is "somewhere in 1 to 2.5 s".
• The highest finite bucket is a ceiling. If p99 falls in the +Inf bucket, the function returns the upper bound of the last finite bucket. With buckets ending at 10 s, a 25-second p99 is drawn as a flat line at 10, which looks bad but stable, and is wrong.

Spring Boot adds a third trap: it exports http_server_requests_seconds with only _count, _sum and _max unless you turn on management.metrics.distribution.percentiles-histogram.http.server.requests=true. No buckets means no p99 at all.

Slow with idle CPU means waiting

Seconds per request at 3% CPU means threads are parked, waiting for something. That's a queue, not a computation.

Diagnosis

1. Measure it yourself, under load

One curl gives you one sample, not a p99. A load generator like hey gives a distribution and the client-side timeouts (the output at the top).

2. Check the buckets, not just the percentile

The fraction of requests under your threshold is exact, needs no interpolation, and is the number an SLO is written in:

$ promtool query instant http://localhost:9090 'sum(rate(http_server_requests_seconds_bucket{job="orders",uri="/api/checkout",le="0.5"}[5m])) / sum(rate(http_server_requests_seconds_count{job="orders",uri="/api/checkout"}[5m]))'
{} => 0.8926746166950595 @[1790107204.8]

89% of checkouts finished in under 500 ms. That's a latency SLI that drops when requests get slow, even when every one of them returns 200.

3. Find what the threads wait on

Take three thread dumps ten seconds apart and count the states:

$ grep -A1 'java.lang.Thread.State' dump1.txt | grep -v -- '--' | sort | uniq -c | sort -rn | head -3
    184 	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
    182    java.lang.Thread.State: TIMED_WAITING (parking)
     31    java.lang.Thread.State: RUNNABLE
$ grep -c 'HikariPool.getConnection(HikariPool.java:162)' dump1.txt
180
$ grep -c PaymentsClient.authorize dump1.txt
20

180 threads wait for a database connection. The 20 that hold the whole pool are all inside PaymentsClient.authorize, a call to another service. The pool metrics agree:

$ curl -s localhost:8080/actuator/prometheus | grep -E "^hikaricp_connections_(active|pending|max)"
hikaricp_connections_active{pool="HikariPool-1"} 20.0
hikaricp_connections_pending{pool="HikariPool-1"} 177.0
hikaricp_connections_max{pool="HikariPool-1"} 20.0

The biggest cluster in the dump (180 waiting) is the symptom. The small one (20 holding) is the cause.

4. Find the setting that allows a wait that long

$ sudo grep -n timeout /etc/orders/app.conf
7:db.pool.timeout.ms=30000
8:http.client.connect.timeout.ms=2000
9:http.client.read.timeout.ms=0

read.timeout.ms=0 means no read timeout. When payments slows down, each checkout holds a database connection for as long as payments takes. Every other endpoint queues behind the pool, and those waits stay under the pool's 30-second limit, so they end in 200 and never count as errors.

The fix

Give the call a timeout, restart (the config is read at startup), and measure with the same load:

$ sudo sed -i 's/http.client.read.timeout.ms=0/http.client.read.timeout.ms=2000/' /etc/orders/app.conf
$ sudo systemctl restart orders
$ hey -n 300 -c 10 http://localhost:8080/api/orders | grep -E "99%|responses"
  99% in 0.0048 secs
  [200]	300 responses

Checkout now fails fast while payments is sick. Errors appear, and that's the point: they show the true state of checkout and you can alert on them, while every other endpoint recovers.

How to prevent it

• Alert on latency too, as an SLI (fraction of requests under a threshold), not only on status codes.
• Every outbound call gets a timeout shorter than its caller's. Zero means "forever".
• Size buckets to your timeouts. The highest finite bucket should sit above the longest timeout in the path, or the p99 flat-lines at the ceiling.
• Sum buckets first, then take the percentile. Never average per-instance p99s: a broken instance hides behind a healthy one.
• Keep remote calls out of database transactions, and add a circuit breaker for a dependency that's slow.

For the other half of JVM trouble, memory rather than waiting, see exit code 137 and the JVM. And if the waiting is on disk or NFS rather than a pool, the Linux-side version of this story is high load with idle CPU.

Practise it

Chapter 21's incident "p99 is 25 seconds and the error rate is zero" runs this on a live box with hey, thread dumps and the actuator. Chapter 27's PromQL lessons and drills cover percentiles from buckets.