7 · The number Draft
Counters and sampling profilers
On this page
7.6 Finding where the time goes
A histogram says how much the path costs; it does not say where the time went, and this section is how to find where. Two instruments see the whole program: counters, which count events over a run, and samples, which record where the core was thousands of times a second. A picture made from the samples, the flame graph, shows how the time divides among functions, and one more tool opens the hottest of them. All of these describe the common case. The tail needs different tools, and the section ends with those.
Counters
The hardware performance counters met in the ladder of a measurement each count one kind of event as it happens: clock cycles, instructions finished, cache misses, branches guessed wrong. Each core has a few fixed counters and 4–8 programmable ones, together its PMU, performance monitoring unit. The kernel programs them, and perf stat runs a program with a list of events counting and prints the totals at the end. The hardware does the counting, so the program pays almost nothing. When the list is longer than the counters, the kernel takes turns, counting each event part of the time and scaling up, and prints the share of time each was counted in brackets, such as (66.67%); a short list avoids it. Context switches, migrations and page faults are counted by the kernel itself, in software.
The capstone needs two kinds of count:
# work per message: a flat run, counting only core 3, where the strategy runs
sudo perf stat -a -C 3 -e cycles,instructions,cache-misses,branch-misses \
-- ./target/release/run --flat
# kernel events: a paced run, the three hot cores, after warm-up
sudo perf stat -a -C 2,3,6 -A -D 2000 \
-e context-switches,cpu-migrations,page-faults \
-- ./target/release/run --paced-e names the events. -a counts system-wide and -C 3 narrows that to whatever runs on core 3, not one program’s threads wherever they run; with the strategy pinned and the core isolated, that is the strategy thread and anything that interrupts it. Counting a whole core needs root, or kernel.perf_event_paranoid at 0 or below. -A prints a line per core, -D 2000 starts counting 2,000 ms after the program starts, past its setup and first second, and -- ends perf’s options. The ratio of instructions to cycles is IPC, instructions per cycle; a current core finishes 4–6 a cycle at best.
| Event | What it counts | What to expect |
|---|---|---|
cycles | core clock cycles in which the core ran something, at the core’s own rate, not the TSC’s | per message, the work in cycles; per second counted, the clock the core really ran at |
instructions | instructions the core finished | perf prints IPC beside it as insn per cycle: 1–2 for this code; under 1, the core is waiting, usually on memory |
cache-misses | on most parts, accesses that missed the last-level cache and went to DRAM, 80–100 ns each | near zero per message while the working set stays in cache |
branch-misses | branches the predictor guessed wrong, 15–20 cycles each | about one per message on this feed |
context-switches | times the kernel took the core from a thread, for another or because it blocked | zero on an isolated core |
cpu-migrations | times a thread moved between cores | zero when pinned |
page-faults | traps into the kernel for a page not yet mapped | zero after warm-up, with memory locked |
A flat run of 2,000,000 messages that reports 420 million cycles, 760 million instructions, 20,000 cache misses and 1.9 million branch misses on core 3 spent 210 cycles on each message, 52 ns at 4 GHz, and 380 instructions, at an IPC of 1.8, with a DRAM miss on one message in a hundred and about one wrong guess per message, mostly on which side and level an update lands, which no predictor can know. Set beside think, 52 ns of work against a p50 of 30–100 ns is consistent; a mismatch would mean one of the two measures something else. A paced run’s strategy spends most of its time polling an empty ring, 40,000 cycles a message of which about 200 are work, so the work is counted in a flat run and the paced run only for the kernel events, which must be zero however the loop spends its cycles.
Samples
perf record, the sampling profiler, does not count events: it stops the program many times a second and writes down where it was. It programs a counter, cycles by default, to overflow after N events; at each overflow the core raises an interrupt, and the kernel records the instruction pointer, the address of the instruction running, with the thread and the time, into a buffer that perf drains to a file, perf.data. -F 4000 asks perf to choose N so that samples come about 4,000 times a second, its default, one sample per million cycles at 4 GHz. perf report finds the function containing each address in the binary’s symbol table and sorts functions by their share of the samples. The share estimates time, a rough one when fewer than 100 samples land in a function, so seeing one that takes 1% needs 10,000 samples, 2.5 s of a busy core.
With -g, each sample also records the call stack, the chain of return addresses from the running function back to the thread’s start, which says not only that apply was running but that drain called on_update, which called it. The cheap way to walk a stack is the frame pointer: a register, rbp on x86_64, that each function points at its own stack frame on entry after saving its caller’s value there, so that the frames form a linked list the kernel can follow in a few loads. Optimised builds normally leave frame pointers out and use rbp as one more general register, and a stack walk then stops after a frame or two, the rest shown as [unknown]. RUSTFLAGS="-C force-frame-pointers=yes" keeps them in every crate the build compiles, for 1–3% of speed; code compiled without them, which can include parts of the precompiled standard library, still breaks the chain. The alternative, --call-graph dwarf, copies 8 KB of the thread’s stack into the file with every sample and unwinds it afterwards from the debug information. It needs no frame pointers and is far heavier: 32 MB of file a second at 4,000 Hz, and minutes to report.
Function names survive a release build. Source lines and inlined functions need debug information, which debug = 1 under [profile.release] in Cargo.toml adds: Cargo’s “limited” level, line tables and function records without types or variables. It sits in parts of the file the program never loads, so it costs disk, not speed, and it lets perf name the small functions the compiler inlined into their callers, which have no frame of their own. And because a paced run’s profile is 95% or more the poll on an empty ring, the body of the loop is profiled in a flat run.