Tail latency: p99s, GC pauses and what users feel

A customer told our support team last fall that our app was “slow all the time”. Support passed it on, and an engineer pulled up the dashboard and replied, a bit defensively, that our average API response time was 44 milliseconds. Both of them were right, and the fact that both of them could be right is the whole subject of this post.

The thing that sent me back to it is Discord’s engineering post from the 4th, Why Discord is switching from Go to Rust, which has been all over HN. Most of the discussion has been Go versus Rust, which I find the least interesting part. The actual story is about a latency spike every two minutes, and why that spike mattered even though most requests never saw it.

Why the average lies

Take a made-up endpoint that handles 1,000 requests. 980 of them take 20 ms. The other 20 hit something slow, a lock, a cold cache, a GC pause, and take 2 seconds each.

The average is (980 × 20 + 20 × 2,000) / 1,000 = (19,600 + 40,000) / 1,000 = 59.6 ms. Not one request in that set took anything close to 60 ms. The fast ones took a third of that and the slow ones took thirty times it. The mean is a number that describes no actual request, and it moves when the tail moves, so it looks like it’s telling you something, which is worse than useless.

Percentiles fix this by asking a different question. The p50 (the median) is the latency that half your requests beat. The p99 is the latency that 99% of them beat, so 1 in 100 is slower. In the example, sort the 1,000 latencies and the 500th is 20 ms, so p50 is 20 ms. The 950th is still 20 ms, so p95 is 20 ms too. The 990th is one of the slow ones, so p99 is 2 seconds. Those three numbers tell you the real story, most requests are fast and a small slice is terrible, and the average told you none of it.

Real distributions don’t have two clean spikes, they have a long smear to the right. Here’s the shape of a typical day on one of our busier endpoints, simplified into buckets, per thousand requests:

If you take the midpoint of each bucket as a rough stand-in, the mean comes out around 35 ms, the median is about 19 ms, and p99 sits right at the 320 ms boundary, because 990 of the 1,000 requests are in the first five buckets. p99.9 is somewhere in the 640 ms to 1.3 second bucket. The chart is a decent picture of the problem. The bars you can actually see are the ones nobody’s complaining about.

“But it’s only 1%”

This is the argument I hear most, usually from engineers, and I used to make it myself. If p99 is bad, that’s 1 in 100 requests, so 1 in 100 users has a bad time, and that’s acceptable.

The flaw is that users don’t make one request. A single page load in our app makes somewhere around 40 API calls once you count the initial data, the sidebar, the notifications badge and everything that loads lazily. If each call independently has a 1% chance of landing in the tail, the chance that a page load has at least one slow call is 1 − 0.99⁴⁰, which is about 33%. A third of page loads include something from the tail. And if the slow call is one the page needs before it can render, the whole page is as slow as that one call.

That was our customer. They used the app heavily, all day, so they hit the tail many times a day, and to them “the app” meant the experience of the slowest thing on each screen. Our average told us about the requests. They were telling us about the pages.

The same math applies inside your system, and it gets worse. Jeff Dean and Luiz André Barroso wrote it up in The Tail at Scale (CACM, 2013), which is still the best short paper on this I know. If one user request fans out to 100 servers in parallel and has to wait for all of them, and each server has a 1-in-100 chance of being slow, then 1 − 0.99¹⁰⁰ ≈ 63% of user requests are slow. Their example server is fast at 10 ms typically and slow at a second at the p99, so most requests that fan out wide end up taking a second. The rare thing at the leaves becomes the common thing at the root.

The paper’s fixes are worth knowing even if you’re nowhere near Google’s size. The one I like most is the hedged request: send the request to one replica, and if it hasn’t answered within, say, the p95 latency, send the same request to a second replica and take whichever answers first. You only pay the extra load on the slowest 5% of requests. In their BigTable test, reading 1,000 keys spread over 100 servers, hedging after 10 ms brought the p99.9 down from 1,800 ms to 74 ms for about 2% more requests. That’s a ridiculous return. It only works for requests that are safe to send twice, so reads, or writes that are idempotent, but a lot of fan-out traffic is reads.

Where the tail comes from

In my experience the tail is rarely “the code is slow”. The median request and the p99 request usually run exactly the same code. What differs is what else was happening on the machine at the time. Lock contention, a background job hogging the disk, a noisy neighbor on the same host, a TCP retransmit, a cache that just got evicted, a connection pool that ran dry so the request waited for a connection before doing any work at all. And garbage collection, which is the one that brings us back to Discord.

I wrote about garbage collectors a couple of years ago, including our own run-in with the .NET large object heap, where a reporting service triggered a full gen 2 collection every few seconds under load and the p99 graph had a sawtooth in it you could have cut wood with. The average barely moved during that whole episode. If we’d only had the average we’d never have found it.

Discord’s version is a service called Read States, which tracks which channels and messages each user has read, so it’s on the path of basically everything you do in the app. It’s in Go, and it keeps a big in-memory LRU cache with millions of entries. Every two minutes, latency and CPU spiked. The cause turned out to be that Go’s runtime forces a garbage collection at least every two minutes, whether or not the program has allocated enough to need one, and with a huge cache full of pointers, the collector had to scan the whole thing each time. Tuning the GC target percentage didn’t help, because the service wasn’t allocating fast enough for that setting to matter. Splitting the cache into smaller ones made each spike smaller but raised the p99 overall, since more lookups missed the cache and went to the database. They tested on Go 1.9.2 and say 1.8, 1.9 and 1.10 behaved the same.

So they rewrote the service in Rust, which has no garbage collector, memory is freed as soon as its owner goes away. The first naive port matched Go’s latency and had no spikes at all, and after some tuning it beat Go on latency, CPU and memory, and they could grow the cache to 8 million entries.

My take, for what it’s worth. It’s a good post and a reasonable decision for a small, hot, well-understood service that a team was willing to own in a new language. I wouldn’t read it as “Go is bad for latency”. Go’s GC is very good at short pauses on normal heaps, and this is a specific bad case, a giant long-lived heap of pointers that never really changes, which is about the worst thing you can give a non-generational collector. There are other ways out, keeping the cache off-heap or in a structure without pointers in it, and a few Go people in the HN thread have been suggesting exactly that. What I’d take from it is the shape of the investigation. They saw a spike with a period of exactly two minutes, didn’t accept “it’s the GC, nothing to be done”, found the actual rule in the runtime causing it, and measured the tail before and after.

Measuring it without fooling yourself

A few things I’ve learned to check, mostly by getting them wrong.

You can’t average percentiles. If you have ten servers each reporting their own p99, the average of those ten numbers isn’t the p99 of the fleet, and it can be wildly off if one server is having a bad day. You need the underlying distributions, histograms you can merge, and then compute the percentile from the merged histogram. HdrHistogram is the classic library for this. In Prometheus you’d use a histogram rather than a summary for the same reason, since summaries compute quantiles per instance and can’t be combined. We had a Grafana panel for about a year that showed “average p99 across hosts”, and I’m not proud of it.

Watch your time windows. A p99 over a whole day hides a five-minute disaster at 2 p.m. A p99 per minute is noisy at low traffic, because 1% of 300 requests is three requests. I tend to look at per-minute percentiles with the request count right next to them, so I know how much to believe each point.

Look out for coordinated omission, which is Gil Tene’s name for a mistake almost every load-testing tool makes. If your load generator sends a request, waits for the reply, then sends the next one, then a 2-second stall on the server only shows up as one slow request, because the generator politely stopped sending during the stall. Real users don’t stop arriving because your server is busy. Everyone who would have arrived in those 2 seconds also had a bad time, and your benchmark didn’t count any of them. His talk How NOT to Measure Latency is an hour well spent, and it changed how I read every benchmark graph.

And measure from where the user is, if you can. Server-side latency starts when the request reaches your code. The user’s latency includes DNS, TLS, the load balancer, a queue in front of your app server, and the browser. Our server-side p99 that day was a few hundred milliseconds. The p99 our real-user monitoring showed for the slowest page was over 3 seconds.

What we changed after that complaint

We changed the dashboard first, since that was cheap. The average is gone from the top row, replaced by p50, p99 and p99.9 per endpoint, plus request count. The first week that was up, two endpoints nobody had ever worried about turned out to have a p99.9 over 5 seconds. One was waiting on a connection pool that was sized for a traffic level we’d passed about a year earlier. The other was a query that was fine for 99.8% of customers and took seconds for the handful of very large ones, which is a different kind of tail, because it’s always the same few accounts, and they’re usually the ones paying you the most.

Then we started writing latency goals as percentiles: “p99 under 300 ms for these endpoints” rather than “fast”. I’d love to say we hit them all. We’re working on it.

The customer, for the record, was one of those very large accounts.