What p99 latency hides during connection pool saturation

We had a service whose database queries were, by every metric we collected, fast. Median query time 1.4ms, p99 at 11ms, no slow-query log entries. The service itself was timing out under load.

Where the measurement boundary was wrong

The instrumentation wrapped the query execution, not the pool acquisition:

conn, err := pool.Acquire(ctx)   // not measured
if err != nil {
    return err
}
defer conn.Release()

start := time.Now()               // measurement starts here
rows, err := conn.Query(ctx, sql) // fast, always
observe(time.Since(start))

Every millisecond spent waiting for a free connection landed outside the timer. The database was never the bottleneck; the queue in front of it was. Once Acquire was inside the measured span, p99 moved from 11ms to 840ms and the graph finally matched the user experience.

Why the percentile made it worse

Percentile latency is computed over requests that completed. During saturation the slowest requests are the ones that time out and get dropped, so they never enter the histogram. The pool tightening actively improves your p99 by removing its own worst samples — the metric gets better as the system gets worse.

Two things fix this:

1. Measure acquisition and execution as one span. The caller does not care which half was slow.
2. Track saturation directly, not through its effects: pool utilisation, wait-queue depth, and acquisition timeouts per second are all leading indicators; latency is a lagging one.

The result

Pool size went from 20 to 48 — still well under the database’s connection limit — and the wait queue emptied. p99 settled at 14ms, this time measured across the whole operation, which means it is now a number worth alerting on.

The general lesson is not about pools. It is that a percentile is only as honest as its denominator, and a metric that discards its own worst cases will always look healthy right up to the point of failure.