Measuring Latency Correctly

Latency distributions in a trading system are multi-modal and heavy-tailed. There is a fast mode — warm caches, no contention, the code path you benchmarked — and a zoo of slow modes: a page fault on fresh memory, an interrupt landing on the engine core, a cache-miss storm after a burst, a timer tick, a TLB shootdown, a neighbour thread on the SMT sibling. The mean blends all of them into a number that no request ever experienced.

A concrete example: 99% of orders take 2 µs and 1% take 500 µs. The mean is 0.99 × 2 + 0.01 × 500 ≈ 7 µs. Nothing took 7 µs. The p50 is 2 µs, p99 sits right on the boundary between the modes, and p99.9 is 500 µs. The only honest summary is the shape: p50, p99, p99.9, p99.99, max, and the sample count.

Why the tail matters more here than in most software:

• Frequency. A market maker re-quoting 1,000 times a second sees its p99.9 once every second. The slow update is precisely the one that gets picked off by a faster participant.
• Fan-out. If an order passes through N stages that are each independently slow 1% of the time, the chance that at least one is slow is 1 − 0.99^N: about 5% for N = 5, and 63% for N = 100. Tails compound; means don't tell you that.
• Correlation. Slow events cluster. A market-data burst makes everything slow at once — which is exactly when the money is made or lost.

A closed-loop load generator has a fixed number of clients, and each sends a request, waits for the response, then sends the next. Throughput is an output of the experiment. An open-loop generator sends requests on a schedule that does not depend on responses — every 2 µs, or with Poisson arrivals at a mean rate — so throughput is an input and queueing is allowed to happen.

Real order flow is open loop. The market does not wait for your engine to finish before the next order arrives.

Now Gil Tene's thought experiment. A system serves 100 requests per second at 1 ms each for 100 seconds, then freezes completely for 100 seconds.

• Closed loop records 10,000 samples of 1 ms and one sample of 100 s. Mean ≈ 11 ms. p99.99 ≈ 1 ms. The report says the system is excellent.
• Open loop knows 10,000 more requests were due during the freeze. They waited 100 s, 99.99 s, …, 0.01 s. With 20,000 samples: p50 ≈ 1 ms, p75 ≈ 50 s, p99 ≈ 98 s, mean ≈ 25 s.

Same system, same freeze. The closed-loop tool coordinated with the system under test: it stopped measuring exactly when things were bad. That is coordinated omission.

Run the same experiment at a smaller scale below. Drag the stall from 0 to a second and watch the closed loop's p99 barely move while the open loop's p99 climbs into milliseconds. The lanes at the top show why: during the stall the closed loop simply has nothing in flight.

Where it hides in code you have written:

// Every microbenchmark loop ever written:
for _ in 0..n {
    let t0 = clock.now();
    engine.submit(order());          // if this stalls for 1 ms...
    hist.record(clock.now() - t0);   // ...you record ONE slow sample, and the
}                                    // ~500 orders that would have arrived are never sent

That loop answers "how long does submit take back-to-back" — a perfectly good question, and what criterion-style benchmarks are for. It does not answer "what latency does an order see under load". Two more hiding places: a gateway that timestamps on read() misses the time a request sat in the socket buffer, and a pipeline that records once per batch misses the queueing of every message behind the first.

The week 2 histogram used logarithmic buckets. An HDR (high dynamic range) histogram makes the idea precise: bucket by power of two (the magnitude), then split each power of two linearly into 2^k sub-buckets. With 2,048 sub-buckets you get about three significant decimal digits — a relative error of roughly 0.1% — at every scale from 1 ns to an hour:

const SUB_BITS: u32 = 11;              // 2048 sub-buckets ≈ 3 significant digits
const SUB_HALF: usize = 1 << (SUB_BITS - 1);

fn index(v: u64) -> usize {
    // Magnitude: how many halvings until v fits below 2^SUB_BITS (0 for small values).
    let mag = (64 - (v | ((1 << SUB_BITS) - 1)).leading_zeros()) - SUB_BITS;
    let sub = (v >> mag) as usize;      // [0, 2048) when mag == 0, else [1024, 2048)
    mag as usize * SUB_HALF + sub        // contiguous and monotonic in v
}

Recording is a lzcnt, a shift, an add and an increment — a few nanoseconds, no allocation, no branches worth mentioning. Capping the range at one hour of nanoseconds needs about 34,000 counters (≈270 KB as u64). Histograms with the same layout merge by adding counts, which is exactly what week 19's per-thread histograms need.

Sometimes you inherit data from a closed-loop tool and cannot re-run it. If you know the interval the tool meant to send at, you can estimate the missing samples: when a sample V exceeds the expected interval I, the requests that should have been sent during the stall would have seen V − I, V − 2I, … So you record those too, down to I. HdrHistogram calls this recordValueWithExpectedInterval.

Two caveats that interviewers like to probe:

• It is an estimate that assumes a constant intended rate. Measuring from the intended send time (Day 4) is always better.
• Never apply it to open-loop data. An open-loop measurement already contains the queued requests; correcting it double-counts the stall.

use std::collections::BTreeMap;

/// Exact latency recorder: value (ns) -> count. A real HDR histogram buckets
/// values; an exact map keeps this drill about the correction, not bucketing.
pub struct LatencyLog {
    counts: BTreeMap<u64, u64>,
    total: u64,
}

impl LatencyLog {
    pub fn new() -> Self {
        Self { counts: BTreeMap::new(), total: 0 }
    }

    pub fn record(&mut self, value: u64) {
        *self.counts.entry(value).or_insert(0) += 1;
        self.total += 1;
    }

    pub fn count(&self) -> u64 {
        self.total
    }

    /// Record `value` from a closed-loop client that meant to send one
    /// request every `expected_interval` ns, and back-fill the requests the
    /// stall swallowed: value - I, value - 2I, ... while still >= I.
    /// `expected_interval == 0` means "no correction" (and must not loop).
    pub fn record_corrected(&mut self, value: u64, expected_interval: u64) {
        todo!()
    }

    /// Nearest-rank quantile: the smallest recorded value v such that at
    /// least ceil(q * count) samples are <= v. Clamp q to [0, 1]; q == 0
    /// returns the minimum. An empty log returns 0.
    pub fn value_at_quantile(&self, q: f64) -> u64 {
        todo!()
    }
}

/// Correct a whole closed-loop run after the fact.
pub fn correct_run(raw: &[u64], expected_interval: u64) -> LatencyLog {
    todo!()
}

An open-loop generator has three jobs:

1. Compute intended send times that do not drift. At 3 orders per second the interval is 333,333,333.3 ns; add a rounded interval repeatedly and you lose a nanosecond every three orders. Compute request i's time from i directly.
2. Send on time, or late — but never skip. Do not thread::sleep until the next send: on Linux a normal thread's default timer slack is 50 µs, and the wake-up itself costs microseconds more. Spin on your week 21 clock on a dedicated core. If the generator falls behind, send immediately and keep the intended time; count late sends as a health metric — a generator that is more than a few microseconds late is measuring itself.
3. Measure from the intended time. Put the intended timestamp in the message (or in a side table keyed by sequence number) so whoever observes completion can compute done − intended, no matter how many queues and threads the order crossed.

Constant-rate arrivals are easiest to reason about; Poisson arrivals (week 23) produce bursts and expose queueing earlier. Run both.

The drill models a single FIFO server so you can see the effect with exact numbers. Notice that both models compute the same completion times — the difference between the closed-loop and open-loop reports is purely which timestamp gets subtracted. The closed loop's lost time shows up as send lag, and open-loop latency is exactly closed-loop latency plus that lag.

/// Intended send times for an open-loop generator: `n` requests at
/// `rate_per_sec`, starting at `start_ns`. Request i is due at
/// start_ns + i * 1e9 / rate_per_sec — compute it from i every time so
/// rounding never accumulates (u128 avoids overflow). Rate 0 -> empty.
pub fn schedule(start_ns: u64, rate_per_sec: u64, n: usize) -> Vec<u64> {
    todo!()
}

// The system under test is one FIFO server: request i needs service_ns[i]
// and starts when both (a) it has been sent and (b) request i-1 is done.

/// Closed-loop client (what most tools do): it wants to send at intended[i]
/// but cannot send before response i-1 is back, so it sends at
/// max(intended[i], done[i-1]). Report latency from the ACTUAL send time.
pub fn closed_loop_latencies(intended: &[u64], service_ns: &[u64]) -> Vec<u64> {
    todo!()
}

/// How late the closed-loop client sent each request: actual send - intended.
pub fn send_lag(intended: &[u64], service_ns: &[u64]) -> Vec<u64> {
    todo!()
}

/// Open-loop client: every request is sent exactly at intended[i] and may
/// queue at the server. Report latency = completion - intended[i].
pub fn open_loop_latencies(intended: &[u64], service_ns: &[u64]) -> Vec<u64> {
    todo!()
}

Warmup. The first seconds of any run pay one-off costs: page faults on freshly allocated memory, cold caches and TLBs, untrained branch predictors, lazy initialisation, the CPU ramping its clock up from idle. Discard a warmup period, then check you reached a steady state: compute p50 and p99 per one-second window and make sure they stop drifting before you start recording.

Sample counts. A percentile is only as good as the number of samples beyond it. p99.9 of 1,000 samples is decided by the single largest one or two values. A workable rule: aim for at least ~100 samples in the tail beyond the quantile — about 100,000 samples for p99.9 and a million for p99.99 — and repeat the run several times to see the spread between runs.

Utilization. Latency is a function of offered load. In the simplest queueing model (M/M/1), mean response time is S / (1 − ρ) where S is service time and ρ the utilization: 2S at 50% load, 10S at 90%, 100S at 99%. Real systems are not M/M/1, but the hockey-stick shape is universal. A single latency number without the offered rate is meaningless; a latency-vs-throughput curve is the real result.

Environment. Release build (with debug info for profiling next week), the performance CPU governor, turbo either always on or always off, the generator and the engine on separate dedicated cores, nothing else running. Record the machine, kernel, Rust version and commit in the report.

Run the week 24 closed-loop benchmark and your new open-loop harness against the same engine build, same machine, same core layout. The gap between them is your coordinated omission — write it down; it is a great interview story.

For each offered rate report: offered and achieved rate, sample count, p50, p99, p99.9, max, and the generator's late-send count. Plot p99 and p99.9 against offered rate and mark the knee. If the curve has a step rather than a knee, you are probably looking at a periodic event (a timer, a housekeeping thread, a background flush) — note it; week 26's profiler will find it.