← Labsperf-04Measurement●●○○

Microbenchmark pitfalls — measuring the wrong thing

perf/04_microbench_pitfalls.cneeds: tools/bench.h, objdump, nm4 steps

0/4 steps

what this lab teaches

A microbenchmark is a program whose ONLY purpose is to be measured, and the optimizer does not know that. Six ways the number lies, each with the fix, all demonstrated by ONE binary and proven by reading its machine code: dce the result is unused -> the loop is deleted -> "0 ns" constfold the input is a compile-time constant -> answer is a literal closedform even with an opaque input, some loops become a formula keep the fix: opaque input (argv) + BENCH_KEEP(result) volatile the WRONG fix: `volatile` forces a store per iteration and forbids vectorization: you measure a program nobody ships warmup first-touch page faults inflate the first pass timer the clock itself has a cost and a resolution

evidence to leave with

Disassembly proves each 0 ms row; volatile 8x slower than the shipped loop; timer costs measured

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/04_microbench_pitfalls (-O2), .O0 variant

walk it, one step at a time

run this

$ ../tools/pin.sh -q ./bin/04_microbench_pitfalls all

what it printed on the machine that wrote this lab

dce               0.000 ms     0.000 ns/iter   sum unused -> loop deleted
constfold         0.000 ms     0.037 ns/iter   constant input -> answer computed at build time
closedform        0.000 ms     0.000 ns/iter   opaque input, but SCEV replaced the loop by a formula
keep             29.636 ms     0.442 ns/iter   opaque input + BENCH_KEEP -> real (vectorized) number
volatile        235.609 ms     3.511 ns/iter   volatile accumulator -> measures the harness
warmup-1        129.699 ms    30.923 ns/iter   pass 1 over 256 MB, one write per line
warmup-2         40.092 ms     9.559 ns/iter   pass 2 over 256 MB, one write per line
timer-ns        269.922 ms    26.992 ns/iter   cost of one clock_gettime (vDSO)
timer-tsc       125.318 ms    12.532 ns/iter   cost of one rdtsc
timer-tscp      241.267 ms    24.127 ns/iter   cost of one rdtscp+lfence (serialized)
tsc rate: 2.496 GHz (calibrated against CLOCK_MONOTONIC)

Three "0 ms" rows for three different reasons, an 8x gap between the right and the wrong way to keep a result alive, and a 3x warm-up effect.

run this

$ objdump -d --no-show-raw-insn ./bin/04_microbench_pitfalls | sed -n '/<sum_dce>:/,/ret/p'

what it printed on the machine that wrote this lab

0000000000400fe0 <sum_dce>:
  400fe0:	movslq -0x4(%rdi,%rsi,4),%rax
  400fe5:	ret
Two instructions: load a[n-1], return. The 64M-iteration sum was never
used, so computing it was dead code and the optimizer removed it.
"It runs in 0 ns" means "it does not run". (A first draft returned a
constant instead of a[n-1]; clang then deleted the CALL too, and `nm`
showed no sum_dce symbol at all. Dead-code removal is interprocedural.)

run this

$ objdump -d --no-show-raw-insn ./bin/04_microbench_pitfalls | sed -n '/<sum_squares_const>:/,/ret/p'

what it printed on the machine that wrote this lab

0000000000400ff0 <sum_squares_const>:
  400ff0:	mov    $0x13d6a2dc,%eax
  400ff5:	ret
0x13d6a2dc = 332833500 = sum of i*i for i < 1000. The loop ran inside
clang, at build time. Any benchmark whose inputs are visible constants
can end like this — including "realistic" ones where the size is a
#define and the data a static initializer.

`closedform` is subtler: the input n comes from argv, yet:

run this

$ objdump -d --no-show-raw-insn ./bin/04_microbench_pitfalls | sed -n '/<sum_squares>:/,/ret/p'

what it printed on the machine that wrote this lab

0000000000401000 <sum_squares>:
  401000:	test   %rdi,%rdi
  401003:	je     40103c <sum_squares+0x3c>
  401005:	lea    -0x1(%rdi),%rax
  401009:	lea    -0x2(%rdi),%rcx
  40100d:	mul    %rcx
  ...
  401025:	imul   %rcx,%rsi
  401029:	add    %rdi,%rsi
  ...
  40103b:	ret

No loop at all: LLVM's scalar evolution (SCEV) recognized sum(i*i) as a polynomial in n and emitted the closed form, ~15 instructions for any n. A benchmark "of a loop" that the compiler can solve in O(1) measures nothing. Real loops have data the compiler cannot see (loads).

run this

$ objdump -d --no-show-raw-insn ./bin/04_microbench_pitfalls | sed -n '/<sum_keep>:/,/^$/p' | sed -n '14,30p'

what it printed on the machine that wrote this lab

    401070:	movq   (%rdi,%rax,4),%xmm2
    401075:	movq   0x8(%rdi,%rax,4),%xmm3
    40107b:	pxor   %xmm4,%xmm4
    40107f:	pcmpgtd %xmm2,%xmm4
    401083:	punpckldq %xmm4,%xmm2
    401087:	paddq  %xmm2,%xmm0
    ...
    40109b:	add    $0x4,%rax
    40109f:	cmp    %rax,%rcx
    4010a2:	jne    401070 <sum_keep+0x30>
  A real loop over an opaque n, vectorized: two 64-bit loads, sign-extend
  (pcmpgtd + punpckldq is how baseline SSE2 widens int -> long), two paddq,
  four elements per iteration. 0.44 ns/element = 256 MB in 30 ms = 8.6 GB/s,
  i.e. this loop is memory-bandwidth bound on this laptop, and no amount of
  AVX would change the number (try -march=native: TRY THIS #4 in lab 02).

  Now `volatile`:

run this

$ objdump -d --no-show-raw-insn ./bin/04_microbench_pitfalls | sed -n '/<sum_volatile>:/,/^$/p' | sed -n '12,18p'

what it printed on the machine that wrote this lab

    401100:	movslq (%rdi,%rcx,4),%rdx
    401104:	add    %rdx,-0x8(%rsp)
    401109:	movslq 0x4(%rdi,%rcx,4),%rdx
    40110e:	add    %rdx,-0x8(%rsp)
  Scalar, and every element does a read-modify-write of the stack slot
  holding the volatile accumulator: a store-to-load dependency of ~5 cycles
  per element. 3.5 ns/element, 8x slower than the shipped code. You did
  not measure "summing an array"; you measured "volatile". This is the
  most common wrong benchmark on the internet.

HOW TO READ THE `warmup` ROWS:
  pass 1 touches 256 MB of fresh pages: every 4 KiB page costs a minor page
  fault (the kernel allocates and zeroes a page on first write). pass 2 pays
  only memory bandwidth. Here 3.2x; on another run it was 10x — the
  first-touch cost depends on what the kernel has to do (zeroing, page
  reclaim, huge pages: THP is `madvise` on this box, so no). That is the
  "warm-up" every benchmark framework discards. If your real workload runs
  ONCE on fresh memory, pass 1 IS the real cost: then measure pass 1 on
  purpose, and consider MAP_POPULATE / pre-faulting (lab 05).

HOW TO READ THE `timer` ROWS:
  clock_gettime(CLOCK_MONOTONIC) is a vDSO call: no kernel entry, but ~27 ns
  here. rdtsc ~12 ns; rdtscp+lfence (serialized, lab 05) ~24 ns. None can
  time a 1 ns operation: put N of them in a loop and divide, or accept the
  resolution floor. Everything you time includes the timer's cost once;
  subtract it only if it is a meaningful fraction. (Numbers are for this
  CPU; measure yours with `timer` before trusting sub-100 ns results.)

THE -O0 TRAP (the opposite lie):

run this

$ ../tools/pin.sh -q ./bin/04_microbench_pitfalls.O0 dce

what it printed on the machine that wrote this lab

  dce              85.941 ms     1.281 ns/iter   sum unused -> loop deleted

run this

$ ../tools/pin.sh -q ./bin/04_microbench_pitfalls.O0 constfold

what it printed on the machine that wrote this lab

  constfold         0.002 ms     1.564 ns/iter   constant input -> answer computed at build time
  closedform       70.666 ms     1.053 ns/iter   opaque input, but SCEV replaced the loop by a formula

At -O0 the dead loop "costs" 86 ms and the polynomial loop 71 ms. Neither program exists in production. -O0 numbers describe the compiler's worst-case scaffolding, not your algorithm. Benchmark what you ship.

usage

./bin/04_microbench_pitfalls dce|constfold|keep|volatile|warmup|timer|all [n]

the rules

K1. Inputs come from outside the compiler's sight (argv, a file, a volatile read ONCE before the loop). Sizes included. K2. Every result is consumed: BENCH_KEEP(result) after the loop, not inside it. K3. Never make the accumulator volatile. If you must stop a loop from being vectorized/reassociated, use a barrier or a `-fno-…` flag, and KNOW that you changed the program. K4. Read the asm of the timed region once. If it is not what you meant to measure, the number is meaningless no matter how stable. K5. Report timer overhead and warm-up separately from the result, and benchmark the optimization level you ship.

take it further

1. Move BENCH_KEEP(r) INSIDE the loop of sum_keep. How much slower? Why? (It forces the running sum into a register/memory each iteration and blocks vectorization — the same disease as volatile, milder.) 2. Change sum_squares to `s += i * i * i`. Does SCEV still find a closed form? (Read the asm.) What about `s += a[i] * i`? 3. Run `keep` with n = 1M (4 MB, fits in L2) and n = 4M (16 MB, L3): watch ns/element drop as the loop stops being DRAM-bound. ============================================================

read the source · perf/04_microbench_pitfalls.c

#include "../tools/bench.h"

/* The honest kernel: sum an int array. At -O2 clang vectorizes it (SSE2 at
 * the baseline x86-64 target), so the real cost is memory bandwidth. */
__attribute__((noinline)) static uint64_t sum_keep(const int *a, size_t n) {
    uint64_t s = 0;
    for (size_t i = 0; i < n; i++) s += (uint64_t)a[i];
    return s;
}

/* PITFALL dce: same loop, result thrown away -> the loop is deleted. The
 * function still exists (it returns the last element, which the caller
 * cannot compute without calling it), but its body has no loop. */
__attribute__((noinline)) static uint64_t sum_dce(const int *a, size_t n) {
    uint64_t s = 0;
    for (size_t i = 0; i < n; i++) s += (uint64_t)a[i];
    return (uint64_t)a[n - 1];                   /* <-- s unused: the loop is dead */
}

/* PITFALL constfold: a loop whose result the compiler can compute itself.
 * LLVM's scalar evolution (SCEV) knows sum(i*i) has a closed form; with a
 * constant N the answer is a literal, and even with an OPAQUE n there is no
 * loop, just a polynomial. */
__attribute__((noinline)) static uint64_t sum_squares(uint64_t n) {
    uint64_t s = 0;
    for (uint64_t i = 0; i < n; i++) s += i * i;
    return s;
}
static inline uint64_t sum_squares_inl(uint64_t n) {   /* inlinable copy */
    uint64_t s = 0;
    for (uint64_t i = 0; i < n; i++) s += i * i;
    return s;
}
__attribute__((noinline)) static uint64_t sum_squares_const(void) {
    return sum_squares_inl(1000);                /* <-- folded to a literal at build time */
}

/* PITFALL volatile: the "fix" that measures a different program. The
 * volatile accumulator forces a load+store per element and forbids
 * vectorization: 8x slower than the code you actually ship. */
__attribute__((noinline)) static uint64_t sum_volatile(const int *a, size_t n) {
    volatile uint64_t s = 0;
    for (size_t i = 0; i < n; i++) s += (uint64_t)a[i];   /* <-- store every iteration */
    return s;
}

static void row(const char *name, uint64_t ns, uint64_t n, const char *note) {
    printf("%-10s %12.3f ms  %8.3f ns/iter   %s\n", name, (double)ns / 1e6, (double)ns / (double)n, note);
}

int main(int argc, char **argv) {
    const char *mode = argc > 1 ? argv[1] : "all";
    size_t n = argc > 2 ? strtoull(argv[2], 0, 10) : (64u << 20);    /* 64M ints = 256 MB, opaque */
    int all = !strcmp(mode, "all");
    uint64_t t0, r;

    int *a = (int *)malloc(n * sizeof *a);
    for (size_t i = 0; i < n; i++) a[i] = (int)(i & 0xFF);            /* also pre-faults the pages */

    if (all || !strcmp(mode, "dce")) {
        t0 = bench_ns(); r = sum_dce(a, n); BENCH_KEEP(r);
        row("dce", bench_ns() - t0, n, "sum unused -> loop deleted");
    }
    if (all || !strcmp(mode, "constfold")) {
        t0 = bench_ns(); r = sum_squares_const(); BENCH_KEEP(r);
        row("constfold", bench_ns() - t0, 1000, "constant input -> answer computed at build time");
        t0 = bench_ns(); r = sum_squares(n); BENCH_KEEP(r);
        row("closedform", bench_ns() - t0, n, "opaque input, but SCEV replaced the loop by a formula");
    }
    if (all || !strcmp(mode, "keep")) {
        t0 = bench_ns(); r = sum_keep(a, n); BENCH_KEEP(r);
        row("keep", bench_ns() - t0, n, "opaque input + BENCH_KEEP -> real (vectorized) number");
    }
    if (all || !strcmp(mode, "volatile")) {
        t0 = bench_ns(); r = sum_volatile(a, n); BENCH_KEEP(r);
        row("volatile", bench_ns() - t0, n, "volatile accumulator -> measures the harness");
    }
    if (all || !strcmp(mode, "warmup")) {
        size_t bytes = 256ull << 20;
        unsigned char *buf = (unsigned char *)malloc(bytes);
        for (int pass = 1; pass <= 2; pass++) {
            t0 = bench_ns();
            for (size_t i = 0; i < bytes; i += 64) buf[i] = (unsigned char)i;
            BENCH_KEEP(buf);
            char note[64]; snprintf(note, sizeof note, "pass %d over 256 MB, one write per line", pass);
            row(pass == 1 ? "warmup-1" : "warmup-2", bench_ns() - t0, bytes / 64, note);
        }
        free(buf);
    }
    if (all || !strcmp(mode, "timer")) {
        uint64_t reps = 10000000, acc = 0;
        t0 = bench_ns(); for (uint64_t i = 0; i < reps; i++) acc += bench_ns(); BENCH_KEEP(acc);
        row("timer-ns", bench_ns() - t0, reps, "cost of one clock_gettime (vDSO)");
        t0 = bench_ns(); for (uint64_t i = 0; i < reps; i++) acc += bench_tsc(); BENCH_KEEP(acc);
        row("timer-tsc", bench_ns() - t0, reps, "cost of one rdtsc");
        t0 = bench_ns(); for (uint64_t i = 0; i < reps; i++) acc += bench_tsc_end(); BENCH_KEEP(acc);
        row("timer-tscp", bench_ns() - t0, reps, "cost of one rdtscp+lfence (serialized)");
        printf("tsc rate: %.3f GHz (calibrated against CLOCK_MONOTONIC)\n", bench_tsc_hz() / 1e9);
    }
    free(a);
    return 0;
}

◇

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.