Throughput benchmarks (labs 01-04) time a whole loop. Latency-critical
systems (trading, audio, control, request serving) care about EACH
iteration, and specifically about the worst ones. This lab times one
million iterations of a ~1 us operation INDIVIDUALLY with the serialized
TSC, and shows:
- the distribution is not a bell curve: a tight body plus a long tail
- what puts events in the tail (page faults, preemption, migration,
SMT sharing, interrupts) and how to SEE each one from user space
- which mitigations you can apply yourself (pre-fault, pin, no
allocation/syscalls in the loop) and which need the kernel
evidence to leave with
p99.9 from ~39 us to ~7.6 us by pre-faulting; faults and involuntary switches counted; residual tail attributed to preemption/interrupts
first, get the code
run this
$ git clone https://github.com/adit4443ya/debug_labs.git && cd debug_labs
then build it
run this
$ cd perf && ./build.sh
produces bin/05_tail_latency (-O2)walk it, one step at a time
run this
$ ./bin/05_tail_latency cold
what it printed on the machine that wrote this lab
Read it: p50 (992 ns) is the honest cost of 8 serialized DRAM misses. But
p99.9 is 39x that and the max is 360 us: one iteration in a thousand is
slower than a thousand normal ones. The histogram has a second hump at
8-65 us (4.5K samples) that the body does not explain. The counters say
why: 32,772 minor page faults DURING the loop. The table is 16,384 pages
and each fresh page costs TWO faults: the first read maps the shared zero
page, the first write then allocates a real page (copy-on-write). Each
fault is a trip through the kernel: a few microseconds, sometimes tens.
run this
$ ./bin/05_tail_latency warm
what it printed on the machine that wrote this lab
The page-fault hump is gone (6 faults, none in the table). p99.9 fell
from 38.7 us to 7.6 us: a 5x improvement of the metric that matters,
from a change that does not touch the hot loop at all. What remains in
the tail: 10 involuntary context switches (the scheduler took the CPU
away mid-iteration), timer/network interrupts, and the SMT sibling.
run this
$ ../tools/pin.sh -q ./bin/05_tail_latency warm
what it printed on the machine that wrote this lab
8 dependent loads 48 994 1555 3682 7691 77662 1171.6
tail: p99/p50 = 3.7x p99.9/p50 = 7.7x max/p50 = 78x
during loop: minor page faults=6 voluntary ctxsw=0 involuntary ctxsw=7 migrations seen=0
Honest result: on this laptop pinning alone does not move p99.9 (7.7 vs
7.6 us) — there were no migrations in the unpinned warm run either — and
the max swings between ~40 and ~100 us from run to run in both modes.
What is left is preemption and interrupts, and without root you cannot
remove them. That IS the finding: "the residual tail is not in my code;
it needs an isolated core." Knowing where your responsibility ends is
part of the skill.
what it printed on the machine that wrote this lab
8 dependent loads 44 1000 1517 3502 7729 82889 1169.4
during loop: minor page faults=4 voluntary ctxsw=0 involuntary ctxsw=9 migrations seen=0
Same result as warm, no loop to write: MAP_POPULATE (or mlock, or
MADV_WILLNEED) makes the kernel fault the whole mapping in at mmap time.
This is what allocators in latency-critical systems do at startup.
the operation
8 dependent random read-modify-writes in a 64 MB table (each
address depends on the previous value, so the 8 misses serialize). That
is a stand-in for "look something up in a big order book / hash map":
~125 ns per DRAM miss x 8 = ~1 us.
usage
./bin/05_tail_latency [cold|warm|populate] [iterations]
cold table from calloc, NEVER touched before the timed loop
warm table written once before the loop (page faults paid up front)
populate table from mmap(MAP_POPULATE) (kernel pre-faults it)
how to read the histogram
Buckets are powers of two in ns. A healthy latency-critical loop has one
or two adjacent buckets holding >90% of samples and a tail that decays
FAST. A second hump is a DIFFERENT mechanism (here: page faults), not
"noise". Name every hump; the counters printed below the table are how.
THE SOURCES OF TAIL LATENCY (and how to see each):
page faults getrusage(ru_minflt) delta; perf stat -e page-faults;
fix: pre-fault, MAP_POPULATE, mlock, hugepages (MADV_HUGEPAGE)
preemption /proc/self/status nonvoluntary_ctxt_switches; perf sched (root);
fix: pin, SCHED_FIFO (root), isolcpus (root), fewer runnable threads
migration sched_getcpu() changing mid-run; fix: pin
SMT sibling a busy sibling steals execution units; fix: leave the sibling idle
frequency changes powersave governor / turbo; fix: performance governor (root)
interrupts /proc/interrupts per-CPU deltas; fix: IRQ affinity (root)
allocation/syscall in the loop strace -c, ltrace -c; fix: preallocate, never call
the kernel on the hot path (that is the whole point of
busy-polling and kernel-bypass NICs)
TLB misses perf stat -e dTLB-load-misses; fix: hugepages (a 64 MB
table is 16K 4-KiB pages but only 32 huge pages)
what to report
p50 / p99 / p99.9 / max and the sample count, with the
conditions (pinned to what, warm or cold, governor). "Average latency
1.2 us" is not a result. "p99.9 went from 38.7 us to 7.6 us because the
table was pre-faulted; the remaining tail is preemption, verified by the
involuntary-switch counter" IS a result.
take it further
1. Start a busy loop on the SMT sibling (`taskset -c 3 yes >/dev/null &`)
and rerun STEP 3. Watch p50 AND the tail move; kill it after.
2. Add `free(malloc(64))` inside the timed iteration. Find it in the
histogram, then confirm with `ltrace -c`.
3. `madvise(table, TABLE_BYTES, MADV_HUGEPAGE)` right after the mmap in
populate mode (THP is `madvise` on this box). Compare p50: fewer TLB
misses per lookup. Then `perf stat -e dTLB-load-misses:u` both ways.
4. Shrink TABLE_BYTES to 1 MB (fits in L2): p50 falls ~5-10x; does the
tail? The tail is not about your code.
============================================================
read the source · perf/05_tail_latency.c
#include"../tools/bench.h"#include<sys/mman.h>#include<sys/resource.h>#defineTABLE_BYTES(64ull<<20)#defineTABLE_N(TABLE_BYTES /sizeof(uint32_t))#defineCHAIN8staticlongread_status_field(constchar*key){/* from /proc/self/status */ FILE *f =fopen("/proc/self/status","r");if(!f)return-1;char line[256];long v =-1;while(fgets(line,sizeof line, f))if(!strncmp(line, key,strlen(key))){ v =atol(line +strlen(key));break;}fclose(f);return v;}staticlongminflt(void){structrusage r;getrusage(RUSAGE_SELF,&r);return r.ru_minflt;}intmain(int argc,char**argv){constchar*mode = argc >1? argv[1]:"cold";uint64_t iters = argc >2?strtoull(argv[2],0,10):1000000ull;uint32_t*table;if(!strcmp(mode,"populate")){ table =(uint32_t*)mmap(NULL, TABLE_BYTES, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS | MAP_POPULATE,-1,0);if(table == MAP_FAILED){perror("mmap");return1;}}else{ table =(uint32_t*)calloc(TABLE_N,sizeof*table);/* fresh zero pages, untouched */if(!table){perror("calloc");return1;}}if(!strcmp(mode,"warm")){for(size_t i =0; i < TABLE_N; i +=1024) table[i]=1;/* one write per 4 KiB page */BENCH_CLOBBER();}/* The samples array is 8 MB: touch it NOW so its own page faults do not
* land inside the timed loop. Two real bugs from drafts of this lab:
* (1) not touching it at all -> ~2000 faults inside the loop;
* (2) memset(...,0,...) right after malloc -> clang rewrote the pair as
* calloc(), which touches nothing. Hence the 0xFF. */uint64_t*samples =(uint64_t*)malloc(iters *sizeof*samples);memset(samples,0xFF, iters *sizeof*samples);double hz =bench_tsc_hz();uint64_t seed =0xD1B54A32D192ED03ull, sink =0;long flt0 =minflt(), vcs0 =read_status_field("voluntary_ctxt_switches:"), ics0 =read_status_field("nonvoluntary_ctxt_switches:");int cpu0 =bench_cpu(), migrations =0;for(uint64_t it =0; it < iters; it++){uint64_t idx =bench_rand(&seed)% TABLE_N;uint64_t t0 =bench_tsc_begin();for(int k =0; k < CHAIN; k++){uint32_t v = table[idx]; table[idx]= v +1;/* a WRITE: an untouched page must really be allocated */ idx =(idx + v +0x9E3779B1ull*(uint64_t)(k +1))% TABLE_N;/* next address depends on v */}uint64_t t1 =bench_tsc_end(); sink += idx; samples[it]=(uint64_t)((double)(t1 - t0)*1e9/ hz);if((it &0xFFFF)==0&&bench_cpu()!= cpu0){ migrations++; cpu0 =bench_cpu();}}BENCH_KEEP(sink);long flt1 =minflt(), vcs1 =read_status_field("voluntary_ctxt_switches:"), ics1 =read_status_field("nonvoluntary_ctxt_switches:");printf("mode=%s iters=%llu chain=%d table=%llu MB (ending on cpu %d)\n", mode,(unsignedlonglong)iters, CHAIN,(unsignedlonglong)(TABLE_BYTES >>20),bench_cpu()); bench_stats st =bench_compute(samples, iters);bench_print_header("ns");bench_print("8 dependent loads",&st);printf("tail: p99/p50 = %.1fx p99.9/p50 = %.1fx max/p50 = %.0fx\n",(double)st.p99 /(double)st.p50,(double)st.p999 /(double)st.p50,(double)st.max /(double)st.p50);printf("during loop: minor page faults=%ld voluntary ctxsw=%ld involuntary ctxsw=%ld migrations seen=%d\n", flt1 - flt0, vcs1 - vcs0, ics1 - ics0, migrations);bench_hist_log2(samples, iters,"ns");free(samples);return0;}
◇
Finish the lab: write the evidence note
A lab is done when you can say what it showed on your machine — not when you have read it.
Which role are you preparing for?
It decides which problems come first, which drills open, which labs you see and how the Learn surface is organised. Change it any time from the switch in the top bar, or press Escape to look around first.