Step 6 of 6

Benchmarks and profilers

Guessing where a program spends its time is famously unreliable, even for experts. Two tools replace guessing: profilers tell you where the time goes, and benchmarks tell you how much a change helped.

Benchmarks with criterion

criterion is the standard benchmarking crate. It runs your code many times, warms up first, and uses statistics to tell real changes from noise:

# Cargo.toml
[dev-dependencies]
criterion = "0.5"   # check crates.io for the current version

[[bench]]
name = "word_count"
harness = false

// benches/word_count.rs
use criterion::{criterion_group, criterion_main, Criterion};
use std::hint::black_box;
use my_app::count_words;

fn bench_count_words(c: &mut Criterion) {
    let text = std::fs::read_to_string("benches/sample.txt").unwrap();
    c.bench_function("count_words 1 MB", |b| {
        b.iter(|| count_words(black_box(&text)))
    });
}

criterion_group!(benches, bench_count_words);
criterion_main!(benches);

$ cargo bench
count_words 1 MB        time:   [2.8131 ms 2.8297 ms 2.8476 ms]
                        change: [-41.205% -40.731% -40.249%] (p = 0.00 < 0.05)
                        Performance has improved.

• cargo bench always builds with optimizations.
• std::hint::black_box hides a value from the optimizer. Without it, the compiler may notice the result is unused and delete the work you meant to measure.
• The three times are a confidence interval; the change line compares with the previous run.
• Benchmark with realistic input. A function that's fastest on 10 items may be slowest on 10 million.

A hand-rolled Instant::now() timing loop is fine for a rough idea, in a release build, but it won't tell you whether a 3% difference is real.

Profilers: where does the time go?

A sampling profiler interrupts the program thousands of times per second and records which function was running. On Linux:

$ cargo build --release            # with debug = true in [profile.release]
$ perf record -g ./target/release/report big_input.txt
$ perf report                      # functions sorted by share of samples

Flamegraphs draw the same data as a picture. cargo install flamegraph, then cargo flamegraph --bin report -- big_input.txt writes flamegraph.svg (it builds in release mode by default). How to read one:

• Each box is a function; the boxes on top of it are the functions it called.
• Width is the share of samples, so wide boxes are where the time goes. The x-axis is not time order.
• Look for wide plateaus near the top: a function that is wide itself, not just because of what it calls.

samply is a cross-platform alternative that opens results in the Firefox profiler; macOS has Instruments. For memory, heaptrack and the dhat crate show who allocates.

The workflow

1. Reproduce the slowness with realistic input, in a release build.
2. Profile. Find the widest box.
3. Fix that one thing (usually an algorithm, a collection, or an allocation in a loop).
4. Benchmark before and after, and keep the benchmark so a later change can't quietly undo it.

A real hot spot

Suppose a flamegraph of a text tool looks like this (one line per stack level, with its share of samples):

main                                 100%
└─ count_vowels                       98%
   └─ core::iter::Iterator::nth       96%   <- almost all the time

and count_vowels is:

fn count_vowels(text: &str) -> usize {
    let mut count = 0;
    for i in 0..text.chars().count() {
        let c = text.chars().nth(i).unwrap(); // walks from the start every time
        if "aeiouAEIOU".contains(c) {
            count += 1;
        }
    }
    count
}

Strings are UTF-8, so finding the i-th character means walking from the start: nth(i) is O(i), and the loop makes the whole function O(n²). The profile points straight at it; no amount of compiler tuning would.

Your task

Fix count_vowels so it walks the characters once (O(n)), without nth. The tests include a 100,000-character string.

Challenge 2

A profile of a job scheduler shows 99% of the time in Vec::remove, called from finish_times. Removing the first element of a Vec shifts every other element down, so the loop is O(n²). Rewrite it to walk the jobs in order without removing anything: each job's finish time is the running total of the costs so far.

Challenge 3

A profile of a word counter shows most of its time in to_string allocations and hashing, because every word is converted to a String up to three times and looked up up to three times. Rewrite word_counts to return HashMap<&str, usize> that borrows the words from text (no allocation per word), and use the entry API so each word is hashed once.

Previous: Cow: borrow when you can, own when you must