Measuring performance

A program that is too slow needs one number before it needs a fix. Measuring that number is harder than it looks: the first run of a function is slower than the rest, an optimizer may delete the work that is being timed, and a single run cannot tell a real difference from the noise of the machine.

This lesson builds a measurement in four steps. It times a loop with Instant, adds a warm-up and several rounds, hides the work from the optimizer with std::hint::black_box, and puts the whole shape into a function that takes a closure. The last section is the mistake every C++ programmer makes once: subtracting a wall clock from a monotonic clock.

A clock around a loop

Instant::now is a reading of a monotonic clock, and elapsed is the difference between the reading and the same clock now. The number of iterations is fixed, so the measurement is comparable between runs, and the loop returns a value that the program prints, which is the first defence against an optimizer that removes work nobody uses.

The function adds i % 7 a million times. The last two fields of the output are the measurement, and they are written as comparisons rather than as a raw duration, because a printed number of microseconds changes on every run and would make the example look different each time.

use std::time::Instant; fn work(n: u64) -> u64 { let mut sum = 0; for i in 0..n { sum += i % 7; } sum } fn main() { let start = Instant::now(); let result = work(1_000_000); let elapsed = start.elapsed(); println!("{} {} {}", result, elapsed.as_micros() > 100, elapsed.as_secs() == 0); }

rustc --edition 2024 clock.rs
./clock

2999997 true true

The sum is the same on every run, and it proves that the loop ran: three million is the value of the million remainders added together. On the machine at the end of this lesson the call took about 1.5 milliseconds, which is why the first comparison is true and the second one says that the whole thing stayed under a second. The lesson on time covers the duration types that these readings return.

Warm up and repeat

One run measures the machine as much as the code: the first call pays for a cold instruction cache, a branch predictor that has not seen the loop yet, and a page fault on the stack. The fix is to call the function once for nothing, then to run several rounds and keep the best one, because noise only ever adds time.

The program warms up, then runs three rounds and keeps the smallest duration and the largest one. Each round prints its own result, and the last line compares the two durations, which is true whenever at least one round finished.

use std::time::Instant; fn work(n: u64) -> u64 { let mut sum = 0; for i in 0..n { sum += i % 7; } sum } fn main() { let _ = work(1_000_000); let mut best = u128::MAX; let mut worst = 0; for round in 1..=3 { let start = Instant::now(); let result = work(1_000_000); let elapsed = start.elapsed().as_nanos(); best = best.min(elapsed); worst = worst.max(elapsed); println!("round {} {} {}", round, result, elapsed > 0); } println!("best <= worst {}", best <= worst); }

rustc --edition 2024 warmup.rs
./warmup

round 1 2999997 true
round 2 2999997 true
round 3 2999997 true
best <= worst true

as_nanos returns a u128, which is the type to compare durations in: microseconds and milliseconds both truncate, and a fast function would look like zero. The value of best is the number a report should quote, and the spread between best and worst is the honest measure of how much the machine interfered.

Three rounds are enough to see a spread and not enough to average it out. A short job wants five or ten rounds, and a job that takes seconds wants one round per process, because a single call already outweighs the noise.

The loop the optimizer removes

A release build inlines a small function. If the result is unused and the loop has no side effect, the whole computation can disappear and the measurement becomes the time of an empty block. The standard library has an answer: std::hint::black_box takes a value and returns it, and the optimizer must assume that anything may happen to it, so the work around it stays.

The program hides the input and the result. The loop adds the remainders of a thousand numbers, and the answer is printed so that the reader can check that the hidden value came back unchanged.

use std::hint::black_box; fn sum(n: u64) -> u64 { let mut total = 0u64; for i in 0..n { total = total.wrapping_add(black_box(i) % 7); } total } fn main() { let value = sum(black_box(1000)); println!("{}", black_box(value)); }

rustc --edition 2024 -O blackbox.rs
./blackbox

2997

A thousand iterations cover a hundred and forty-two full cycles of seven, worth twenty-one each, and six more values from zero to five, which add fifteen: the answer is 2997 and it does not depend on the optimization level. Wrap the input of the timed function, and the result if nothing reads it, and the measurement is of the work rather than of the optimizer's opinion about it.

black_box is not a barrier for correctness and it does not change the value. It is a promise to the compiler that the caller may look at the bytes, which is exactly the pessimism a benchmark needs. The lesson on profiles explains why a debug build measures something else entirely: no inlining, no constant folding and overflow checks on every addition.

A harness that reports

Once the shape is clear it belongs in a function: a name, a number of rounds and a job. A generic parameter with the FnMut bound accepts a closure, so the harness can time any piece of code without knowing what it does, and the closure may update its own state.

The job below sums the remainders of a hundred thousand numbers with an iterator. The harness keeps the checksum that the job returned, which proves the work happened, and prints it with the name.

use std::time::Instant; fn bench(name: &str, rounds: u32, mut job: impl FnMut() -> u64) { let mut best = u128::MAX; let mut checksum = 0; for _ in 0..rounds { let start = Instant::now(); checksum = job(); best = best.min(start.elapsed().as_nanos()); } println!("{}: checksum {}", name, checksum); println!("sane: {}", best > 0 && best < 1_000_000_000); } fn main() { bench("sum 100000", 3, || (0..100_000u64).map(|i| i % 7).sum()); }

rustc --edition 2024 harness.rs
./harness

sum 100000: checksum 299995
sane: true

The checksum is the same number the loop would compute by hand, and the sanity check catches the two ways a measurement goes wrong without a word: a zero means the work was removed, and a second or more means the harness timed something else. A real report prints best as well; in this run it was under a hundred nanoseconds, and the number moves with the machine.

The lesson on closures explains why the parameter is mut job: the harness calls the closure several times, so the binding has to be mutable even though the caller does not write mut at the call site. The last capstone lesson uses exactly this harness to compare two versions of the same search.

Two clocks do not subtract

Instant and SystemTime are different types for a reason: one cannot go backwards and the other is the wall clock a user can change. The compiler refuses to mix them, and the message names the two types at the argument.

The program takes one reading of each and asks the wall clock for the time since the monotonic one. The method exists on SystemTime and takes another SystemTime, so the Instant is the wrong argument.

use std::time::{Instant, SystemTime}; fn main() { let start = Instant::now(); let wall = SystemTime::now(); let elapsed = wall.duration_since(start); println!("{:?}", elapsed); }

rustc --edition 2024 two_clocks_err.rs

error[E0308]: mismatched types
--> two_clocks_err.rs:6:39
|
6 | let elapsed = wall.duration_since(start);
| -------------- ^^^^^ expected `SystemTime`, found `Instant`
| |
| arguments to this method are incorrect
|
note: method defined here
--> /rustc/31fca3adb283cc9dfd56b49cdee9a96eb9c96ffd/library/std/src/time.rs:630:11

error: aborting due to 1 previous error

For more information about this error, try `rustc --explain E0308`.

The fix is to measure with one clock and convert at the edges. A benchmark uses Instant for both readings, and a log line uses SystemTime for both, with duration_since(UNIX_EPOCH) when a timestamp is needed. The next lesson finds out where the time goes instead of how much of it there is.

Exercises

  1. Time a function that sorts a thousand numbers five times and print the best round with as_micros.
  2. Add a black_box around the input of the sort and compare the two measurements.
  3. Change the harness so that it returns the best duration and the caller prints the name and the number.

Questions

A new set of questions in a new order every time. Choose one answer for each, then check.

  1. Why does a benchmark warm up before it measures?

    Answer

    The first call fills caches and resolves lazy work, so it is slower

    The first run pays for cold caches and uninitialized state, which the later rounds do not.

  2. What does std::hint::black_box do?

    Answer

    It hides a value from the optimizer while returning it unchanged

    The compiler must assume the value is read elsewhere, so the work around it stays.

  3. Which reading measures an interval that cannot go backwards?

    Answer

    Instant::now

    Instant is monotonic, while SystemTime is the wall clock that can be adjusted.

  4. Why does a benchmark keep the best round instead of the average?

    Answer

    Noise only adds time, so the smallest reading is closest to the work itself

    Interference from the machine adds time and never removes it, so the minimum is the cleanest reading.

  5. What does elapsed.as_nanos() return, and why does a benchmark prefer it?

    Answer

    A u128 of nanoseconds, which does not truncate a fast call

    Microseconds and milliseconds truncate, and a short call would measure as zero.

  6. What does this program print? use std::time::{Duration, Instant}; fn main() { let start = Instant::now(); std::thread::sleep(Duration::from_millis(5)); let elapsed = start.elapsed(); println!("{}", elapsed >= Duration::from_millis(5)); println!("{}", elapsed.as_secs() == 0); }

    Answer

    true / true

    A sleep lasts at least the requested time and five milliseconds are less than a second.

  7. What does this program print? use std::time::Duration; fn main() { let total = Duration::from_millis(1500); let part = total / 3; println!("{} {}", part.as_millis(), total.subsec_millis()); }

    Answer

    500 500

    A third of 1500 milliseconds is 500, and the fraction of the original second is 500 milliseconds.

  8. What does this program print? use std::hint::black_box; fn main() { let n = black_box(4u32); let value = (0..n).fold(0u32, |acc, i| acc + i * i); println!("{}", black_box(value)); }

    Answer

    14

    The squares below four are zero, one, four and nine, and their sum is fourteen.

  9. What does this program print? use std::time::{Duration, Instant}; fn work(n: u64) -> u64 { (0..n).map(|i| i % 2).sum() } fn main() { let start = Instant::now(); let sum = work(10); let elapsed = start.elapsed(); println!("{} {}", sum, elapsed.as_secs() == 0); }

    Answer

    5 true

    Five odd numbers below ten sum to five, and ten additions take far less than a second.

  10. What is the first line of the compiler output for this program? use std::time::{Instant, SystemTime}; fn main() { let start = Instant::now(); let wall = SystemTime::now(); let elapsed = wall.duration_since(start); println!("{:?}", elapsed); }

    Answer

    error[E0308]: mismatched types

    The method takes a SystemTime and the argument is an Instant, so the types do not match.

The code on this page was built with rustc 1.96.1 and run on Alpine Linux 3.24.3 (x86_64) in a Docker container.

Article author: Arthur Isaev

Banner image