Recording histograms and retaining slow samples

HdrHistogram

HdrHistogram is Gil Tene’s library, written first in Java and since ported to C, Go, Rust and others; the Rust crate is hdrhistogram, at version 7. Its constructor takes three numbers: the lowest discernible value, the smallest difference worth telling apart, here 1 ns; the highest trackable value, here 1 s; and the significant figures, here 3. From them it works out the buckets and allocates every counter at once, 21,504 counters for these arguments, and writes them all to zero, so their pages are faulted in when it is built and not when it is first used. The type parameter is the counter: u64 counters cannot fill in any run a person would wait for, and narrower ones, which save memory, saturate rather than wrap when they do. The capstone’s use of it is this:

use hdrhistogram::Histogram;

/// Before the run: every byte the histogram will ever use.
pub fn new_hist() -> Histogram<u64> {
    // 1 ns to 1 s at 3 significant figures: 21,504 counters, about 170 KB
    Histogram::<u64>::new_with_bounds(1, 1_000_000_000, 3).unwrap()
}

/// In the loop, after the timed region: a few branches, a leading_zeros, one add.
#[inline]
pub fn record(h: &mut Histogram<u64>, ns: u64) {
    h.saturating_record(ns);      // above 1 s counts as 1 s: never lost, never allocates
}

/// After the run, on the main thread: per-thread histograms added counter by counter.
pub fn merge(per_thread: &[Histogram<u64>]) -> Histogram<u64> {
    let mut all = new_hist();
    for h in per_thread {
        all.add(h).unwrap();      // same bounds, so the sum is exact
    }
    all
}

pub fn report(name: &str, h: &Histogram<u64>) {
    println!("{name:>8}: n {} p50 {} p99 {} p99.9 {} max {} ns",
             h.len(), h.value_at_quantile(0.50), h.value_at_quantile(0.99),
             h.value_at_quantile(0.999), h.max());
}

record(v) returns an error for a value above the highest trackable one and leaves it uncounted; saturating_record(v) counts it at the top instead, so a 5 s stall appears as a sample of 1 s, which is wrong in size but not in count, and a max of exactly 1 s says the bounds were too narrow. Both are a compare or two, the index arithmetic above and one increment, 10–30 ns with no allocation. There is also Histogram::new(3), which takes no bounds, starts small and grows when a larger value arrives: a reallocation inside whichever record meets the first large value, which is the one place it must not happen.

The queries walk the counters. value_at_quantile(0.99) sums counts from the bottom until it reaches 99% of len(), the total count, and returns the top of that sub-bucket, at most 10–20 µs for 21,504 counters; value_at_percentile(99.0) is the same question in percent. max() is the largest value recorded, to the same 0.1%, and mean() is there for completeness. add, also written +=, adds one histogram’s counters to another’s, exactly when the two have the same layout; the result’s p99 is the p99 of all the samples together, to the same precision, which averaging two p99s is not.

Recording without allocating

Three habits keep a histogram out of the number it holds. It is built before the run, on the thread that will record into it, so its 170 KB is allocated and faulted in once, from the core that will use it, and no record ever calls the allocator. It is recorded into only after the last clock read of the timed region: the ticks are converted to nanoseconds and counted once the interval is closed, so the record delays the next message, a little, and never sits inside this one.

And each thread has its own. A record into a histogram that only one thread writes is a plain increment of a line no other core touches. A histogram shared between the feed and strategy threads would need an atomic add for every record, a read-modify-write that must take the counter’s line from whichever core had it last, 50–100 ns whenever the two alternate, the threads chapter’s one-writer rule broken for the sake of a statistic. So the feed thread keeps its histograms, the strategy thread keeps its own, the gateway its own, and the main thread adds them together after join, when nothing is running.

What a histogram cannot tell you

A histogram has no time in it. It knows that one sample took 2.1 ms, to within 2 µs, and not which message that was, when it arrived, or whether the ten slowest came in one burst or ten minutes apart. Separate histograms per stage do not say whether the slow totals were slow in the hop or in the think, because each has forgotten which sample was which. And a histogram of a whole run blends its minutes: a p99 that doubles after ten minutes, when the package has heated and its clock has dropped, comes out as one moderate p99.

What it forgets is kept beside it, in fixed memory. The worst N samples, with the sequence number of the message each belongs to, fit in a small array:

/// The N largest samples, each with its sequence number, in fixed memory.
pub struct Worst<const N: usize> {
    v: [(u64, u64); N],   // (ns, seq)
    min_at: usize,        // where the smallest of the N is
}

impl<const N: usize> Worst<N> {
    pub fn new() -> Self { Worst { v: [(0, 0); N], min_at: 0 } }

    #[inline]
    pub fn offer(&mut self, ns: u64, seq: u64) {
        if ns <= self.v[self.min_at].0 { return; }     // nearly always: one compare
        self.v[self.min_at] = (ns, seq);               // replace the smallest kept
        self.min_at = (0..N).min_by_key(|&i| self.v[i].0).unwrap();  // N compares
    }
}

Once the run has a hundred slow samples, nearly every message costs one compare against the smallest of them, about 1 ns; only a sample slower than that pays the scan of the hundred, about 100 ns, and such samples become rarer the longer the run goes. With the sequence numbers the slow messages can be found in the replay file and run again, alone, with every stage stamped. For drift, the run keeps one histogram per interval rather than one in all: per second, a 20-second replay is 20 histograms, 3.4 MB at three significant figures or 0.5 MB at two, and the p99 of each second, plotted in order, shows a run that slowed down, a once-a-minute job on a neighbouring core, or a warm-up that lasted longer than assumed. A program that never stops does the same by swapping in a fresh histogram at each interval and handing the full one to another thread to report, so the hot thread never pauses its recording.