Profiling: perf, Flame Graphs & Counters

perf record programs a hardware counter (by default, cycles) to overflow every N events or at a target frequency. Each overflow raises an interrupt; the kernel records the instruction pointer and, with -g, a call stack. Run long enough and the samples are a statistical picture of where cycles go. Two consequences worth internalising:

• It is statistical. 10,000 samples give you percentages to about ±1% for big frames; a function at 0.3% may be noise. Profile for tens of seconds, not two.
• It only sees on-CPU time. A thread blocked in futex or recv is invisible to a cycles profile (Day 5 deals with that).

What the binary needs:

# Cargo.toml — profile what you ship, with enough metadata to read it
[profile.release]
debug = "line-tables-only"   # or true: file/line info and inlined-frame info

# Frame pointers make stack walking cheap and reliable
RUSTFLAGS="-C force-frame-pointers=yes" cargo build --release

perf record -F 999 -g -- ./target/release/loadgen --rate 500000 --secs 30
perf report --no-children          # sort by self time
perf report                        # 'Children' column = inclusive time

Stack walking has three modes, each with a trade-off. Frame pointers (-g / --call-graph fp) are cheap but need every frame compiled with them — Rust omits them by default on x86-64 Linux, and a precompiled standard library may not have them, so stacks through std can be truncated. DWARF (--call-graph dwarf) copies a chunk of each thread's stack per sample (8 KiB by default) and unwinds offline — reliable, but big files and more overhead. LBR (--call-graph lbr) uses Intel's last-branch-record hardware — very cheap, but limited depth and Intel-only.

Why -F 999 and not 1000: an odd frequency avoids sampling in lockstep with something periodic (a 1 kHz timer tick, a 1 ms batch loop) and systematically over- or under-counting it.

The pipeline is three steps, and the middle one is the interesting one:

perf script > out.perf                                  # raw samples with stacks
inferno-collapse-perf out.perf > out.folded             # one line per unique stack
inferno-flamegraph out.folded > engine.svg              # render

The collapsed (folded) format is one line per unique stack with a sample count: main;engine::run;engine::Engine::submit;book::Book::add 60. Everything a flame graph shows can be computed from it:

• A frame's width is its inclusive samples: every stack it appears in.
• The top edge of a tower (frames with nothing above them) is self time: where the CPU was actually executing.
• The x-axis is sorted alphabetically to merge identical frames — left-to-right order means nothing about time. (For time order, use a flame chart.)

The workflow: find the widest plateaus (big self time), then walk down to find the frame you own that is responsible. A wide core::hash::sip::Hasher::write is not a hashing problem to optimise — it is a hint that your Book::add hashes on the hot path at all.

Because the text format is so simple, grep and a few lines of code beat clicking around an SVG: filter to stacks containing Engine::submit, sum self time by frame, diff two profiles. That is the drill. One trap: Rust symbols contain spaces (<alloc::string::String as core::fmt::Write>::write_str), so the count is whatever follows the last space.

use std::collections::HashMap;

/// One line of collapsed-stack output ("frame;frame;frame COUNT"), as
/// produced by stackcollapse-perf.pl or inferno-collapse-perf. Frames may
/// contain spaces (`<alloc::string::String as core::fmt::Write>::write_str`),
/// so the count is whatever follows the LAST space. Ignore surrounding
/// whitespace. Return None for blank or malformed lines.
pub fn parse_line(line: &str) -> Option<(Vec<&str>, u64)> {
    todo!()
}

/// Total samples across all valid lines (skip junk lines).
pub fn total_samples(collapsed: &str) -> u64 {
    todo!()
}

/// Self ("exclusive") samples: each line's count is credited to its leaf
/// frame only. Sort by count descending, then name ascending.
pub fn self_samples(collapsed: &str) -> Vec<(String, u64)> {
    todo!()
}

/// Inclusive samples: every frame on the stack gets the line's count — but
/// a frame appearing several times in one stack (recursion) counts once.
/// Same sort order as `self_samples`.
pub fn inclusive_samples(collapsed: &str) -> Vec<(String, u64)> {
    todo!()
}

/// The frame with the most self samples (ties: smallest name) and its share
/// of all samples in percent. None for an empty profile.
pub fn hottest(collapsed: &str) -> Option<(String, f64)> {
    todo!()
}

perf stat -e cycles,instructions,branches,branch-misses,cache-misses,LLC-load-misses \
    -- ./target/release/loadgen --rate 500000 --secs 30

The numbers that matter, and how to read them:

• IPC (instructions per cycle). Modern big cores can retire four to six or more instructions per cycle at peak. A tight, cache-resident loop runs at 2–4. An order book chasing pointers through DRAM often runs at 0.3–0.8. Low IPC says "the core is waiting"; it does not yet say on what.
• Branch-miss rate. A mispredict throws away the speculative work behind it — roughly 15–20 cycles on recent x86 cores. At 1% of branches it rarely matters; at 4%+ in a hot loop it can be a fifth of all cycles.
• LLC misses and MPKI (misses per thousand instructions). Each last-level miss that goes to DRAM costs on the order of 80–100 ns — about 300 cycles at 3 GHz, more on big multi-socket servers. Five misses per thousand instructions is enough to make a workload memory-bound.

The crude cost model in the drill — misses × penalty ÷ cycles — is an upper bound, because an out-of-order core overlaps independent misses. That overlap is called memory-level parallelism (MLP): a pointer chase (each load's address depends on the previous load) has MLP ≈ 1; a scan over an array can keep ten misses in flight. Same miss count, very different cost — which is the whole argument for the dense, array-based book in week 28.

On recent Intel CPUs, perf stat --topdown (or the TopdownL1 metric group in newer perf) does this attribution properly, using counters designed for it; AMD's recent cores expose a similar pipeline breakdown. Use the real thing when you have it; use the arithmetic to sanity-check it.

/// A `perf stat` readout (cycles, instructions, branches, branch-misses,
/// LLC-load-misses).
#[derive(Clone, Copy, Debug)]
pub struct Counters {
    pub cycles: u64,
    pub instructions: u64,
    pub branches: u64,
    pub branch_misses: u64,
    pub llc_misses: u64,
}

/// What a stall costs on this machine, in core cycles, and how many LLC
/// misses the core overlaps on average (memory-level parallelism: ~1 for a
/// pointer chase, 5-10 for a streaming scan).
#[derive(Clone, Copy, Debug)]
pub struct CostModel {
    pub mispredict_penalty: f64,
    pub dram_latency_cycles: f64,
    pub mlp: f64,
}

#[derive(Clone, Copy, Debug, PartialEq, Eq)]
pub enum Bottleneck {
    Memory,
    BranchMispredict,
    Compute,
}

/// Instructions per cycle (0 when there are no cycles).
pub fn ipc(c: &Counters) -> f64 {
    todo!()
}

/// Branch misses as a percentage of branches (0 when there are no branches).
pub fn branch_miss_pct(c: &Counters) -> f64 {
    todo!()
}

/// LLC misses per thousand instructions (0 when there are no instructions).
pub fn llc_mpki(c: &Counters) -> f64 {
    todo!()
}

/// Fraction of cycles lost to mispredicts: misses * penalty / cycles,
/// clamped to [0, 1] (0 when there are no cycles).
pub fn branch_stall_frac(c: &Counters, m: &CostModel) -> f64 {
    todo!()
}

/// Fraction of cycles stalled on DRAM: llc_misses * dram_latency / mlp /
/// cycles, clamped to [0, 1] (0 when there are no cycles).
pub fn memory_stall_frac(c: &Counters, m: &CostModel) -> f64 {
    todo!()
}

/// Memory if memory_stall_frac >= 0.30 and it is at least the branch
/// fraction; otherwise BranchMispredict if branch_stall_frac >= 0.15;
/// otherwise Compute.
pub fn classify(c: &Counters, m: &CostModel) -> Bottleneck {
    todo!()
}

Inlining. In a release build most small functions are inlined, so their cost shows up under the caller. A profile that says Engine::submit is 60% self time may really be Level::push_back inlined into it. With debug info, perf report --inline (and perf annotate) can attribute inlined code; temporarily marking a suspect function #[inline(never)] also works — but remove it afterwards, because it changes what you are measuring.

Skid. The interrupt for a sample lands a few instructions after the one that caused the event, so perf annotate often blames the instruction after the expensive load. Precise sampling — Intel's PEBS via cycles:pp, AMD's IBS — reduces this. When annotating, look for the load just before the hot instruction.

Symbols. Rust symbols are mangled; perf demangles legacy-mangled names, and rustfilt handles the rest. A stripped binary profiles as raw addresses. Generics produce one symbol per instantiation — HashMap<OrderId, Loc>::insert and HashMap<u64, Account>::insert are different frames.

The environment. Profiling the kernel side needs a relaxed kernel.perf_event_paranoid or CAP_PERFMON. In VMs counters are often missing or virtualised. And perf itself costs something: at high frequency with DWARF stacks the overhead can be several percent and the profile can shift. Compare throughput with and without the profiler attached.

The workload. A microbenchmark that adds and cancels the same order a million times keeps everything in L1 and trains every branch. The same code under realistic open-loop flow from week 25 misses caches and mispredicts. Profile the system, not the microbenchmark.

A busy-polling engine thread (week 30) spends all its time on-CPU, so a cycles profile describes it fully. The gateway and journal threads block: in epoll_wait, futex, fsync. Their latency problems are off-CPU — time spent waiting to be scheduled or for I/O — and are invisible to perf record -e cycles. Tools for that: perf sched (scheduler latency), perf trace (syscalls), and off-CPU flame graphs built from scheduler events (Brendan Gregg's site covers all three).

When a change claims a speedup, profile both versions and compare: differential flame graphs colour frames by how much they grew or shrank. And check the counters moved the way your theory says — if you "fixed cache misses", LLC-load-misses on that path should drop.

The hotspots you will most likely find in engine v2, and the usual fix:

• malloc, free, RawVec::grow_one, realloc — an allocation per order or per event. Preallocate; slabs and pools (week 27).
• core::hash::sip::Hasher — the default HashMap hasher (SipHash-1-3, DoS-resistant and comparatively slow) keyed by order id. A faster hasher for trusted keys, or a slab index instead of a hash lookup (week 27). The repo's books already use book::IdMap, a one-multiply hasher, so you'll only see this frame if your book uses the default HashMap.
• BTreeMap search frames with low IPC — pointer-chasing price levels. A dense price ladder (week 28). In the repo this was the top hotspot, and this week's fix is a sorted Vec of prices per side (see the capstone).
• core::fmt, format_inner, write_str — formatting or logging on the hot path. Binary events, formatting on another thread (weeks 19 and 38).
• memcpy / memmove — large events copied by value, or VecDeque/Vec shifting elements. Smaller events; pass indices, not copies.
• futex, syscall — locks or blocking queues between stages. Lock-free handoff (week 5) and busy polling (week 30).

The discipline that makes optimisation work is the loop: hypothesis → one change → re-profile → counters → open-loop latency. Change one thing per iteration; if you change three and throughput goes up 20%, you have learned nothing about which one mattered, and one of them may have made the tail worse.

Keep an experiment log (it becomes week 40's report): commit, change, hypothesis, throughput, p99/p99.9 at a fixed offered rate, IPC, LLC MPKI, branch-miss rate, and a link to the flame graph.