Headline and stage instrumentation

Worked example: instrumenting the capstone’s loop

The capstone marks five points on each message’s path. In paced mode t0 is the scheduled arrival, computed from the replay file and not read. t1 is read on core 2 after decode, t2 on core 3 inside drain’s closure, t3 on core 3 once per batch after the quote, and t4 on core 6, after the decision, where it cannot touch the headline. So the path carries three reads: t1 and t2 for every message and t3 for every batch, which at 100,000 messages a second is nearly every message. After t3 the strategy thread records four histograms per message, decode, hop, think and total, at 10–15 ns each while their counters’ lines are in L1, as the common case’s are.

Three reads at 20–30 ns and four records at 10–15 ns are 100–150 ns per message. The prediction for total is a p50 of 150–350 ns, about 300 ns, so the instruments would add a third to a half of the number they report, and spend 10–15% of the budget, three times the observer budget. Two of the three reads, t1 and t2, sit between t0 and t3 and are inside total itself, 40–60 ns of it; the records sit outside it but on the strategy’s core, so in a burst every message behind the first waits for its predecessors’ records too. And t2’s fence, inside the closure, stops the core overlapping one apply with the next across a batch.

So the capstone builds two ways. A Cargo feature, a named switch declared in the crate’s Cargo.toml with a line stages = [] under [features] and chosen at build time with --features stages, decides whether the stage reads and records exist:

use hdrhistogram::Histogram;

/// A stage's histogram and the sequence number of its slowest message, which
/// the histogram alone forgets.
pub struct Stage {
    pub h: Histogram<u64>,
    pub max: u64,
    pub max_seq: u64,
}

impl Stage {
    /// `saturating_record`, plus one compare to remember who set the max.
    #[inline]
    pub fn saturating_record(&mut self, ns: u64, seq: u64) {
        self.h.saturating_record(ns);
        if ns > self.max { self.max = ns; self.max_seq = seq; }
    }
}

/// The strategy thread's histograms, made on its own core before the first message.
pub struct Hists {
    pub decode: Stage,            // t1 - t0, stages build only
    pub hop: Stage,               // t2 - t1, stages build only
    pub think: Stage,             // t3 - t2, stages build only
    pub total: Histogram<u64>,    // t3 - t0: the headline, every build
    pub worst: Worst<100>,        // the slowest totals, with their sequence numbers
    pub dropped: u64,             // orders refused by a full output ring: must stay 0
}

/// A stage stamp: a fenced read in a build made with `--features stages`;
/// in any other build, a constant the compiler folds away.
#[inline(always)]
pub fn stage() -> u64 {
    if cfg!(feature = "stages") { now() } else { 0 }
}

cfg!(feature = "stages") is a constant, true or false for the whole build, so the optimiser deletes the branch it can never take; the three stage records sit in the strategy’s loop under #[cfg(feature = "stages")], which leaves them out of the headline build before it is compiled, so the headline binary contains neither the reads nor the three records. The headline build keeps t0, which costs nothing in paced mode, the one t3 per batch, and the total record: 30–50 ns per message, of which only the closing read is inside the number, at the observer budget’s edge and not past it. The stages build gives the breakdown, and the difference between its total and the headline build’s total, run on the same file, is the measured cost of the stage timers, 40–60 ns at the p50 if the arithmetic above is right.

Seeing it

Build both and run each the same way:

cargo build --release                                               # t0 and t3 only
cargo build --release --features stages --target-dir target/stages # all five points
for run in target/release/run target/stages/release/run; do
    sudo perf stat -a -C 3 -e cycles,instructions,L1-dcache-load-misses \
        -- $run --flat --records 2000000
    $run --paced --records 2000000
done

-a -C 3 counts everything that ran on core 3 while the command ran, which on an isolated core is the strategy thread and nothing else; counting a whole machine needs root, or the kernel’s perf_event_paranoid setting at 0 or below. In a flat run the strategy works as fast as messages come, so the counts divided by the 2,000,000 records are its cost per message, spinning included when it is the faster thread. Predict first: the stages build should add 60–100 instructions and 200–350 cycles a message on core 3, the t2 read and three records, and a few L1 misses per thousand messages for the three extra histograms’ lines; and the flat run’s updates per second, which run prints, should fall by about the same proportion if the strategy is the slower thread. The paced runs give the figure that matters: the stages build’s total p50 minus the headline build’s, predicted at 40–60 ns, with a larger gap at the p99, where bursts make each message wait for the records of those ahead of it. Then run the headline build paced once more under sudo perf record -F 4000 -C 3 -g --, and compare its total p99 with the plain run’s.

Read more: Brendan Gregg, Systems Performance: Enterprise and the Cloud, 2nd edition (Addison-Wesley, 2020), discusses in its chapters on methodology and on observability tools what each kind of tool, counters, profilers and tracers, costs the system it observes, and why tracing every event is the expensive end. The perf tutorial on the kernel’s perf wiki, https://perf.wiki.kernel.org/index.php/Tutorial, explains counting and sampling, event multiplexing and the scaling of counts, and the sampling frequency options.