Measuring Latency: Percentiles and Coordinated Omission

Latency is the time one operation takes, from request to response. Throughput is the number of operations completed per unit of time. A system can have high throughput and bad latency at once, and the latency that matters to users and trading strategies is the slow tail, not the average. This lesson shows how to summarize latency with percentiles, record it with HdrHistogram, and avoid coordinated omission, the most common error in latency tests.

Item	Purpose
Percentile (p50, p99, p99.9)	The value below which that share of samples falls
Max	The worst sample; often the number that hurts
`org.HdrHistogram.Histogram`	Records values with fixed relative precision and constant memory
Coordinated omission	A load generator that waits for slow responses skips the samples that would show the slowness
`recordValueWithExpectedInterval`	Adds the missing samples while recording
`System.nanoTime`	Monotonic clock for elapsed time

Every example uses synthetic latency values in microseconds, so the output is the same on every machine. Real tests record measured values the same way.

Example 1: averages hide the tail

A percentile pN is the smallest value such that at least N% of the samples are at or below it (the nearest-rank definition). With 1,000 samples, p99 is the 990th smallest value.

Java

import java.util.Arrays;

public class AverageVsPercentile {
    static long percentile(long[] sorted, double p) {
        int rank = (int) Math.ceil(p / 100.0 * sorted.length);   // nearest rank, 1-based
        return sorted[Math.max(rank, 1) - 1];
    }

    public static void main(String[] args) {
        long[] micros = new long[1_000];
        for (int i = 0; i < micros.length; i++) micros[i] = 100 + (i % 10);   // 100..109 us
        for (int i = 0; i < 15; i++) micros[i * 61] = 20_000;                 // 15 slow requests: 20 ms
        long[] sorted = micros.clone();
        Arrays.sort(sorted);

        double mean = Arrays.stream(micros).average().orElseThrow();
        System.out.printf("mean  = %.1f us%n", mean);
        System.out.println("p50   = " + percentile(sorted, 50) + " us");
        System.out.println("p90   = " + percentile(sorted, 90) + " us");
        System.out.println("p99   = " + percentile(sorted, 99) + " us");
        System.out.println("p99.9 = " + percentile(sorted, 99.9) + " us");
        System.out.println("max   = " + sorted[sorted.length - 1] + " us");
    }
}

Output

mean  = 402.9 us
p50   = 105 us
p90   = 109 us
p99   = 20000 us
p99.9 = 20000 us
max   = 20000 us

The mean is about four times the median, yet no request took that long: it describes no real request. p50 and p90 show the normal case, p99 and above show the 1.5% of slow requests. A page that makes 100 backend calls hits the p99 of the backend on most page loads, which is why services set targets on p99 and p99.9.

Example 2: recording with HdrHistogram

HdrHistogram stores counts in buckets whose width grows with the value, so every value is kept to a fixed number of significant decimal digits. Memory depends on the range and precision, not on the number of samples, and recording is a few array operations with no allocation.

Java

import org.HdrHistogram.Histogram;

public class HdrBasics {
    public static void main(String[] args) {
        // Track 1 us .. 60 s (in us) with 3 significant digits.
        Histogram h = new Histogram(60_000_000L, 3);
        for (int i = 0; i < 1_000; i++) h.recordValue(100 + (i % 10));
        for (int i = 0; i < 15; i++) h.recordValue(20_000);

        System.out.println("count = " + h.getTotalCount());
        System.out.println("p50   = " + h.getValueAtPercentile(50));
        System.out.println("p99   = " + h.getValueAtPercentile(99));
        System.out.println("p99.9 = " + h.getValueAtPercentile(99.9));
        System.out.println("max   = " + h.getMaxValue());
        System.out.println("20000 and 20001 share a bucket: "
                + h.valuesAreEquivalent(20_000, 20_001));
        System.out.println("100 and 101 share a bucket: " + h.valuesAreEquivalent(100, 101));
    }
}

Output

count = 1015
p50   = 105
p99   = 20015
p99.9 = 20015
max   = 20015
20000 and 20001 share a bucket: true
100 and 101 share a bucket: false

With 3 significant digits, values up to 2,047 are exact, and larger values are reported as the highest value in their bucket, which is why 20000 reads back as a slightly larger number. The error is bounded by 0.1% of the value. Histograms from different threads or hosts can be merged with add, which averages of percentiles cannot (the mean of two p99s is not the p99 of the combined data).

Example 3: throughput and latency under load

A single server with a fixed service time shows how the two quantities relate. While arrivals are slower than service, latency equals the service time. When arrivals come faster than the server can serve them, a queue forms, throughput stops growing, and latency grows without bound.

Java

public class QueueSimulation {
    static void run(long arrivalGapUs, long serviceUs, int requests) {
        long serverFreeAt = 0, maxLatency = 0, lastEnd = 0;
        for (int i = 0; i < requests; i++) {
            long arrival = i * arrivalGapUs;
            long start = Math.max(arrival, serverFreeAt);
            long end = start + serviceUs;
            serverFreeAt = end;
            lastEnd = end;
            maxLatency = Math.max(maxLatency, end - arrival);
        }
        long throughputPerSec = requests * 1_000_000L / lastEnd;
        System.out.printf("gap %4d us: throughput %4d/s, max latency %6d us%n",
                arrivalGapUs, throughputPerSec, maxLatency);
    }

    public static void main(String[] args) {
        int requests = 1_000;
        long serviceUs = 800;                 // server capacity: 1,250 requests/s
        run(2_000, serviceUs, requests);      // 500/s offered
        run(1_000, serviceUs, requests);      // 1,000/s offered
        run(800, serviceUs, requests);        // exactly at capacity
        run(700, serviceUs, requests);        // over capacity
    }
}

Output

gap 2000 us: throughput  500/s, max latency    800 us
gap 1000 us: throughput 1000/s, max latency    800 us
gap  800 us: throughput 1250/s, max latency    800 us
gap  700 us: throughput 1250/s, max latency 100700 us

At a gap of 700 us the throughput stays at the server's capacity and the extra load turns into queueing delay. Throughput tests alone miss this, so a latency result is always reported together with the offered load.

Example 4: coordinated omission in a closed-loop tester

A closed-loop load generator sends a request, waits for the response, and only then sends the next one. If the system stalls, the generator stalls with it and does not send the requests it was supposed to send, so the stall is recorded once. This is coordinated omission: the tester coordinates with the system and omits exactly the bad samples. The simulation plans one request every 1,000 us; every request takes 100 us except one that takes 2 s (for example during a GC pause).

Java

import org.HdrHistogram.Histogram;

public class CoordinatedOmission {
    public static void main(String[] args) {
        Histogram naive = new Histogram(60_000_000L, 3);
        long now = 0;
        int sent = 0;
        long testEnd = 10_000_000;                  // a 10 s test
        while (now < testEnd) {
            long service = (sent == 5_000) ? 2_000_000 : 100;
            naive.recordValue(service);             // measured from actual send time
            sent++;
            long done = now + service;                      // wait for the response
            now = (done + 999) / 1_000 * 1_000;             // then send at the next free slot
        }
        System.out.println("requests sent = " + naive.getTotalCount() + " (planned 10000)");
        System.out.println("p50   = " + naive.getValueAtPercentile(50));
        System.out.println("p99   = " + naive.getValueAtPercentile(99));
        System.out.println("p99.9 = " + naive.getValueAtPercentile(99.9));
        System.out.println("max   = " + naive.getMaxValue());
    }
}

Output

requests sent = 8001 (planned 10000)
p50   = 100
p99   = 100
p99.9 = 100
max   = 2000895

The report says p99.9 is 100 us. A user who sent requests at the planned rate during those 2 s would have seen about 2,000 requests wait for up to 2 s each, so 20% of the planned requests were slow, not 0.01%.

Example 5: correcting with an expected interval

recordValueWithExpectedInterval(value, interval) records the value and, when it is larger than the interval, also records value - interval, value - 2*interval, and so on down to the interval: the latencies of the requests that would have been sent during the stall. copyCorrectedForCoordinatedOmission(interval) applies the same correction to an existing histogram.

Java

import org.HdrHistogram.Histogram;

public class CorrectedHistogram {
    static void print(String label, Histogram h) {
        System.out.printf("%-10s count %5d  p50 %7d  p90 %7d  p99 %7d  max %7d%n", label,
                h.getTotalCount(), h.getValueAtPercentile(50), h.getValueAtPercentile(90),
                h.getValueAtPercentile(99), h.getMaxValue());
    }

    public static void main(String[] args) {
        long intervalUs = 1_000;
        Histogram naive = new Histogram(60_000_000L, 3);
        Histogram corrected = new Histogram(60_000_000L, 3);
        for (int i = 0; i < 8_000; i++) {
            long service = (i == 5_000) ? 2_000_000 : 100;
            naive.recordValue(service);
            corrected.recordValueWithExpectedInterval(service, intervalUs);
        }
        print("naive", naive);
        print("corrected", corrected);
        print("post-hoc", naive.copyCorrectedForCoordinatedOmission(intervalUs));
    }
}

Output

naive      count  8000  p50     100  p90     100  p99     100  max 2000895
corrected  count  9999  p50     100  p90 1001471  p99 1901567  max 2000895
post-hoc   count  9999  p50     100  p90 1001983  p99 1902591  max 2000895

Both corrected histograms hold about 2,000 extra samples spread from 1 ms to 2 s, and p90 and p99 now show the stall. The correction is an estimate: it assumes requests would have arrived at exactly the expected interval. It applies only when the test has a known planned rate.

Example 6: measuring from the intended start time

The direct fix is an open-loop design: each request has an intended start time from the schedule, and latency is measured from that time, not from when it was actually sent. System.nanoTime is the right clock for this because it is monotonic; System.currentTimeMillis follows the wall clock and can jump when the clock is adjusted. Here the clock is a LongSupplier so a test can drive it with scripted values; production code passes System::nanoTime.

Java

import java.util.function.LongSupplier;
import org.HdrHistogram.Histogram;

public class IntendedStart {
    static final class FakeClock implements LongSupplier {
        long nanos;
        public long getAsLong() { return nanos; }
    }

    static void serve(FakeClock clock, int i) {
        clock.nanos += (i == 3) ? 5_000_000 : 100_000;   // request 3 stalls for 5 ms
    }

    public static void main(String[] args) {
        FakeClock clock = new FakeClock();
        LongSupplier time = clock;                         // System::nanoTime in production
        long intervalNs = 1_000_000;                       // one request per ms
        Histogram serviceTime = new Histogram(60_000_000_000L, 3);
        Histogram responseTime = new Histogram(60_000_000_000L, 3);

        long startOfTest = time.getAsLong();
        for (int i = 0; i < 10; i++) {
            long intended = startOfTest + i * intervalNs;
            if (time.getAsLong() < intended) clock.nanos = intended;   // wait for the slot
            long sentAt = time.getAsLong();
            serve(clock, i);
            long doneAt = time.getAsLong();
            serviceTime.recordValue(doneAt - sentAt);
            responseTime.recordValue(doneAt - intended);
        }
        System.out.println("service time  p50 = " + serviceTime.getValueAtPercentile(50) / 1_000 + " us"
                + ", max = " + serviceTime.getMaxValue() / 1_000 + " us");
        System.out.println("response time p50 = " + responseTime.getValueAtPercentile(50) / 1_000 + " us"
                + ", p90 = " + responseTime.getValueAtPercentile(90) / 1_000 + " us");
        System.out.println("requests slower than 1 ms: service " + serviceTime.getCountBetweenValues(1_000_000, Long.MAX_VALUE >> 2)
                + ", response " + responseTime.getCountBetweenValues(1_000_000, Long.MAX_VALUE >> 2));
    }
}

Output

service time  p50 = 100 us, max = 5001 us
response time p50 = 500 us, p90 = 4100 us
requests slower than 1 ms: service 1, response 5

Service time sees one slow request. Response time also counts requests 4 to 7, which were scheduled during the stall and had to wait, which is what a caller experiences. Rules for nanoTime: subtract two readings (b - a, never compare raw values with < across a long run, because the value can overflow), and read it in the same process; its origin is arbitrary.

Example 7: interval reports with Recorder

A long test reports percentiles per interval, so a short stall is not averaged into a whole hour. org.HdrHistogram.Recorder lets a recording thread write while a reporting thread swaps out the interval histogram without locks. The program is single-threaded so the output is fixed.

Java

import org.HdrHistogram.Histogram;
import org.HdrHistogram.Recorder;

public class IntervalReport {
    public static void main(String[] args) {
        Recorder recorder = new Recorder(3);
        Histogram total = new Histogram(3);       // auto-resizing range
        Histogram interval = null;
        long[][] seconds = {
            {100, 1_000},          // value, count for second 1
            {100, 1_000},
            {100, 980},            // second 3 has a GC pause: 20 slow requests
            {100, 1_000},
        };
        for (int s = 0; s < seconds.length; s++) {
            for (int i = 0; i < seconds[s][1]; i++) recorder.recordValue(seconds[s][0] + (i % 20));
            if (s == 2) for (int i = 0; i < 20; i++) recorder.recordValue(15_000);
            interval = recorder.getIntervalHistogram(interval);   // swap, reusing the old one
            total.add(interval);
            System.out.printf("second %d: count %4d  p99 %6d  max %6d%n", s + 1,
                    interval.getTotalCount(), interval.getValueAtPercentile(99), interval.getMaxValue());
        }
        System.out.printf("whole run: count %4d  p99 %6d  p99.9 %6d%n",
                total.getTotalCount(), total.getValueAtPercentile(99), total.getValueAtPercentile(99.9));
    }
}

Output

second 1: count 1000  p99    119  max    119
second 2: count 1000  p99    119  max    119
second 3: count 1000  p99  15007  max  15007
second 4: count 1000  p99    119  max    119
whole run: count 4000  p99    119  p99.9  15007

Second 3 shows the pause in its p99, while the whole-run p99 does not. Tools such as HdrHistogram's HistogramLogWriter save each interval so the run can be plotted over time.

Load generators and tail causes

A load generator is the program that sends requests during a test. Generators that keep a fixed schedule and record from the intended start (open-loop, for example wrk2 or Gatling's open injection profiles) avoid coordinated omission. Generators with a fixed number of users that each wait for a response (closed-loop) need the correction from Example 5 or report only service time.

Common causes of tail latency in a JVM service, each taught in an earlier lesson:

Cause	Mechanism	Lesson
GC pauses	Stop-the-world phases	GC fundamentals, G1
Safepoints and time to safepoint	All threads stop for a VM operation	Safepoints, warmup, deoptimization
JIT warmup and deoptimization	Interpreted or recompiled code after start or a profile change	Safepoints, warmup, deoptimization
Page faults	First touch of memory, swapping	Virtual memory and perf
Context switches	The thread is descheduled or migrated	Processes, threads, and scheduling
Lock contention and queueing	Requests wait behind each other (Example 3)	Locks and synchronizers

JFR events for GC pauses and safepoints (JFR) line up with the slow intervals in Example 7's report, which ties a percentile spike to its cause.

Interview points

Latency is per operation; throughput is operations per time; past capacity, extra load becomes queueing delay.
Averages hide tails; report p50, p99, p99.9, and max, with the offered load.
Percentiles cannot be averaged; histograms can be merged.
HdrHistogram keeps a fixed number of significant digits in constant memory with no allocation per record.
Coordinated omission: a closed-loop tester waits during a stall and omits the samples that would show it.
Correct it with an open-loop schedule and latency from the intended start, or with recordValueWithExpectedInterval when the planned rate is known.
Use System.nanoTime differences for elapsed time; currentTimeMillis can jump.

Summary

pN is the smallest value with at least N% of samples at or below it.
Histogram(highest, digits) sets range and precision; getValueAtPercentile reads results.
recordValueWithExpectedInterval and copyCorrectedForCoordinatedOmission add the missing samples.
Recorder.getIntervalHistogram gives lock-free per-interval histograms.
Tail latency in the JVM comes from GC, safepoints, JIT changes, page faults, context switches, and queueing.