measuring performance

the picture

your commute is "25 minutes on average". once a month there's an accident and it's two hours. when you have a flight to catch, which number do you plan around? the average doesn't even hint that the two-hour day exists. that's the whole problem with averages: they're dominated by the boring majority and they smear the rare disaster into a rounding error.

servers have accident days constantly. a GC pause, a cache miss storm, a lock convoy, a slow disk. each one is rare per request, and each one is exactly what a user remembers.

a real distribution

here's a tiny "request" (build a HashMap of 40 entries, walk it), called two million times in a row, each call timed on its own:

import java.util.*;
 
public class Latency {
    static long sink;
 
    static long handle(int id) {
        HashMap<String, Integer> m = new HashMap<>();
        for (int i = 0; i < 40; i++) m.put("item-" + (id + i), i);
        long sum = 0;
        for (Map.Entry<String, Integer> e : m.entrySet()) sum += e.getKey().hashCode() ^ e.getValue();
        return sum;
    }
 
    public static void main(String[] args) {
        int warm = 300_000, n = 2_000_000;
        for (int i = 0; i < warm; i++) sink += handle(i);   // let the JIT finish first
        long[] lat = new long[n];
        for (int i = 0; i < n; i++) {
            long t0 = System.nanoTime();
            sink += handle(i);
            lat[i] = System.nanoTime() - t0;
        }
        long[] s = lat.clone();
        Arrays.sort(s);
        System.out.printf("mean %.0f ns%n", Arrays.stream(lat).average().orElse(0));
        for (double p : new double[] {50, 90, 99, 99.9, 99.99})
            System.out.printf("p%s %d ns%n", p, s[(int) Math.ceil(p / 100 * n) - 1]);
        System.out.printf("max %d ns  (sink %d)%n", s[n - 1], sink & 1);
    }
}

no output shown because it changes every run. here's one run, with -Xmx64m, as a histogram:

look at where the mean is: 855 ns, right next to the median. by the mean, this code is fine. and it mostly is. but one request in ten thousand took over 100 µs, and the slowest took 225 µs, and the mean has no way of telling you. those requests barely move it: the worst one shifted it by about a tenth of a nanosecond.

the bump is the garbage collector. in a rerun with -Xlog:gc (reading GC logs), G1 logged 244 young pauses of 0.1 to 0.4 ms while the loop ran, which is about how many requests landed out there. that rerun also had a p99.99 of 155 µs and a max of 2.3 ms. the tail of a distribution is noisy from run to run, which is one more reason to look at the whole shape instead of one number.

why the tail matters more than it looks

"p99" sounds like an edge case: one percent of requests, who cares. but a user doesn't make one request. loading one page in a typical app fans out into dozens of calls to backends, caches and databases, and the page is as slow as its slowest call.

forty calls per page, and a third of all page loads include a p99 call. that's why big services set their targets on p99 and p99.9, and why "our average latency is 20 ms" is not a defence when users say the site feels slow.

coordinated omission

now the subtle one. here's how most hand-written load tests work: send a request, wait for the response, record how long it took, wait for the next tick, repeat. it looks completely reasonable.

i wrote exactly that: a loop that wants one request every 10 ms for 5 seconds, against a "server" that answers in 1 ms, except that request #200 hits a one-second stall (think GC pause). here's what the loop recorded, next to what callers would actually have experienced:

requests the loop actually sent: 401 of 500
p50.0  naive     1000 us   corrected     1000 us
p90.0  naive     1000 us   corrected   551000 us
p99.0  naive     1001 us   corrected   956000 us
p99.9  naive  1008072 us   corrected  1001000 us
p100.0 naive  1008072 us   corrected  1001000 us

the naive loop's p99 is one millisecond. the honest p99 is almost a second. same system, same stall.

the name comes from Gil Tene: the load generator coordinates with the system under test (it backs off whenever the system is slow) and so omits exactly the samples that would have shown the problem. the system effectively decides which of its own bad moments get recorded.

the fixes:

• measure from the intended start time, not the moment you actually managed to send. that's what the corrected column does: a request scheduled at 2.01 s that could only start at 3.0 s waited 990 ms, and it's recorded that way.
• use an open-model load generator that keeps sending on schedule no matter what (wrk2, Gatling's open injection profiles, k6's arrival-rate executors), instead of a fixed pool of users that each wait for their own response.
• record into a histogram that can do the correction for you: HdrHistogram's recordValueWithExpectedInterval back-fills the samples a stalled loop missed.

the short list

1. look at the distribution. a histogram, on log scales, before any single number.
2. report percentiles and the max, with the sample count. p50, p90, p99, p99.9 are a good default.
3. never average percentiles. merge histograms, then compute.
4. measure from the intended start time, and drive load open-loop.
5. warm up and know your environment. the JIT changes the numbers for the first seconds (the JIT), GC changes the tail (choosing a collector), and a laptop is not a server.
6. for tiny pieces of code, don't use a loop and nanoTime at all. the JIT will happily delete the code you're timing. that's the next chapter.