Lab II: Instrumenting a Pipeline End-to-End

Before you start — this lab exercises the whole of Part II at once; the primer pages worth having fresh:

• TSC / rdtsc and cycle→ns calibration — every stamp in the lab is raw cycles: ch00e
• HdrHistogram and percentiles — where the samples land and how to read the output table: ch00e
• Coordinated omission / open-loop load — why the producer paces by intended send time: ch00e
• Cores, pinning, hyperthreads, false sharing — what experiments (b) and (c) actually break: ch00a
• perf counters (page faults, context switches, IPC) — the fingerprints step (d) checks: ch00e

Read those first — 20 minutes there saves an hour here.

Everything from the measurement chapters (ch07–ch11), welded into one runnable artifact: a three-stage pipeline (producer → SPSC → transformer → SPSC → consumer; SPSC = the single-producer single-consumer queues from the microbenchmarks chapter, ch10), TSC-stamped at every hop, aggregated off-path into per-stage HdrHistograms. Then you break it four ways on purpose and watch each break appear in the numbers. This lab is the difference between having read Part II and being able to say things in an interview.

Climb the ladder first. The capstone below arrives fully assembled — calibration, open-loop pacing, off-path aggregation all pre-built — and reading someone else’s finished instrument teaches much less than building each instrument yourself. So three warm-ups come first, one per craft, ~15 minutes each, each a standalone binary in the same crate. Do them in order; every design decision in the capstone will then be something your own hands have already made.

Warm-up 1 — Own your clock (ch07)

The capstone calls calibrate() and moves on. Do it yourself once, and answer the three questions ch07 says every timestamp rests on: is the ratio stable, does it drift, and what does a correct read cost?

Fair warning: this file reaches below the language, so it contains three things a Node developer has likely never typed — a compile-time architecture switch, an unsafe block, and one line of inline assembly. Each is glossed in a comment at first use; the comments are part of the lesson.

Two pictures to hold before you read it.

The fence. A modern CPU does not run your instructions in the order you wrote them: it executes whatever is ready first, and only guarantees the results come out as if they ran in program order. Normally that reordering is free speed. But a timestamp read is an ordinary instruction — the CPU may execute it before the work you meant to time has finished, and the as-if guarantee does nothing to protect a measurement. A fence (lfence on x86, isb on ARM) forbids that: the counter read may not start until every earlier instruction has completed. Without it, your stopwatch can click before the race ends.

Calibration. The cycle counter is a car’s odometer that counts in ticks, not kilometres: it tells you how many ticks passed, never how long a tick is. Calibration is driving a known distance — let the OS clock (which does speak nanoseconds) run for 200ms, count the ticks that elapsed, divide. From then on you own the exchange rate: ticks per nanosecond.

Those pictures say why; here is where each read actually travels:

 USERSPACE                                  │ KERNEL
                                            │
 (1) Instant::now() ─► read the vDSO page ◄─┼── kernel updates this page
     ~20–40ns — the page is kernel data     │   on its own tick; the
     mapped into your process, so no        │   crossing happened earlier,
     boundary is crossed at call time       │   not on your call
 ───────────────────────────────────────────┤
 (2) cycles() ─► rdtsc: copy the TSC        │ (never involved)
     register — ~6–10ns, one instruction,   │
     and the value never leaves the core    │

src/bin/w1_clock.rs:

// Calibrate the cycle counter yourself, then price a fence.
use std::time::Instant;

// The CPU keeps its own tick counter running in hardware — a count that has
// been ticking since boot: no epoch, no unit, just a number, no OS involved.
// This function copies it out. On x86 it
// ticks billions of times a second; ARM's counter can be far coarser (~24MHz
// on some parts — see the note below). Either way: the cheapest timing read you have.
#[inline(always)]   // "paste the body in place of every call" — a function
                    // call costs as much as the thing we're trying to time
fn cycles() -> u64 {
    // Compile-time switch: only the branch for the CPU you're building for
    // exists in the binary at all.
    #[cfg(target_arch = "x86_64")]
    // `unsafe` = "compiler, you can't verify this; I vouch for it". Copying
    // out a counter the CPU maintains anyway is harmless — it just sits
    // outside Rust's safety model. _rdtsc grabs the Time Stamp Counter
    // (TSC), x86's name for that hardware tick counter.
    unsafe { core::arch::x86_64::_rdtsc() }
    #[cfg(target_arch = "aarch64")]
    // Same tick counter, ARM flavour — no library helper exists, so we write
    // the single CPU instruction ourselves; it copies the counter into `v`.
    // (asm! = embed one raw CPU instruction; `mrs` reads a CPU-internal slot;
    // `cntvct_el0` is that counter's name; `out(reg) v` = "put the answer in v".)
    { let v: u64; unsafe { core::arch::asm!("mrs {}, cntvct_el0", out(reg) v) }; v }
}

// Fenced read: every earlier instruction completes before the counter is
// sampled. Without this, the out-of-order CPU can click your stopwatch
// before the work it's supposedly timing has finished (ch07).
#[inline(always)]
fn cycles_fenced() -> u64 {
    #[cfg(target_arch = "x86_64")]
    // _mm_lfence is the fence: the CPU may not start the counter read until
    // every earlier instruction has actually finished.
    unsafe { core::arch::x86_64::_mm_lfence(); core::arch::x86_64::_rdtsc() }
    #[cfg(target_arch = "aarch64")]
    // `isb` (instruction synchronization barrier) — ARM's equivalent fence:
    // everything earlier finishes, then the counter is read.
    { let v: u64; unsafe { core::arch::asm!("isb; mrs {}, cntvct_el0", out(reg) v) }; v }
}

// The odometer calibration from the picture above: drive `ms` milliseconds
// by the OS clock, count the ticks that passed, return ticks (cycles) per ns.
fn calibrate(ms: u64) -> f64 {
    let t0 = Instant::now();
    let c0 = cycles();
    // Busy-wait: keep re-checking the clock in a tight loop rather than
    // handing the core back to the OS — NOT a sleep, NOT a yield. spin_loop()
    // adds the CPU's `pause` hint, an "I'm just waiting" courtesy to the
    // core and its hyperthread sibling.
    while t0.elapsed().as_millis() < ms as u128 { std::hint::spin_loop(); }
    (cycles() - c0) as f64 / t0.elapsed().as_nanos() as f64
}

// Answer ch07's three questions: is the ratio stable, does it drift,
// and what does a correct (fenced) read cost?
fn main() {
    // 1. Three calibrations: is the ratio stable run to run?
    for _ in 0..3 { println!("calibration: {:.4} cycles/ns", calibrate(200)); }

    // 2. Drift: does a 3-second window in cycles agree with the OS clock?
    let ghz = calibrate(200);
    let t0 = Instant::now();
    let c0 = cycles();
    while t0.elapsed().as_secs() < 3 { std::hint::spin_loop(); }
    let os_ns = t0.elapsed().as_nanos() as f64;
    let tsc_ns = (cycles() - c0) as f64 / ghz;
    println!("3s window: os={:.3}ms tsc={:.3}ms drift={:+.1}ppm",
             os_ns / 1e6, tsc_ns / 1e6, (tsc_ns - os_ns) / os_ns * 1e6);

    // 3. What a read costs, unfenced vs fenced.
    let mut raw = Vec::with_capacity(100_000);
    let mut fen = Vec::with_capacity(100_000);
    // wrapping_sub is odometer-rollover math: if the free-running counter
    // ever rolls past its maximum between two reads, wrapping around zero
    // still gives the true distance travelled (plain `-` would panic in
    // debug builds instead).
    for _ in 0..100_000 { let a = cycles(); let b = cycles(); raw.push(b.wrapping_sub(a)); }
    for _ in 0..100_000 { let a = cycles_fenced(); let b = cycles_fenced(); fen.push(b.wrapping_sub(a)); }
    raw.sort_unstable(); fen.sort_unstable();
    println!("read cost   unfenced p50={:.1}ns  fenced p50={:.1}ns",
             raw[50_000] as f64 / ghz, fen[50_000] as f64 / ghz);
}

Read your output against ch07: calibrations agreeing to ~3 decimals means the counter is invariant (it doesn’t change rate with frequency); drift in the low hundreds of ppm is normal crystal error — which is exactly why the capstone recalibrates at every startup rather than hardcoding a GHz. The fence delta is the number that decides your instrumentation budget: it’s what each honest hot-path stamp costs, and it’s why the capstone stamps a handful of points rather than everywhere.

Warm-up 2 — Make the benchmark lie to you (ch08)

The capstone’s producer is open-loop, and one comment tells you why. That’s a claim. This warm-up is the demonstration — and it’s the single most valuable fifteen minutes in Part II, because it makes coordinated omission something you watched happen rather than a term you recite.

One toy system with one injected 100ms freeze, measured two ways. Time flows down; the freeze hits at request #10000 in both lanes:

 time  CLOSED — wait, then send          OPEN — send at timetable ticks
  │
  │  (1) send #9999 ─► reply: 20µs       (1) tick 9999: send ─► 20µs
  │  (2) send #10000 ─► ▓▓▓▓▓▓▓▓         (2) tick 10000: send ─► ▓▓▓▓▓▓▓
  │       100ms STALL — harness          (3) ticks 10001…11000 come due
  │       WAITS; the ~1,000 sends            during the stall: each stamped
  │       due in this gap never exist,       from its INTENDED tick, all
  │       their waits unrecorded             queueing up behind #10000
  │  (3) reply ─► ONE 100ms sample       (4) stall ends, backlog drains:
  │  (4) sends #10001+ bunch up              #10000 records 100ms, #10001
  ▼       here, ~20µs each again             ≈99.9ms … ~1,000 true waits
 closed: (1,2) t0=Instant::now(); service(seq)  (3,4) h.record(t0.elapsed())
 open: (1,2) sleep to intended=start+period·seq  (3,4) h.record(intended.elapsed())

src/bin/w2_co.rs:

// Run: w2_co closed   then   w2_co open
use hdrhistogram::Histogram;
use std::time::{Duration, Instant};

const N: u64 = 20_000;
const RATE_HZ: u64 = 10_000;                 // 100µs between intended sends
const STALL_AT: u64 = 10_000;                // one freeze, mid-run
const STALL: Duration = Duration::from_millis(100);

// The system under test: ~20µs of "work" per request, except one injected
// 100ms freeze at request STALL_AT.
fn service(seq: u64) {
    if seq == STALL_AT { std::thread::sleep(STALL); }        // the freeze
    else { std::thread::sleep(Duration::from_micros(20)); }  // normal work
}

// Drive N requests through service() closed- or open-loop; print percentiles.
fn main() {
    let mode = std::env::args().nth(1).unwrap_or_else(|| "closed".into());
    let mut h = Histogram::<u64>::new_with_bounds(1, 60_000_000_000, 3).unwrap();
    let period = Duration::from_nanos(1_000_000_000 / RATE_HZ);
    let start = Instant::now();

    for seq in 0..N {
        if mode == "closed" {
            // CLOSED LOOP: wait for the reply, then send the next request.
            // During the freeze we simply stop sending, so
            // the requests that *should* have gone out never exist to measure.
            let t0 = Instant::now();
            service(seq);
            h.record(t0.elapsed().as_nanos() as u64).unwrap();
        } else {
            // OPEN LOOP: a bus timetable — send times fixed in advance whether
            // or not the system keeps up. Latency runs from the INTENDED send
            // time, so the freeze lands in every sample that was due during it.
            let intended = start + period * seq as u32;
            let now = Instant::now();
            if intended > now { std::thread::sleep(intended - now); }
            service(seq);
            h.record(intended.elapsed().as_nanos() as u64).unwrap();
        }
    }

    let us = |v: u64| v as f64 / 1000.0;
    println!("{mode:>6}: n={} p50={:.1}us p99={:.1}us p99.9={:.1}us max={:.1}us",
             h.len(), us(h.value_at_quantile(0.50)), us(h.value_at_quantile(0.99)),
             us(h.value_at_quantile(0.999)), us(h.max()));
}

Real output from this exact code:

closed: n=20000 p50=29.3us p99=48.3us p99.9=52.0us max=105054.2us
  open: n=20000 p50=47.6us p99=91029.5us p99.9=103678.0us max=105054.2us

Sit with that. Same system. Same 100ms freeze. Same sample count. The closed-loop harness reports a p99.9 of 52µs — a system that looks healthy — the left lane of the diagram, where the stall’s victims never existed to be measured. Only max betrays it, which is precisely why ch08 says a max wildly detached from your percentiles is a coordinated-omission fingerprint, not an outlier to discard. The open lane’s thousand victims each carry their share of the freeze: p99 of 91ms, p99.9 of 104ms — the truth.

Now you know what the capstone’s let intended = start + seq * interval; line is defending against, and you have the sentence: “I’ve built the same measurement both ways over an injected stall — closed loop hid a 100ms freeze behind a 52µs p99.9.”

Warm-up 3 — Bench one component, then distrust it (ch10)

The capstone uses rtrb and mentions in passing that you could swap in your own queue “to bench it.” Benching it is a skill, and it has a trapdoor.

The trapdoor has a name: dead-code elimination. If a computation’s result is never used, the optimizer doesn’t make the work faster — it deletes it, loop and all, and your benchmark times an empty shell. black_box is a wall the optimizer can’t see through: it must assume the value going in gets used and the value coming out could be anything, so the work on your side of the wall has to actually happen.

And hold this picture of what the queue benchmark below does — and doesn’t — exercise:

             core N — the whole benchmark lives in one lane
 ┌────────────────────────────────────────────────────────┐
 │ (1) p.push(i)  ─► ring slot lands in this core's L1    │
 │ (2) c.pop()   ◄── same slot, same L1, still warm       │
 └────────────────────────────────────────────────────────┘
  ── core boundary ── never crossed: that's why push+pop benches
  at single-digit ns below — and why the number says nothing about
  the cross-core case, where every handoff must move a cache line

src/bin/w3_bench.rs:

// black_box: the wall from the paragraph above — the optimizer must actually
// compute what goes in and may assume nothing about what comes out, so the
// measured work can't be deleted or hoisted out of the loop.
use std::hint::black_box;
use std::time::Instant;

// Cycle-counter read, exactly as in warm-up 1 (rdtsc / `mrs cntvct_el0`).
#[inline(always)]
fn cycles() -> u64 {
    #[cfg(target_arch = "x86_64")]
    unsafe { core::arch::x86_64::_rdtsc() }
    #[cfg(target_arch = "aarch64")]
    { let v: u64; unsafe { core::arch::asm!("mrs {}, cntvct_el0", out(reg) v) }; v }
}

// Cycles per nanosecond, calibrated as in warm-up 1.
fn calibrate() -> f64 {
    let t0 = Instant::now();
    let c0 = cycles();
    while t0.elapsed().as_millis() < 200 { std::hint::spin_loop(); }
    (cycles() - c0) as f64 / t0.elapsed().as_nanos() as f64
}

const ITERS: u64 = 5_000_000;

// Three benchmarks: one the optimizer deletes, one it can't, one real queue.
fn main() {
    let ghz = calibrate();

    // (1) THE TRAP: nothing consumes the result, so the optimizer deletes the work.
    let t = cycles();
    for i in 0..ITERS { let _ = i * 7 + 3; }
    let dce = (cycles() - t) as f64 / ITERS as f64 / ghz;

    // (2) Same arithmetic, but black_box makes the optimizer believe it's used.
    let t = cycles();
    for i in 0..ITERS { black_box(black_box(i) * 7 + 3); }
    let real = (cycles() - t) as f64 / ITERS as f64 / ghz;

    println!("multiply-add   without black_box: {dce:.3}ns/op   with: {real:.3}ns/op");

    // (3) The component under test: same-thread push+pop, everything hot in L1.
    let (mut p, mut c) = rtrb::RingBuffer::<u64>::new(1024);
    let t = cycles();
    for i in 0..ITERS {
        p.push(black_box(i)).ok();
        black_box(c.pop().ok());
    }
    let spsc = (cycles() - t) as f64 / ITERS as f64 / ghz;
    println!("rtrb push+pop (same thread, hot in L1): {spsc:.2}ns/op");
}

Real output:

multiply-add   without black_box: 0.000ns/op   with: 0.331ns/op
rtrb push+pop (same thread, hot in L1): 2.68ns/op

0.000ns/op. Dead-code elimination, caught red-handed in your own harness — ch10’s first trap, on your box, in ten seconds. Any benchmark result at or near zero is not a fast implementation; it is an absent one.

Then apply ch10’s plausibility ladder to the 2.68ns: the diagram above shows why single-digit ns is physically reasonable — no boundary crossed. But now predict before you measure: split producer and consumer across cores and the floor jumps to tens of ns. If a cross-core version still reports 2.68ns, the harness is lying (compiler hoisting, or the consumer never actually seeing the producer’s writes). This is the habit ch10 exists to build: a benchmark number is a hypothesis you test against physics, not a result you report. In production use criterion for this (outlier classification, confidence intervals); the hand-rolled version here is to make the trapdoor visible.

The design

  core 1           │ core 2              │ core 3             │ unpinned core
  producer         │ transformer         │ consumer           │ aggregator
                   │                     │                    │
 (1) t0 = intended │                     │                    │
 (2) p1.push ═q1═══╪═► (3) c1.pop        │                    │
     Msg{t0}       │   (4) t1 = rdtsc    │                    │
                   │   (5) work ~100ns   │                    │
                   │   (6) t2 = rdtsc    │                    │
                   │   (7) p2.push ═q2═══╪═► (8) c2.pop       │
                   │       Msg{t0,t1,t2} │  (9) t3 = rdtsc    │
                   │                     │ (10) pa.push ═ring═╪═► (11) ca.pop
                   │                     │      Sample{deltas}│   cycles→ns →
 ── core boundary ─┴─ core boundary ─────┴── core boundary ───┴  HdrHistograms
  d_q1 = t1−t0  spans cores 1→2 (queue + wake)   d_work = t2−t1  inside core 2
  d_q2 = t3−t2  spans cores 2→3                  d_e2e  = t3−t0  spans them all

• The SPSC rings are drawn on the core boundaries because that’s where they live: the only shared state between adjacent lanes. Hop (10)→(11) is the “event ring drained by a cold thread” pattern from ch11.
• All hot-path stamps are raw cycles; the aggregator’s cycles→ns conversion uses a startup calibration (ch07, ch08).
• The producer is open-loop — warm-up 2’s right-hand lane, wired in: sends at intended times paced by cycles (coordinated omission, ch08).
• Runs on x86_64 (rdtsc) and aarch64 (cntvct_el0, ARM’s counterpart to the TSC), so you can develop on the Mac and take real numbers on the Linux box. Believe only the Linux numbers: macOS won’t let you pin threads to cores, and the ARM counter is far coarser than the TSC (quantified in the notes below).

Cargo.toml

[package]
name = "pipeline-lab"
version = "0.1.0"
edition = "2021"

[dependencies]
rtrb = "0.3"            # proven SPSC ring; warm-up 3 benches it
hdrhistogram = "7"
core_affinity = "0.8"

[profile.release]
debug = true            # keep symbols for perf (the profiling chapter)

The three warm-up binaries (src/bin/w1_clock.rs, w2_co.rs, w3_bench.rs) and the capstone (src/main.rs) all live in this one crate and share these dependencies. Run a warm-up with cargo run --release --bin w1_clock.

Four pictures before the code. The capstone reads much faster with these held in your head; every comment below hangs off one of them.

The 64-byte cache line. A core never fetches memory one byte at a time — it fetches a fixed 64-byte block called a cache line, and only one core may hold a line’s writable copy at a moment. Put two counters on the same line and two cores that each only touch their own counter still pull the entire line back and forth on every bump — the line, not the byte, is the unit of ownership. That’s false sharing (the ping-pong is drawn step by step at experiment (c) below), and the capstone’s SLOTS array is wired to switch it on and off: slots 0 and 1 sit on one line; slots 0 and 16 sit 128 bytes apart, safely on separate lines.

AtomicU64, Relaxed. An AtomicU64 is a counter that many threads may increment at the same instant without a lock — the hardware guarantees no increment is ever lost. Relaxed is the cheapest promise level you can ask for: “count correctly, promise nothing about ordering relative to anything else” — which is all a statistics counter needs.

The rtrb ring. Each queue is a conveyor belt with exactly one loader and one unloader — single producer, single consumer, nobody else allowed to touch it. push sets an item on the belt, pop lifts one off, and if the belt is full, push hands the item back to you inside the error — nothing is ever dropped silently.

pin(). By default the OS scheduler may move a thread to a different core mid-run. Pinning fixes it to one core for the whole measurement, so “which core was it on” stops being a variable in your experiment.

src/main.rs (complete)

use hdrhistogram::Histogram;
use std::sync::atomic::{AtomicU64, Ordering::Relaxed};
use std::time::Instant;

// ---------- cycle counter (the clocks chapter) ----------
// The warm-up 1 read — the CPU's hardware tick counter, a raw count since
// boot: rdtsc on x86; on ARM, inline asm reading `cntvct_el0`.
#[inline(always)]
fn now_cycles() -> u64 {
    #[cfg(target_arch = "x86_64")]
    unsafe { core::arch::x86_64::_rdtsc() }
    #[cfg(target_arch = "aarch64")]
    {
        let v: u64;
        unsafe { core::arch::asm!("mrs {}, cntvct_el0", out(reg) v) };
        v
    }
}

/// Warm-up 1's odometer calibration: drive 200ms by the OS clock, count the
/// ticks that passed, return cycles per nanosecond.
fn calibrate() -> f64 {
    let t0 = Instant::now();
    let c0 = now_cycles();
    while t0.elapsed().as_millis() < 200 { std::hint::spin_loop(); }
    (now_cycles() - c0) as f64 / t0.elapsed().as_nanos() as f64
}

// ---------- pipeline messages ----------
#[derive(Clone, Copy, Default)]
struct Msg { seq: u64, payload: u64, t0: u64, t1: u64, t2: u64 }

#[derive(Clone, Copy)]
struct Sample { d_q1: u64, d_work: u64, d_q2: u64, d_e2e: u64 } // cycles

// ---------- experiment toggles (CLI) ----------
#[derive(Default, Clone, Copy)]
struct Cfg { alloc: bool, no_pin: bool, share_line: bool }

const N: u64 = 2_000_000;       // events per run
const RATE: u64 = 200_000;      // offered rate, events/sec (open loop)
const Q: usize = 4096;          // queue capacity

/// Pin the calling thread to one core: the scheduler may never move it
/// to another core mid-measurement, taking placement out of the experiment
/// (ch00a).
fn pin(core: usize, cfg: &Cfg) {
    if cfg.no_pin { return; }                       // experiment (b)
    if let Some(ids) = core_affinity::get_core_ids() {
        if let Some(id) = ids.get(core) { core_affinity::set_for_current(*id); }
    }
}

// Counter slots: transformer bumps [ti], consumer bumps [ci].
// This array IS the cache-line picture from above. Each slot is an 8-byte
// AtomicU64 (lock-free counter), so index 1 sits 8B away — the SAME 64-byte
// line — while index 16 sits 16*8 = 128B away, safely on its own line
// (128B not 64B because Intel prefetches lines in adjacent pairs).
// share_line picks indices (0,1) — one shared line, experiment (c);
// otherwise (0,16) — separate lines, no ping-pong.
// `[const { ... }; 32]` is the idiom for building an array of atomics at
// compile time (they aren't copyable, so plain `[value; 32]` won't do).
static SLOTS: [AtomicU64; 32] = [const { AtomicU64::new(0) }; 32];

// Wire up the three SPSC rings, spawn the four threads, join, report.
fn main() {
    let cfg = Cfg {
        alloc: std::env::args().any(|a| a == "--alloc"),
        no_pin: std::env::args().any(|a| a == "--no-pin"),
        share_line: std::env::args().any(|a| a == "--share-line"),
    };
    let (ti, ci) = if cfg.share_line { (0usize, 1usize) } else { (0usize, 16usize) };
    let ghz = calibrate();
    eprintln!("calibrated {:.3} cycles/ns; cfg: {:?} {:?} {:?}",
        ghz, cfg.alloc, cfg.no_pin, cfg.share_line);

    let (mut p1, mut c1) = rtrb::RingBuffer::<Msg>::new(Q);
    let (mut p2, mut c2) = rtrb::RingBuffer::<Msg>::new(Q);
    let (mut pa, mut ca) = rtrb::RingBuffer::<Sample>::new(1 << 16);

    // ---- producer: open-loop, paced by intended send time (latency chapter) ----
    let interval = (ghz * 1e9 / RATE as f64) as u64; // cycles between sends
    let producer = std::thread::spawn(move || {
        pin(1, &cfg);
        let start = now_cycles();
        for seq in 0..N {
            let intended = start + seq * interval;
            // Busy-wait to the scheduled tick (spin_loop = pause hint, warm-up 1).
            while now_cycles() < intended { std::hint::spin_loop(); }
            // ..Default::default() = "every field I didn't name gets its zero
            // value" — like spreading in an all-zeroes object literal.
            let mut m = Msg { seq, payload: seq.wrapping_mul(0x9E37_79B9), t0: intended, ..Default::default() };
            // Belt full: push hands the message back inside the error —
            // take it back, wait a beat, set it on the belt again.
            while let Err(rtrb::PushError::Full(v)) = p1.push(m) { m = v; std::hint::spin_loop(); }
        }
    });

    // ---- transformer: dequeue, "strategy" work, enqueue ----
    let transformer = std::thread::spawn(move || {
        pin(2, &cfg);
        for _ in 0..N {
            let mut m = loop {
                if let Ok(m) = c1.pop() { break m; } std::hint::spin_loop();
            };
            m.t1 = now_cycles();
            let mut acc = m.payload;                     // fixed work: ~100ns
            for _ in 0..40 { acc = acc.wrapping_mul(6364136223846793005).wrapping_add(1); }
            if cfg.alloc {                               // experiment (a)
                let v: Vec<u64> = vec![acc; 32];         // heap alloc in hot path
                acc ^= v[31];
            }
            m.payload = acc;
            // Relaxed = "count correctly, promise nothing about order" —
            // the cheapest atomic mode, and all a stats counter needs.
            SLOTS[ti].fetch_add(1, Relaxed);             // stage counter
            m.t2 = now_cycles();
            while let Err(rtrb::PushError::Full(v)) = p2.push(m) { m = v; std::hint::spin_loop(); }
        }
    });

    // ---- consumer: final stamp, ship deltas to cold aggregator ----
    let consumer = std::thread::spawn(move || {
        pin(3, &cfg);
        let mut dropped = 0u64;
        for _ in 0..N {
            let m = loop {
                if let Ok(m) = c2.pop() { break m; } std::hint::spin_loop();
            };
            let t3 = now_cycles();
            SLOTS[ci].fetch_add(1, Relaxed);
            // saturating_sub floors at zero instead of wrapping: if two cores'
            // counter reads ever land a hair out of order, a tiny negative
            // would otherwise wrap into a near-2^64 "latency" and wreck the
            // histogram. A clamped zero beats a corrupt maximum.
            let s = Sample {
                d_q1: m.t1.saturating_sub(m.t0),
                d_work: m.t2.saturating_sub(m.t1),
                d_q2: t3.saturating_sub(m.t2),
                d_e2e: t3.saturating_sub(m.t0),
            };
            if pa.push(s).is_err() { dropped += 1; }     // never block the hot path
        }
        dropped
    });

    // ---- aggregator: cold thread, cycles->ns, HdrHistograms (observability chapter) ----
    let aggregator = std::thread::spawn(move || {
        let mk = || Histogram::<u64>::new_with_bounds(1, 10_000_000_000, 3).unwrap();
        let (mut q1, mut wk, mut q2, mut e2e) = (mk(), mk(), mk(), mk());
        let mut n = 0u64;
        while n < N {
            match ca.pop() {
                Ok(s) => {
                    n += 1;
                    let ns = |c: u64| ((c as f64 / ghz) as u64).max(1);
                    q1.record(ns(s.d_q1)).ok(); wk.record(ns(s.d_work)).ok();
                    q2.record(ns(s.d_q2)).ok(); e2e.record(ns(s.d_e2e)).ok();
                }
                // Nothing waiting: hand the core back to the OS — the
                // opposite of the hot threads' spin. A cold thread can
                // afford that; a hot one never does it.
                Err(_) => std::thread::yield_now(),
            }
        }
        for (name, h) in [("q1+wake", &q1), ("work", &wk), ("q2+wake", &q2), ("e2e", &e2e)] {
            println!("{:8} p50={:>7}ns p99={:>7}ns p99.9={:>8}ns max={:>9}ns",
                name, h.value_at_quantile(0.5), h.value_at_quantile(0.99),
                h.value_at_quantile(0.999), h.max());
        }
    });

    producer.join().unwrap();
    transformer.join().unwrap();
    let dropped = consumer.join().unwrap();
    aggregator.join().unwrap();
    let transformed = SLOTS[ti].load(Relaxed);
    let consumed = SLOTS[ci].load(Relaxed);
    println!("processed: transform={transformed} consume={consumed} (expect {N} each)");
    println!("aggregation ring dropped {dropped} samples (expect 0; >0 means the cold thread fell behind)");
}

Build and run the baseline, pinned, on the Linux box:

cargo run --release                 # baseline
cargo run --release -- --alloc      # experiment (a)
cargo run --release -- --no-pin     # experiment (b)
cargo run --release -- --share-line # experiment (c)

Notes: cores 1/2/3 are assumed free (ideally isolated per Part I); the aggregator is deliberately unpinned. On aarch64 cntvct_el0 ticks at ~24MHz–1GHz, so per-stage resolution is coarser — at 24MHz one tick is ~42ns, bigger than some of the deltas you’re trying to measure — the structure still works, the fine numbers don’t. If dropped is ever nonzero, your aggregator ring is undersized; that counter is itself a lesson from the observability chapter (ch11).

The experiments

Run baseline ≥3 times first; know your run-to-run variance before attributing anything. Then one variable at a time:

(a) --alloc — heap allocation in stage 2. One small Vec per event, and the work path grows a side-trip:

  USERSPACE — core 2, stage-2 work path       │ KERNEL
                                              │
 (1) m.t1 = now_cycles()                      │
 (2) 40× wrapping_mul  (~100ns, fixed work)   │
 (3) --alloc: vec![acc; 32] — ask free list   │
      ├─ usually: slot ready, pointer math,   │
      │  ~20–50ns, kernel never knows ─────┐  │
      └─ sometimes: list empty ── syscall ─┼──┼─► (4) map + zero fresh
         boundary crossed ─────────────────┘  │      pages, page faults —
 (5) m.t2 = now_cycles() ◄────────────────────┼───── microseconds, not ns
  the "sometimes" branch IS the tail: p50 barely moves, p99.9 spikes

Watch work p50 rise modestly (the usual branch) — but watch p99.9 and max: the boundary crossings (free-list refills, madvise calls returning memory to the kernel, occasional page faults) fire episodically. That is why zero-alloc is a tail discipline, not a throughput one.

(b) --no-pin — let the scheduler place threads. Same pipeline, but the lanes stop being fixed — the boundary is now the scheduler’s choice:

  core 2                       │  core 4            (boundary = wherever
  transformer, caches warm     │                     the scheduler decides)
                               │
 (1) c1.pop / work / p2.push … │
 (2) scheduler evicts it ──────┼─► (3) resumes HERE: L1/L2 cold —
     mid-run (another thread,  │       every hot line refetched from
     an IRQ, load balancing)   │       L3 or the old core (~µs of misses)
                               │   (4) or worse: parked on the run queue
                               │       behind someone else — a spinning,
                               │       descheduled consumer takes ms to
                               │       notice new data waiting in its ring

Watch every stage’s p99+ inflate and become bimodal across runs (results cluster into two distinct groups rather than one): sometimes two stages land on SMT siblings of one physical core, sometimes migration (2)→(3) lands mid-burst; q1/q2 wake latencies get noisy — (4) is what “wake” costs when it goes wrong. Nothing in the code changed — only placement. Re-run five times and note the variance explosion; that irreproducibility is the finding. Then close the loop with the profiling chapter’s ftrace silence check (ch09): enable sched_switch/sched_wakeup for a pinned run and again for a --no-pin run. The pinned run’s hot cores trace silent; the unpinned run’s trace names every migration and preemption the histograms felt.

(c) --share-line — stage counters on one cache line. Transformer and consumer now bump adjacent AtomicU64s — the cache line from before the code, in motion:

  core 2 (transformer)             │           core 3 (consumer)
  L1: [ctrA|ctrB…] ← owns the line │  L1: (copy of the same 64B line)
                                   │
 (1) SLOTS[0].fetch_add ───────────┼─► (2) core 3's copy INVALIDATED —
     needs the line writable       │      ctrB rides on the same line
 ─── the 64-byte line transfers ───┼─►    so core 3 must refetch it
                                   │  (3) SLOTS[1].fetch_add ──────────
 (4) core 2's copy INVALIDATED ◄───┼───   needs it back: invalidate,
     …and the line comes back      │      transfer, ~40–100ns each way
  neither core ever reads the other's counter — but the line, not the
  byte, is the unit of ownership, so it ping-pongs on ~every increment

Watch throughput (wall time for the run) degrade and work/q2 medians rise: hops (2) and (4) now tax every bump. Confirm the mechanism with perf c2c record — the slots array shows up with HITM at two offsets on one line (HITM = the line was fetched dirty out of the other core’s cache — the smoking gun of ping-pong; the false-sharing signature from ch09).

(d) [Linux] correlate with perf stat. For baseline vs each experiment:

perf stat -e cycles,instructions,cache-misses,LLC-load-misses,\
context-switches,page-faults -- cargo run --release -- --share-line

Predictions to verify: (a) adds page-faults and instructions; (b) adds context-switches/migrations; (c) tanks IPC on the hot cores and raises cache-misses with flat instruction count — the same instructions are executing, but each one now stalls waiting for the line transfer. Three different fingerprints for three different diseases, visible in counters before you look at code.

(e) [Linux] Profile it — and watch the flamegraph fail you. Counters said what; the profiling chapter’s tools (ch09) say where. The debug = true in your release profile has been waiting for this:

perf record -F 999 -g --call-graph dwarf -- ./target/release/pipeline-lab
perf report --stdio | head -40           # or build a flamegraph from perf script
perf record -F 999 -g -- ./target/release/pipeline-lab --share-line   # compare

Predict first, then look. Prediction: both profiles are dominated by the spin loops — now_cycles, spin_loop, the queue poll — and the baseline and --share-line flamegraphs look nearly identical, even though (c) measurably hurt. That is not a broken tool; it is ch09’s own interview question happening to you. A sampling profiler answers “which instruction was the CPU on,” and under false sharing the CPU is on the same instruction, stalled — the time moved into memory stalls that on-CPU sampling attributes to the very same frames. The counters from (d) saw it (IPC down, cache-misses up, instructions flat) and perf c2c localized it to a cache line. Flamegraph for “which code,” counters for “why it’s slow,” c2c for “which line of memory.” Having run all three on one artifact is the difference between owning a profiler and owning a method.

(f) Close the loop: catch your own outlier (ch11). Everything so far aggregated. Aggregates locate a problem in the distribution and then go quiet about the individual event — but the flight recorder from ch11 exists precisely to answer “what happened during that one.” Extend the lab (~30 lines, the last exercise):

1. Give the aggregator a ring of the last 4,096 Samples (fixed array, wrapping index — it already receives them).
2. On any sample whose d_e2e exceeds a threshold — set it at your measured baseline p99.9 — freeze: stop overwriting, and dump the ring to stderr with per-stage deltas.
3. Run --alloc, which you know produces episodic spikes, and read the dump.

The mechanism you’re building, as dataflow:

  core 3 (consumer)   │           (unpinned) aggregator
                      │
 (1) pa.push(Sample) ─┼─► (2) ca.pop ─► (3) ring[n & 4095] = s
     hot path never   │        (last 4,096 samples, wrapping)
     blocks or knows  │   (4) s.d_e2e > threshold (baseline p99.9)?
     the ring exists  │        │ no → keep overwriting, ring rolls on
                      │        ▼ yes
                      │   (5) FREEZE — stop overwriting; (6) dump ring
                      │       to stderr: the outlier AND its ~4,095
                      │       neighbours, per-stage deltas for each

What to look for is the payoff: the frozen window shows the neighbours of the bad event. Was one event slow in work alone (an allocator slow path), or were twenty consecutive events slow in q2 (the consumer stalled and the queue backed up)? A histogram can never distinguish those two; the ring does it at a glance. That is ch11’s whole argument — histograms locate, the ring says what happened — and you now have it as a thing you built, on a bug you injected, caught by an instrument you wrote.

Expected results (indicative — a modern x86 server, isolated cores; your numbers will differ, your ratios shouldn’t differ much)

The meta-lesson sits in the columns: (a) and (b) are tail diseases, (c) is a throughput/median disease. If you only tracked p50, you’d ship (a) and (b); if you only tracked throughput, you’d ship (a) and (b) and catch only (c). This is the latency-methodology chapter’s argument (ch08), now demonstrated on your own hardware.

Interview narration of the findings

The lab’s product is that you can now narrate cause → measurement → fix in one breath. The template, using experiment (a):

“I decomposed the pipeline with TSC stamps at each hop — cycles carried in the message, converted and histogrammed off-path so instrumentation stayed under a percent of the budget. Baseline e2e was ~600ns p50, 3µs p99.9. Introducing one small allocation in the middle stage left p50 almost untouched but multiplied p99.9 and produced ms-scale maxima; perf stat showed the page faults, and the per-stage histograms put the growth entirely in the transformer’s work delta. That’s the general shape I look for: medians measure the design, tails measure the discipline.”

The same 15-second story for experiment (b):

“Same binary, one flag — I let the scheduler place the threads instead of pinning them. p50 barely moved; p99.9 blew out 5–50×, and differently on every run: results clustered into groups, because some runs landed two stages on hyperthread siblings and others migrated a thread mid-burst. perf stat showed the fingerprint — context switches went from zero to dozens. Nothing in the code changed, so the run-to-run variance itself was the finding, and the ftrace silence check closed it: the pinned run’s hot cores trace empty, the unpinned run’s trace is full of migrations. Placement is a variable; pinning removes it.”

And for experiment (c):

“I moved two ‘independent’ stage counters onto one cache line — transformer and consumer each bumping their own adjacent AtomicU64. Wall time for the run got worse and the work and q2 medians rose a few hundred nanoseconds, because every bump now dragged the line between cores 2 and 3. perf stat showed the fingerprint — IPC down, cache-misses up, instruction count flat: same instructions, each now stalling on a line transfer. perf c2c gave the smoking gun: HITM hits at two offsets on one line of the slots array. Padding the counters 128 bytes apart restored the baseline. That’s false sharing — a median-and-throughput disease, the opposite signature from allocation’s tail disease.”

And the warm-up that earns you the most credit, because most candidates only recite the term:

“I built the same measurement two ways over one injected 100ms stall. Closed-loop — wait for the system, then send — reported a p99.9 of 52µs and a max of 105ms: healthy percentiles, because while the system was frozen the harness wasn’t sending, so the thousand requests that should have arrived were never measured. Open-loop, timing from intended send time, reported p99 of 91ms. Same system, same stall, same sample count. That’s why the max detaching from the percentiles is a coordinated-omission fingerprint, not an outlier to throw away — and why every load generator I trust paces on a schedule.”

Plain-English recap

• The ladder matters as much as the capstone. You calibrated a clock and priced a fence; you made a benchmark lie and then caught it; you watched dead-code elimination report 0.000ns/op. Only then did the assembled pipeline arrive — and every piece of it was a decision you had already made by hand.
• You just built a miniature APM. Stamps carried inside the message are trace context propagation; the aggregator is the metrics backend; the printed percentile table is the dashboard. The difference from Datadog is only the scale: nanosecond spans, ~zero overhead, no vendor.
• Experiment (a) is the GC-pause lesson. One innocent allocation per request is the Node service whose p50 is fine but whose p99 is eaten by GC. Zero-alloc is a tail discipline, which is why code review can’t verify it but a counting allocator can.
• Experiment (b) is noisy neighbors. Unpinned threads are pods without CPU pinning, and the signature isn’t “slower” — it’s irreproducible, run-to-run variance you can’t explain. Placement, not code, was the variable.
• Experiment (c) is two services updating one row. The stage counters are logically independent but physically adjacent — hot-row contention at nanosecond scale, provable with perf c2c instead of pg_stat_activity.
• Step (d) is what dashboards are for: distinct diseases, distinct signatures. Allocation shows page faults; bad placement shows context switches; false sharing shows IPC down with instructions flat. Counters diagnose before anyone reads code — the same triage you already do from metrics.
• The open-loop producer is the honest load generator. It sends on schedule whether or not downstream is keeping up, so a stall shows up as latency instead of silently lowering the offered rate.

The 5 sentences you now get to say in interviews, truthfully

1. “I’ve decomposed a pipeline’s latency budget stage-by-stage with TSC timestamps and per-stage HdrHistograms, aggregated off the hot path, and I know what my instrumentation itself costs.”
2. “I’ve measured, on my own hardware, what a single hot-path heap allocation does to p99.9 versus p50 — and that’s why I treat zero-alloc as a tail-latency discipline and verify it with a counting allocator, not by code review.”
3. “I’ve demonstrated false sharing between two ‘independent’ per-thread counters, watched it in the per-stage histograms, and confirmed the HITM signature with perf c2c before padding the layout.”
4. “I generate load open-loop with intended-send-time accounting, because I’ve seen how a closed-loop harness coordinates with stalls and understates the tail by orders of magnitude.”
5. “I can walk a tail regression from symptom to mechanism with counters first — perf stat, then sched tracing or c2c depending on the fingerprint — and I consider it diagnosed only when the outlier timestamps correlate with the mechanism.”

Interviewer will ask

Q: Why carry timestamps inside the message instead of logging at each stage? A: It makes correlation free — all four stamps for one event arrive together, no joining logs by sequence number across threads — and the hot-path cost is just the rdtsc plus stores into a message already in cache. The trade-off is message size; four u64s is cheap. For wide fan-out topologies you’d switch to per-stage rings keyed by seq and join off-path — a road deliberately not taken here: this lab’s pipeline is a straight line, so in-message stamps stay the cheaper design.

Q: Your q1 delta includes both queue residency and consumer wakeup. How would you split them? A: Add a stamp at enqueue-complete vs dequeue-start — t0 is intended send here, so I’d stamp t0’ after the push returns: t0’−t0 is producer-side delay and pacing, t1−t0’ is residency plus wake. To isolate pure wake latency, run at a rate low enough that the consumer always drains before the next message arrives — then the queue is empty at every enqueue, residency ≈ 0, and the whole t1−t0’ delta is wake.

Q: Is it load-bearing that the aggregator ring is SPSC? A: Yes — it has exactly one producer (the consumer stage) and one consumer (the aggregator); if multiple stages shipped samples I’d give each its own SPSC to the aggregator rather than share one MPSC (multi-producer single-consumer — many writers pushing into one ring), keeping one writer per ring — the rule all of the observability chapter (ch11) ran on — and letting the aggregator merge histograms, which HdrHistogram supports natively.

Q: The producer spins to pace. Isn’t that a core wasted? A: In this lab, yes, deliberately — open-loop pacing needs a reliable clock and spin-waiting is the jitter-free way. In production the “producer” is the NIC; the pacing question becomes replay fidelity: I replay captured data on original timestamps, including bursts, for exactly the reasons steady-state numbers lie.

Q: What would this lab miss about a real trading system? A: Plenty, and knowing it matters: no network (so no IRQ/softirq path, no NIC hardware stamps), trivially small working set (no icache/dcache pressure from a real book), uniform message sizes, no bursty arrival process unless I replay one, and no exchange at the other end. It teaches the measurement machinery; the production replay harness (the change-management chapter, ch17, built on ch13’s event log) is where verdicts come from.

Q: Why is max latency in your baseline tens of µs even when healthy? A: Because I ran 2M samples — at that count you will observe rare platform events: a stray IRQ on an imperfectly isolated core, a TLB shootdown (one core unmapping memory forces every other core to flush its translation cache — a cross-core interrupt), a C-state exit. The follow-up is exactly Part I’s tuning list, verified by the ftrace silence check; a healthy isolated setup pulls the max down toward single-digit µs, and I’d want a flight-recorder dump for whatever remains.

Further reading

• Gil Tene, “How NOT to Measure Latency” — re-watch it after running this lab; it lands differently once you’ve seen coordinated omission in your own harness.
• HdrHistogram documentation — interval histograms and merging, for turning this lab’s one-shot histograms into continuously-published percentiles.
• Brendan Gregg, Systems Performance (2nd ed.) — the CPU and scheduling chapters to explain experiment (b)’s fingerprints.
• The LMAX Disruptor paper — the architectural ancestor of the stamp-and-drain pattern used here.
• The rtrb crate documentation — a clean, real SPSC implementation worth reading end-to-end and comparing against your own queue in this same harness.

Where this goes next: Part II (measurement) is done — Chapter 13 opens Part III with the question the rest of the book hangs on: how does one design decision — the event log — make deployment, recovery, testing, and compliance all fall out for free?