One run measured six ways

Worked example: one run measured six ways

These numbers are predictions, to be written down before measuring: the capstone’s total on the default 2 M-message file at its recorded 100,000 messages a second, on the machine of the predicted-numbers table, changing one thing per row. Rows 1 to 4 use the harness most first measurements use, a closed loop: the feed thread releases each message only once the strategy has decided on the previous one, at its scheduled time or at once if that has passed, and stamps t0 as it releases it, a few lines’ change to the feed thread rather than one of the capstone’s modes. Rows 5 and 6 are paced mode.

Discarding the warm-up moves only the max here, the first message’s page faults, dynamic linking and rising clock, because the unpinned tail is worse than the cold start and hides it; once rows 3 and 4 remove that tail a cold start would set the p99.9, which is why every later row discards it. Pinning lowers the p50 because feed and strategy now sit on two cores sharing an L3, at a held clock, and the p99 because nothing migrates. Other work still runs on cores 2 and 3 until isolation and locked memory take it out of the p99.9 and the max in row 4.

Row 4 is the most dangerous line in the table: the best numbers, and wrong. Its closed loop releases a burst of 30 messages one at a time, so none ever waits for another. Row 5 releases them as the market sent them, and the p99 and p99.9 rise by the bursts: the last of 30 waits behind 29 decodes on core 2, the first of a batch for its batch-mates’ applies on core 3. The p50 does not move, because the median message is not in a burst. In row 6 think is as in row 5, about 19,000 of the 1.9 M measured messages wait between 0 and 10 ms, and the p99.9 is the stall’s. Row 4’s closed loop with the same stall would record 19 slow samples, one a second: a p99.9 still at 1–5 µs, and a max of 10 ms that a reader would call noise.

Seeing it

Check the clock rate and hold it, then count what the kernel did on the hot cores after warm-up:

# frequency: driver, governor, limits and boost; then hold it
cpupower frequency-info
sudo cpupower frequency-set -g performance
echo 1 | sudo tee /sys/devices/system/cpu/intel_pstate/no_turbo   # Intel, intel_pstate
sudo cpupower set --turbo-boost 0                                 # AMD, a recent cpupower

# a paced run; past its warm-up, count kernel events on cores 2, 3 and 6
./target/release/run --paced > report.txt &
sleep 2
cat /proc/interrupts > irq-before.txt
sudo perf stat -a -C 2,3,6 -A -e context-switches,cpu-migrations,page-faults -- sleep 10
cat /proc/interrupts > irq-after.txt
grep ctxt /proc/$(pidof run)/task/*/status
wait
diff irq-before.txt irq-after.txt

cpupower frequency-info names the frequency driver (intel_pstate, amd-pstate or acpi-cpufreq), the governor, the range it may choose from, and whether boost is active. perf stat here counts whole cores rather than a program: -a asks for system-wide counting and -C 2,3,6 narrows it to everything that runs on those cores, -A prints one line per core instead of their sum, and -- sleep 10 sets a ten-second window past the run’s first second. Counting whole cores needs root, or kernel.perf_event_paranoid at 0 or below. All three counts should be zero: a context switch says something else ran or the thread blocked, a migration that a thread was not pinned, a page fault that memory was first touched inside the run.

/proc/interrupts has a column per core and a row per source; read the columns for cores 2, 3 and 6. The numbered rows are devices, the network card’s queues among them, and should not move there. LOC, the local timer, moves about once a second on a nohz_full core running one thread, against 250–1,000 times on an ordinary one; RES, the scheduler waking the core, and TLB, another core asking it to flush address translations, should not move. The grep prints each thread’s voluntary and nonvoluntary context switches; neither should grow after warm-up.

Read more: Gil Tene’s talk “How NOT to Measure Latency”, given at many conferences and recorded at several, introduces coordinated omission and service time against response time. Tene’s README for wrk2, his constant-throughput version of the wrk HTTP load generator, explains how a load generator omits the slow samples and how to correct for it. Red Hat’s Low Latency Performance Tuning for Red Hat Enterprise Linux 7 covers governors, idle states, isolation and interrupt affinity, with the reasons attached.