Lab 26: Benchmarking Methodology

Time: ~50 minutes | Prerequisites: Lab 25 | Hardware: Pico 2

Four ways your stopwatch will lie

A precise instrument used carelessly produces precise nonsense. Every mistake in this lab was made for real while building this course — including one that turned a reported "1.93× speedup" into an honest 1.26×. Let's tune in.

What You'll Build

Four demonstrations of benchmark failure, measured on your own board, and a five-line reporting format you can defend.

Learning Objectives

• Measure the cold-start penalty and explain why it varies by workload
• Justify best-of-N over mean for a deterministic algorithm
• Demonstrate the observer effect from fine-grained timing
• Identify what a timed region silently excludes
• Report a benchmark honestly

Concepts Introduced

ID	Concept
454	Cold Start Effect
455	Warm Up Discard
456	Best Of N
457	Minimum Sample
458	Variance Sources
459	Interrupt Interference
460	Observer Effect
461	Timing Overhead
462	Measurement Discipline
463	Prediction Before Measurement
464	Honest Reporting
465	What A Benchmark Excludes
466	Negative Result

Background

Run the lab and work through each lie in turn.

# Lab 26: Benchmarking Methodology
#
# You now have a cycle-accurate stopwatch. That is necessary but nowhere
# near sufficient -- a precise instrument used carelessly produces precise
# nonsense.
#
# This lab demonstrates four ways a benchmark lies to you. Every one of them
# was found the hard way while building this course, and one of them turned
# a reported "1.93x speedup" into an honest 1.26x.

import gc
import machine
import math
import fft_asm
from fftlab import FFT

machine.mem32[0xE000EDFC] = machine.mem32[0xE000EDFC] | (1 << 24)   # TRCENA
machine.mem32[0xE0001000] = machine.mem32[0xE0001000] | 1           # CYCCNTENA
FREQ = machine.freq()


def rd():
    return machine.mem32[0xE0001004]


def stats(values):
    lo = min(values)
    mean = sum(values) / len(values)
    var = sum((v - mean) ** 2 for v in values) / len(values)
    return lo, mean, var ** 0.5


N = 512
asm = fft_asm.FFT(N)
re, im = asm.make_buffers()
signal = [math.sin(2 * math.pi * 40 * i / N) for i in range(N)]


def load():
    for i in range(N):
        re[i] = signal[i]
        im[i] = 0.0


def run_once():
    load()
    s = rd()
    asm.run(re, im)
    e = rd()
    return (e - s) & 0xFFFFFFFF


# =========================================================================
# LIE 1 -- the first run is not like the others
# =========================================================================
print("=== LIE 1: the cold start ===")
print()
first = run_once()
rest = [run_once() for _ in range(15)]
lo, mean, sd = stats(rest)

print("first run ever : %d cycles" % first)
print("best of next 15: %d cycles" % lo)
print("penalty        : %.1f%%" % (100 * (first - lo) / lo))
print()
print("The very first call is measurably slower. Code paths are untouched,")
print("branch predictors are empty, the flash cache has not seen these")
print("instructions before.")
print()
print("How big this effect is DEPENDS on the workload. For the pure-Python")
print("FFT it is under 1%; for this assembly one it is over 15%. You cannot")
print("know in advance, which is exactly why you always discard a warm-up.")
print()
print("FIX: throw away the first run. Always.")


# =========================================================================
# LIE 2 -- the mean hides the truth
# =========================================================================
print()
print("=== LIE 2: mean versus best-of-N ===")
print()
runs = [run_once() for _ in range(30)]
lo, mean, sd = stats(runs)
hi = max(runs)

print("30 runs of the SAME code on the SAME data:")
print("  best   : %d cycles" % lo)
print("  mean   : %d cycles" % int(mean))
print("  worst  : %d cycles" % hi)
print("  stddev : %.0f cycles" % sd)
print("  spread : %.1f%% between best and worst" % (100 * (hi - lo) / lo))
print()
print("Identical work, different answers. Interrupts, the USB stack and")
print("memory refresh all steal time at random moments.")
print()
print("The distribution is ASYMMETRIC: nothing can make code run faster")
print("than it truly is, but plenty can make it slower. So there is a hard")
print("floor and a long tail -- and the floor is the honest number.")
print()
print("FIX: report best-of-N as the speed, and the spread as the honesty.")


# =========================================================================
# LIE 3 -- measuring changes what you measure
# =========================================================================
print()
print("=== LIE 3: the observer effect ===")
print()
REPS = 500

s = rd()
for i in range(REPS):
    x = 3.7 * 2.1
whole = (rd() - s) & 0xFFFFFFFF

total = 0
for i in range(REPS):
    a = rd()
    x = 3.7 * 2.1
    b = rd()
    total += (b - a) & 0xFFFFFFFF

print("%d tiny multiplications" % REPS)
print("  timed as one block : %8d cycles" % whole)
print("  timed one by one   : %8d cycles" % total)
print("  inflation          : %.1fx" % (total / whole))
print()
print("Same work. Timing each operation individually made it look almost")
print("three times more expensive, because each probe costs more than the")
print("multiply it was measuring.")
print()
print("This is not hypothetical: while building Lab 16 for this course,")
print("timing the FFT's 9 stages separately summed to 206,000 cycles when")
print("the whole transform took 127,000.")
print()
print("FIX: profile in pieces to FIND the bottleneck. Then measure the")
print("     whole operation to REPORT the number.")


# =========================================================================
# LIE 4 -- what the benchmark quietly leaves out
# =========================================================================
print()
print("=== LIE 4: what is not in the timed region ===")
print()
s = rd()
load()
load_cost = (rd() - s) & 0xFFFFFFFF

s = rd()
extra = fft_asm.FFT(N)
setup_cost = (rd() - s) & 0xFFFFFFFF

print("the FFT itself      : %8d cycles" % lo)
print("loading the buffers : %8d cycles  (%.0f%% of the FFT)"
      % (load_cost, 100 * load_cost / lo))
print("building the tables : %8d cycles  (%.1f FFTs' worth)"
      % (setup_cost, setup_cost / lo))
print()
print("Our headline number excludes both. That is defensible -- tables are")
print("built once at startup, and the microphone fills the buffers anyway --")
print("but it has to be STATED.")
print()
print("A real example from this project: one variant looked 15x SLOWER than")
print("the baseline until you noticed its timed region included a data")
print("format conversion the others did not need. Its actual transform was")
print("the fastest of the lot. Same code, opposite conclusion, depending")
print("entirely on where the stopwatch started.")


# =========================================================================
# Putting it together
# =========================================================================
print()
print("=== A benchmark you can defend ===")
print()


def benchmark(fn, trials=20):
    fn()                                # warm-up, discarded
    runs = [fn() for _ in range(trials)]
    return stats(runs)


gc.collect()
lo, mean, sd = benchmark(run_once)
print("%d-point assembly FFT, 20 trials after one discarded warm-up:" % N)
print("  best   : %8d cycles = %7.1f us" % (lo, lo * 1e6 / FREQ))
print("  mean   : %8d cycles = %7.1f us" % (int(mean), mean * 1e6 / FREQ))
print("  stddev : %8.0f cycles (%.1f%%)" % (sd, 100 * sd / mean))
print("  excludes table construction and buffer loading")
print()
print("Five lines. The last one is what separates a measurement from a")
print("marketing claim.")

Lie 1 — the first run is not like the others

first run ever : 133851 cycles
best of next 15: 125608 cycles
penalty        : 6.6%

Cold code paths, empty branch predictors, an untouched flash cache.

The size of this effect depends on the workload — under 1% for the pure-Python FFT, over 6% for the assembly one. You can't predict it, which is precisely why you always discard a warm-up.

Lie 2 — the mean hides the truth

30 runs of the SAME code on the SAME data:
  best   : 125509 cycles
  worst  : 134194 cycles
  spread : 6.9%

Identical work, different answers — interrupts, USB servicing, memory refresh.

The distribution is asymmetric. Nothing makes code run faster than it truly is; plenty makes it slower. So there's a hard floor and a long tail, and the floor is the honest number.

Report both

Best-of-N is the speed. The spread is the honesty. Quote the first alone and you're hiding how noisy your measurement was; quote the mean alone and you're reporting interrupt load as if it were your algorithm.

Lie 3 — measuring changes what you measure

500 tiny multiplications
  timed as one block :   772077 cycles
  timed one by one   :  1613746 cycles
  inflation          : 2.1x

Same work, twice the apparent cost — because each probe costs more than the multiply it measures.

This is not hypothetical. While building Lab 16, timing the FFT's nine stages separately summed to 206,000 cycles when the whole transform took 127,000.

Profile in pieces to find the bottleneck. Measure the whole thing to report it.

Lie 4 — what the timed region leaves out

the FFT itself      :   125509 cycles
loading the buffers :   656753 cycles  (523% of the FFT)
building the tables :  5660564 cycles  (45.1 FFTs' worth)

Filling the buffers costs five times more than the transform. Building the tables costs forty-five transforms.

Excluding both is defensible — tables are built once, and the microphone fills buffers anyway — but it must be stated.

A real example from this project

One FFT variant looked 15× slower than the baseline until someone noticed its timed region included a data-format conversion the others didn't need. Its actual transform was the fastest of the lot. Same code, opposite conclusion, depending entirely on where the stopwatch started.

Procedure

Step 1 — Predict

Before running: how much slower do you think the first run is? How much spread across 30 identical runs?

Write both down.

Step 2 — Run and compare

Work through the four lies. Which surprised you most?

Step 3 — Reproduce the 1.93× mistake

During development of this course, an early ad-hoc measurement reported a variant at 1.93× faster. The disciplined harness later reported 1.26×.

The entire difference was a cold-start baseline: the reference implementation's first run was being compared against the optimized version's warm runs.

Try it deliberately. Time the assembly FFT's first run, compare it against the best of 15 warm runs, and see how large a fake speedup you can manufacture without writing a single line of faster code.

Step 4 — Adopt the format

512-point assembly FFT, 20 trials after one discarded warm-up:
  best   :   126126 cycles =   840.8 us
  mean   :   127127 cycles =   847.5 us
  stddev :      872 cycles (0.7%)
  excludes table construction and buffer loading

Five lines. The last one is what separates a measurement from a marketing claim.

Troubleshooting

Symptom	Likely cause	Fix
No cold-start effect	Function already called	Restart the board first
Spread near 0%	Very short measurement	Time something longer
Inflation ratio ~1	Operation too large	Use something tiny
Negative "cost of instrumentation"	Noise exceeded the effect	Take the best of several

Challenges

1. Manufacture a lie. Produce a 1.5× "speedup" between two identical pieces of code using only bad methodology. Then write down which rule each trick broke.
2. Find your interrupt load. Run 100 trials and histogram them. Is the tail from one source or several?
3. Full disclosure. Rewrite Lab 24's stage report to state its exclusions explicitly.

Check Your Understanding

1. Why discard the first run, and why can't you predict how much it matters?
2. Why is best-of-N more honest than the mean for deterministic code?
3. What is the observer effect, and when does it dominate?
4. Give an example where excluding something from a timed region flips the conclusion.
5. What five things belong in a defensible benchmark report?

You can now measure honestly

Precise and trustworthy. Next lab uses it to price every layer of abstraction between Python and the metal.

---

Next: Lab 27: The Abstraction Ladder | Previous: Lab 25