142. Measuring Rust performance

A number from the wrong build

You port a hot loop to Rust, time it with cargo run, and it is slower than your JavaScript. Before you blame Rust, look at the first line Cargo prints: Finished `dev` profile [unoptimized + debuginfo]. You measured the build made for debugging.

Debug and release

Cargo builds with a profile. cargo build and cargo run use dev; --release uses release. Their defaults differ like this^[1]:

[profile.dev]
opt-level = 0
debug-assertions = true
overflow-checks = true

[profile.release]
opt-level = 3
debug-assertions = false
overflow-checks = false

opt-level = 0 means no optimization at all. How much that matters: I built drip-rs both ways (rustc 1.97, the book’s shared cloud VM) and ran fib.drip three times each. Debug took 16.0 to 16.6 seconds, release 1.4 to 1.6. Ten times. drip-rs’s own Cargo.toml goes further, with lto = true and codegen-units = 1, which let the optimizer see the whole program at once at the price of slower builds.

The two builds also behave differently. Integer overflow panics in a debug build and wraps around in release^[2]. Run this one: it panics with attempt to add with overflow. Built with -O on the same machine, it printed 255 + 1 = 0.

use std::hint::black_box;

fn main() {
    // black_box hides the 255, so the
    // check happens at run time.
    let x: u8 = black_box(255);
    let y = x + 1;
    println!("255 + 1 = {y}");
}

A note on this book. The Run button sends Rust to the official Rust Playground in debug mode, so any time it prints is a debug time, on a server you don’t control. The “Open in Rust Playground” link lets you switch the mode to Release there.

The loop that vanished

Now build for release and time a sum of a million f64s, done 100 times. The example below does it twice: once plainly, once with every input and output wrapped in black_box. On the book’s VM, with -O, three runs printed:

plain: 401ns    boxed: 69.389644ms
plain: 190ns    boxed: 65.083303ms
plain: 191ns    boxed: 68.060892ms

A hundred million additions in 190 ns is about 500 per picosecond. They didn’t happen. sum has no side effects and its result was dropped, so the optimizer deleted the loop: chapter 24’s dead code elimination, now in a compiler that is far better at it than a JIT with a time budget. In debug, both loops took 285 to 343 ms, because nothing was deleted.

use std::hint::black_box;
use std::time::Instant;

fn sum(xs: &[f64]) -> f64 {
    let mut s = 0.0;
    for x in xs {
        s += x;
    }
    s
}

fn main() {
    let xs: Vec<f64> = (0..1_000_000)
        .map(|i| i as f64)
        .collect();

    let t = Instant::now();
    for _ in 0..100 {
        sum(&xs);
    }
    let d = t.elapsed();
    println!("plain: {d:?}");

    let t = Instant::now();
    for _ in 0..100 {
        black_box(sum(black_box(&xs)));
    }
    let d = t.elapsed();
    println!("boxed: {d:?}");
}

std::hint::black_box is the fix. It returns its argument unchanged, but the compiler is told to assume the value could be used in any way at all. Wrapping the input stops the compiler from reasoning about xs; wrapping the result stops it from throwing the sum away^[3].

Statistics: criterion

One time is one sample from a noisy process. Stable Rust’s cargo bench runs a benches/ target, but the built-in #[bench] attribute is nightly-only, so the Cargo book points to criterion for stable Rust^[4]. The book’s runner can’t run it (it compiles single files with no crates, in debug mode), so I ran it with cargo 1.97, which fetched criterion 0.5.1 from crates.io. The benchmark, in benches/sum.rs, with harness = false in Cargo.toml:

fn bench(c: &mut Criterion) {
    let xs: Vec<f64> = (0..1000)
        .map(|i| i as f64)
        .collect();
    c.bench_function("sum 1000", |b| {
        b.iter(|| sum(black_box(&xs)))
    });
}
criterion_group!(benches, bench);
criterion_main!(benches);

b.iter passes each result through black_box itself. cargo bench builds with the bench profile, which inherits from release^[1]. Step through what happens next:

The last step is the honest lesson. I ran the same code twice, and the second run said change: [-6.08% -4.28% -2.57%] (p = 0.00 < 0.05) Performance has improved. The difference was real, in the sense that the timings really did differ. Its cause was the VM’s other tenants. Criterion’s own guide warns that small, deterministic benchmarks are this sensitive, and its default noise threshold of 1% was too small here^[5].

Your turn

// Quartiles by nearest rank: sort, then
// take the values at n/4 and 3n/4.
fn quartiles(xs: &[f64]) -> (f64, f64) {
    let mut s = xs.to_vec();
    s.sort_by(f64::total_cmp);
    let n = s.len();
    (s[n / 4], s[3 * n / 4])
}

fn fences(xs: &[f64], k: f64)
    -> (f64, f64) {
    todo!()
}

// (mild, severe), as criterion counts.
fn outliers(xs: &[f64])
    -> (usize, usize) {
    todo!()
}

What you learned

• Time only a release build: opt-level = 3, no overflow checks. The dev default was ten times slower on drip-rs’s fib.
• Debug panics on integer overflow; release wraps.
• An unused result invites the optimizer to delete the work. black_box hides inputs and keeps results, on a best-effort basis.
• Criterion fits a line through many samples, gives a confidence interval, counts outliers with Tukey’s fences, and compares runs. On a noisy machine it can call noise an improvement.
• drip-rs times whole programs, best of three; engine/rust times warm calls in process. Both report the machine and the noise.