Profiling costs and a page-fault investigation

What it costs

The second row has a consequence: a profiled run’s percentiles are not the program’s. Messages that arrive while a sample is being taken wait for it, 1–5% of them at 4,000 Hz, enough to move a p99. Profile one run and take the histograms from another.

Worked example: a p99.9 of 6 µs that the flame graph cannot see

A first assembly of the capstone, before the main thread called mlockall, is built with stages and run paced with --records 300000: 100,000 warm-up messages and 200,000 measured, so its p99.9 rests on 200 samples. total reads count 200,000, p50 290 ns, p99 1.2 µs, p99.9 6.1 µs, max 7.9 µs. The p99.9 is inside the predicted 2–10 µs, but the shape is wrong: about 240 samples lie between 5.5 and 7.9 µs and almost none between 2 and 5.5. A tail with a cliff in it, its p99.9 close to its max, is one cause of one size, repeated.

The flame graph of a flat run looks like the sketch above, and the paced run’s is 96% polling with the rest in the same proportions. Neither could show anything: 240 messages that lost about 5.5 µs each cost 1.3 ms in 2 s, 0.07% of core 3, about six of its 8,000 samples.

Replayed alone with every stage stamped, the worst 100 point at once. decode is 20–40 ns and think 60–250 ns, but hop is 5.2–5.8 µs: for 5.5 µs after those messages were pushed, the strategy did not look. The 240 fall in 12 runs of 15–25 consecutive sequence numbers, each a burst, and the message just before each run has a normal hop and a think of about 5.6 µs: the strategy spent 5.5 µs inside one apply while the burst queued behind it. A second run is slow at the same 12 places, so the cause travels with the data, or with something that happens for the first time.

perf stat -a -C 3 -D 1500 -e page-faults,context-switches,cpu-migrations over the measured part reads 12 page faults and nothing else, and /proc/interrupts shows only timer ticks on core 3. Twelve faults, twelve runs. perf trace --pf=all puts all twelve inside the book’s 1 MB array of quantities. The array was allocated zeroed, and the kernel provides a zeroed allocation’s pages lazily, each on its first write. The warm-up’s prices wrote a few pages around the opening price; when the price later moved into a page of 512 levels the run had not yet written, the first update there faulted: the kernel found a free page, zeroed it and mapped it, 1–2 µs, and the loop then refilled the cache lines and address translations the kernel’s code had displaced, about 5.5 µs in all, while the burst that came with the price move waited in the ring.

The fix is the OS chapter’s: the main thread calls mlockall(MCL_CURRENT | MCL_FUTURE) before it spawns the threads. Memory locked as it is mapped is also filled in as it is mapped, so all 256 pages of the book get their memory when it is allocated. The re-run reads zero page faults, the 12 places show hop at 90–250 ns, and total reads p99.9 2.3 µs and max 4.1 µs, a tail now set by the bursts. The flame graph was right throughout, apply 55% of the work before the fix and after; it was about something else.

Seeing it

The whole sequence, from build flags to flame.svg, after setting debug = 1 under [profile.release] in Cargo.toml:

# frame pointers in every crate the build compiles (add --features stages for t1 and t2)
RUSTFLAGS="-C force-frame-pointers=yes" cargo build --release

# counters on the strategy's core; divide by the 2,000,000 messages
sudo perf stat -a -C 3 -e cycles,instructions,cache-misses,branch-misses \
    -- ./target/release/run --flat

# samples with call stacks on core 3, 4,000 a second, then the flat tops
sudo perf record -F 4000 -g -C 3 -o strategy.data -- ./target/release/run --flat
sudo perf report -i strategy.data --no-children

# the flame graph
cargo install inferno
sudo perf script -i strategy.data | inferno-collapse-perf > strategy.folded
inferno-flamegraph --title "strategy thread, flat run" strategy.folded > flame.svg

# inside the hottest function
sudo perf annotate -i strategy.data --stdio '<ch06_book::ArrayBook as ch06_book::Book>::apply'

-o and -i name the data file, so that a later recording does not overwrite it. perf report --no-children sorts functions by their own samples, the flat tops; without it, each function is also credited with everything it called. In a browser, hovering over a box of flame.svg shows its name and share, and clicking one zooms to its tower. If perf annotate finds no such function, it was inlined, and its instructions are inside the function perf report names instead.

Read more: Brendan Gregg, “The Flame Graph” (ACM Queue, 2016), explains how flame graphs are built and read and the variants made from other kinds of samples; brendangregg.com/flamegraphs.html collects the scripts and examples. The perf wiki’s tutorial at perf.wiki.kernel.org walks through perf stat, perf record, perf report and perf annotate, including how events are multiplexed. Brendan Gregg’s Systems Performance, 2nd ed. (Addison-Wesley, 2020), in its chapter on CPUs, treats counters, profiling and scheduler analysis as one method.