7 · The number Draft
The measurement ladder and observer budget
On this page
7.3 The ladder of a measurement
Every act of measuring costs time and changes what it measures, and on a path whose budget is 1 µs the cost of the ruler is often the same size as the thing it rules. This ladder prices each act a program or a tool can use to take a number, cheapest first, and says what each does to the code it watches.
A few of the rows name tools that run beside the program rather than inside it. A hardware performance counter is a register in the core that counts an event, cycles, instructions, cache misses, while the program runs, with no instruction of the program’s own; perf stat sets a few of them up, lets the program run, and prints the totals. perf record is a sampling profiler: it has a counter raise an interrupt every so often, and at each interrupt it writes down where the program was. strace prints every system call a program makes, and ltrace every call into a shared library; both work by ptrace, the kernel’s interface for one process to stop another and inspect it, which a debugger also uses to stop a program at a breakpoint, an instruction it has marked. Costs are set, as before, against the budget of 1 µs, 4,000 cycles at 4 GHz.
| Act of measuring | Typical cost | Cycles at 4 GHz | What it does to the thing measured |
|---|---|---|---|
| Store a sample into a preallocated array | 1 ns | 4 | one store; a fresh line every eight samples, streaming through the cache at 8 MB per million and pushing the program’s own lines out |
Vec::push of a sample | 1–2 ns within capacity | 4–8 | at each doubling, a copy of every sample so far, 2–3 µs at 32 KB and 2–3 ms at 32 MB, or tens of µs if the kernel remaps the pages instead; then 0.5–1 µs per fresh 4 KB page as it is first touched: a tail the measurement adds to the samples it is taking |
rdtsc | 5–10 ns | 20–40 | nothing else; unfenced, it may read before the work it closes has finished |
Histogram::record | 10–30 ns | 40–120 | a few branches, a leading_zeros and one increment in a 25–170 KB array; the common values’ counters stay in L1, a rare value’s line comes from L2 or L3 |
Instant::now() through the vDSO | 20–25 ns | 80–100 | a fenced read plus the [vvar] page’s line |
lfence; rdtsc, or rdtscp | 20–30 ns | 80–120 | the core may not overlap the work before the read with the work after it |
Instant::now() as a system call | 300 ns–2 µs | 1,200–8,000 | a kernel entry and exit, and the lines and branch history the kernel’s code displaces |
A println! or log line in the loop | 1–5 µs | 4,000–20,000 | formatting, often into a new String; the lock on standard output; a write system call, which waits when the terminal or pipe behind it is slow |
perf stat, counting | under 1% of the run | none inside the program; the kernel saves and restores the counters at every context switch, and with more events than the core’s 4–8 programmable counters it time-shares them and scales the counts | |
perf record at 4,000 samples a second | 1–5% of the thread’s time | an interrupt every 250 µs, each a few microseconds of handler and stack walk dropped on whatever message is in flight, and a cache line or more per sample written to perf’s buffer | |
strace or ltrace | each traced call 10–100× slower | the thread stops twice per call while another process reads its registers and prints | |
| A debugger breakpoint | milliseconds to minutes | the thread is not slow but stopped, and everything waiting on it queues |
Read the table against the budget. Storing a sample is a thousandth of it. A bare clock read is 0.5–1%, a record 1–3%, and a fenced read, the cheapest timestamp that can be trusted, 2–3%. A clock read that has fallen back to the kernel is a third of a budget to two budgets, and a log line one to five: a loop that prints once per message has a latency set by its printing. The last four rows, the tools that run beside the program, cost little on average, which is how they are usually described, and that average is the wrong figure for a latency: perf record spends its 1–5% as a few-microsecond stall every 250 µs, each one landing on some message, and strace turns the system calls it watches into the slowest thing the program does.
Direct and indirect cost
The direct cost of a measurement is its own instructions: the 20–30 ns of a fenced read, the 10–30 ns of a record. The indirect cost is what it does to the code around it, and it can be larger.
A fence stops overlap. An out-of-order core holds a few hundred instructions in flight, so the end of one message’s work normally runs alongside the start of the next one’s loads; an lfence between them makes the core finish everything before it starts anything after. Work that cost 50 ns when overlapped can cost 70 ns when cut in two, and the extra 20 ns appears nowhere in the read’s own price. A record touches a cache line: the histogram’s common values, a few hundred nanoseconds wide, share a few dozen lines that stay in L1, but a rare value’s counter sits in a line from L2 at 4 ns or L3 at 10–40 ns, so the record is slowest exactly on the message that was already slow. An array of samples streams a fresh line in every eight samples and, over a million messages, pushes 8 MB of its own lines through the caches the program depends on. Each inlined record adds branches for the predictor to hold and tens of bytes of code to the loop.
The largest indirect cost changes behaviour rather than time. A strategy thread made 100 ns slower per message by its instruments falls further behind in a burst, so each drain finds more messages waiting, the batches grow, and the publish-once rule pays one line transfer for more messages than before. The instrumented loop is not the loop with a delay added; it is a loop with different batch sizes, and some of its stages may even look cheaper than they are in the uninstrumented program. Measuring a program changes which program is measured, and the only check on that is to measure the measurement.
The observer budget
A measurement is worth having only if it changes the number by less than the precision wanted from it. For a hot path with a 1 µs budget, that sets an observer budget of 2–5% of the budget, 20–50 ns per message, for everything the instrumentation does on the path.
That is one fenced read and one record, or two reads and nothing else. Three consequences follow, each from that arithmetic. A stage boundary is marked by a single read, shared by the stage it ends and the one it begins, never by a pair around each stage. The conversion from ticks to nanoseconds, the record and any bookkeeping happen after the last read of the timed region, where they delay the next message but are not inside this one’s number. And whatever does not fit, a breakdown by stage, a log line, a profile, belongs in a separate run of a separate build whose own cost is measured by comparing it with the build that does fit. The observer budget is also why a log line has no place in a loop being timed: at 1–5 µs it is the observer budget twenty to two hundred times over.
What it costs
Four ways of instrumenting the capstone, priced per message at 100,000 messages a second, where most batches hold one message:
| Instrumentation | Work added per message on the hot threads | Inside that message’s own total | Against the 1 µs budget |
|---|---|---|---|
| Headline build: t0 computed, t3 read once per batch, one record | 30–50 ns | 5–25 ns, the closing read | 3–5% |
| Stages build: t1 and t2 read per message as well, four records | 100–150 ns | 50–90 ns, three reads | 10–15% |
| A log line per message | 1–5 µs | all of it, for every message queued behind | 100–500% |
Headline build under perf record at 4,000 Hz | 1–5% of the thread on average | 2–10 µs, for 1–4% of messages | the whole p99 |
The last row deserves its arithmetic. At 4,000 samples a second, each an interrupt of 2–10 µs, and one message every 10 µs on average, a message is in flight or arrives during the handler for something between a fifth of the interrupts and all of them: 800–4,000 messages a second, 1–4% of the 100,000. That is the p99, and above it the p99.9 is set by perf. A profile and a latency histogram are therefore taken in separate runs.