Profiling Rust Programs From Flamegraph to a Fix Guide

Making a Rust program faster is a measurement problem before it is a coding problem. The compiler is already good, so the usual wins are not clever tricks but removing one accidental quadratic loop or a few million allocations that nobody meant to write, and you cannot find those by reading code. This guide takes a small, realistic program, a log analyser that computes the 95th-percentile latency per route, and speeds it up in three measured steps: 195 ms to 108 ms to 25 ms in a release build, with the allocation count falling from 2,403,309 to 3,310. The route there is the order that works on real projects: build in release mode, take a sampling profile, read the table of where time goes, fix the biggest item, then count allocations, then measure again. Everything ran on rustc 1.99.0 on an Apple M1 Max (macOS), with the profile taken by the system sample tool and rendered by inferno. The commands for Linux's perf are given but were not run here.

The program under test

The input is 400,000 access-log lines, 21 MB in all, spread over 300 routes. A line looks like 2026-11-07T12:00:05 GET /api/v1/resource17/items 214, and the output is, for each route, the 95th percentile of the last field. The generator is a fixed linear congruential sequence, so every run sees the same input. Three versions of the analysis follow the same pattern of improvement a real codebase goes through. The first is what you write on the first day:

/// Version 1: allocate a String per field, find the route with a linear scan.
fn slow(log: &str) -> Vec<(String, u64)> {
    let mut stats: Vec<(String, Vec<u64>)> = Vec::new();
    for line in log.lines() {
        let fields: Vec<String> = line.split(' ').map(String::from).collect();
        let route = fields[2].clone();
        let latency: u64 = fields[3].parse().unwrap();
        match stats.iter_mut().find(|(r, _)| *r == route) {
            Some((_, v)) => v.push(latency),
            None => stats.push((route, vec![latency])),
        }
    }
    summarize(stats)
}

fn summarize(mut stats: Vec<(String, Vec<u64>)>) -> Vec<(String, u64)> {
    stats.sort_by(|a, b| a.0.cmp(&b.0));
    stats
        .into_iter()
        .map(|(r, mut v)| {
            v.sort_unstable();
            let p95 = v[(v.len() * 95 / 100).min(v.len() - 1)];
            (r, p95)
        })
        .collect()
}

Nothing in it is wrong. It is correct, readable, and what most people would write. It also hides two costs: every line allocates a vector plus four strings plus a clone of the route, and the lookup walks a list of up to 300 routes comparing strings. Neither shows up as a warning, and neither is obvious from the shape of the code.

Rule zero: measure a release build

A debug build is not a slower version of the release build; it is a different program. Overflow checks, no inlining, no loop optimisation and unoptimised iterator chains make it many times slower (between 4.6 and 12.9 times for the three versions below), and the slowdown is not uniform. A profile of a debug build points at the wrong functions. So before anything else, build with --release. I ran the same three analysers in both modes and kept the best of five runs of each:

debug build (cargo run)
slow        1022.9 ms
hashed       490.6 ms
borrowed     324.4 ms

release build (cargo run --release)
slow         195.4 ms
hashed       107.8 ms
borrowed      25.2 ms

Look at the ratios, not just the sizes. Version 1 is 5.2 times faster in release. Version 3 is 12.9 times faster, because the optimiser can inline and vectorise the borrowed version in ways it cannot for the allocating one. The debug numbers would have told you that the third version is three times better than the first, and the release numbers say it is nearly eight. If you tuned against the debug build you would have underestimated the gain and, worse, you might have spent effort on code that the optimiser already handles.

One setting is needed to make a release build profilable. Release strips debug info by default, so a profiler sees addresses instead of line numbers. Keep optimisation on and add symbols:

[profile.release]
debug = true

Line tables do not change the generated machine code, so the profile still reflects the fast build. For a binary you ship, keep this out of the default release profile and use a custom profile that inherits from it, so the change is explicit.

Take a sampling profile

A sampling profiler interrupts the program many times a second, records the call stack each time, and counts. A function that holds the CPU for a quarter of the run appears in about a quarter of the samples. There is no instrumentation, so the program runs at close to full speed, and that is why sampling is the right first tool.

The measurement program needs to run long enough to sample, so a mode argument repeats version 1 twenty-five times. On macOS the system sample tool attaches to a running process by pid:

cargo build --release
./target/release/prof slow &
sample $! 3 -file sample.txt

On Linux the equivalent is perf record -g ./target/release/prof slow followed by perf report, and the cargo flamegraph wrapper runs both steps. I did not run perf on this machine, so treat that line as the standard recipe and not as something verified here. The output of sample is a long call tree followed by a section called "Sort by top of stack", which is the part to read first: it lists each function by how often it was the one executing, and that is the self-time. These are the leading rows of that table, with the share of the roughly 2,239 samples they hold:

function                         samples   share
_platform_memcmp                     563   25.1%
prof::slow                            460   20.5%
_xzm_free                            187    8.4%
DYLD-STUB$$memcmp                    161    7.2%
_xzm_xzone_malloc_tiny               151    6.7%
core::slice::memchr                  111    5.0%

The malloc and free rows further down add up too: the three allocation entries (151, 68 and 30 samples) and the three free entries (187, 48 and 26) total 510 samples, or 22.8% of the table. What matters is the shape. A quarter of all time is memcmp (the byte comparison inside string equality), another fifth is the function body itself, and the allocator (malloc and free together) takes the 22.8% computed above. That is the signature of the two costs hidden in version 1: string comparison from the linear scan, and allocation from the per-line strings. The profile did not tell us something we could not have guessed once told where to look, but it ranked the guesses, and it said that comparison and allocation each matter and that parsing numbers is not near the top.

Turn the profile into a flamegraph

The table is the quickest read; the flamegraph shows the call structure that produced it. The inferno crate (cargo install inferno) ships converters for the output of the common profilers, including one for sample:

inferno-collapse-sample < sample.txt > prof.folded
inferno-flamegraph prof.folded > prof.svg

The first command folds each sampled stack into one line of semicolon-separated frames followed by a count. That folded format is the common currency of flamegraph tools, and it is plain text you can search with grep. The second draws the SVG. In the picture, the horizontal axis is the share of samples, not time order, and the vertical axis is call depth: a wide box near the top is a function where the CPU actually was, and a wide box low down is just a caller whose callees were expensive. Read the top edge for self-time, then walk down to see who calls it. Here the widest top edges are the string comparison and the allocator, called from slow, which matches the table. Do not hunt for pretty shapes; look for one wide plateau and ask why that code runs so often.

Fix one: remove the scan

The biggest item is the comparison, and the cause is the lookup: with 300 routes the loop compares on average 150 strings per line, and 400,000 lines make about 60 million string comparisons. The fix is a data structure change, not micro-optimisation. A hash map finds the route in one lookup. This is version 2, and only the lookup changed:

use std::collections::HashMap;

/// Version 2: a hash map replaces the scan.
fn hashed(log: &str) -> Vec<(String, u64)> {
    let mut stats: HashMap<String, Vec<u64>> = HashMap::new();
    for line in log.lines() {
        let fields: Vec<String> = line.split(' ').map(String::from).collect();
        let latency: u64 = fields[3].parse().unwrap();
        stats.entry(fields[2].clone()).or_default().push(latency);
    }
    summarize(stats.into_iter().collect())
}

That took release time from 195.4 ms to 107.8 ms, an 1.8 times speedup from one change that deleted the biggest row of the profile. Notice what it did not do: it did not touch the per-line strings. The profile said that the allocator was the second problem, and a measurement is the only thing that tells you whether to go there next, so measure the allocations directly.

Count the allocations

A sampling profile shows allocation as time in malloc, but it does not say how many allocations there were or which line made them. The dhat crate swaps in a counting global allocator. Enabled behind a cargo feature so that it costs nothing normally, it reports totals that can be read before and after any call:

#[cfg(feature = "dhat")]
#[global_allocator]
static ALLOC: dhat::Alloc = dhat::Alloc;

#[cfg(feature = "dhat")]
fn count_allocations(log: &str) {
    let _profiler = dhat::Profiler::builder().testing().build();
    for (name, f) in [("slow", slow as fn(&str) -> Vec<(String, u64)>), ("hashed", hashed), ("borrowed", borrowed)] {
        let before = dhat::HeapStats::get();
        f(log);
        let after = dhat::HeapStats::get();
        println!("{name:<9} {:>9} allocations", after.total_blocks - before.total_blocks);
    }
}

The testing() mode makes the profiler usable for assertions without writing a report file. I ran it with cargo run --release --features dhat -- heap:

slow        2403309 allocations
hashed      2403010 allocations
borrowed      3310 allocations

Two things stand out. Version 1 makes 2,403,309 allocations to process 400,000 lines, which is about six per line: the vector of fields, four field strings, and the cloned route. The hash map version makes almost exactly as many, 2,403,010, because it kept the same per-line strings; only the lookup changed. That is the number that explains why version 2 is only 1.8 times faster. And the last row, 3,310 allocations, is what the program needs when nothing is allocated per line: the hash map growing, the 300 vectors of latencies growing, and a few more.

Fix two: borrow instead of own

Every field string in version 2 is a copy of bytes that already sit in the input. Rust can hold a &str that points into the original text for as long as the text lives, which here is the whole run. So the key of the map becomes a &str, the line is split lazily without collecting, and only the 300 distinct route names are copied, once, at the end:

/// Version 3: no per-line allocation, keys borrow from the input.
fn borrowed(log: &str) -> Vec<(String, u64)> {
    let mut stats: HashMap<&str, Vec<u64>> = HashMap::new();
    for line in log.lines() {
        let mut f = line.split(' ');
        let route = f.nth(2).unwrap();
        let latency: u64 = f.next().unwrap().parse().unwrap();
        stats.entry(route).or_default().push(latency);
    }
    summarize(stats.into_iter().map(|(r, v)| (r.to_string(), v)).collect())
}

f.nth(2) skips the first two fields and returns the third without allocating, and the next call returns the fourth, which is parsed in place. The borrow checker is doing real work here: the map holds references into log, so the compiler guarantees log outlives the map. In this version the lifetimes need no annotation because the function returns owned Strings, the copies made in the last line.

The result is the 25.2 ms figure: 7.8 times faster than version 1, and 4.3 times faster than version 2. A harness checks that the speedup did not change the answer, which is the step people skip when they are pleased with a number:

use std::time::Instant;

fn time<F: Fn(&str) -> Vec<(String, u64)>>(name: &str, f: F, log: &str) -> Vec<(String, u64)> {
    let mut best = f64::MAX;
    let mut result = Vec::new();
    for _ in 0..5 {
        let start = Instant::now();
        result = f(log);
        best = best.min(start.elapsed().as_secs_f64());
    }
    println!("{name:<9} {:>8.1} ms  ({} routes, first: {:?})", best * 1000.0, result.len(), result[0]);
    result
}

fn run_all(log: &str) {
    let a = time("slow", slow, log);
    let b = time("hashed", hashed, log);
    let c = time("borrowed", borrowed, log);
    assert_eq!(a, b);
    assert_eq!(b, c);
    println!("all three agree");
}

slow         195.4 ms  (300 routes, first: ("/api/v1/resource0/items", 389))
hashed       107.8 ms  (300 routes, first: ("/api/v1/resource0/items", 389))
borrowed      25.2 ms  (300 routes, first: ("/api/v1/resource0/items", 389))
all three agree

The two assert_eq! lines compare complete outputs, 300 routes each, not a sample. A speedup that quietly changes results is a bug, and the cheapest guard is to keep the slow version around as the reference while you optimise. The harness also takes the best of five runs instead of the mean: the minimum is the closest estimate of the program's own cost, because noise from the scheduler, other processes and thermal limits only ever makes a run slower, never faster.

What the three steps add up to

Putting the measurements side by side shows how little of the gain came from clever code:

The first change removed an algorithmic cost, the second removed a constant-factor cost, and neither one is an operation you would find by reading the code for "slow lines". The order was set by the profile each time: the biggest row first, then re-measure. Had we started with version 3's allocation fix, the scan would have kept most of the time and the result would have looked disappointing, which is the usual way people conclude that optimisation does not work.

It is worth saying what version 3 still costs, because 25.2 ms is not zero. The 400,000 lines are still read once, every latency is still parsed, and each route keeps a vector of its measurements that is sorted at the end to find the percentile. Profiling version 3 again would show where the next dollar goes, probably in the sorts and the number parsing, and the same rule applies there: take the profile, believe the top row, and ask whether a 10 ms program is worth the extra code. For a nightly report the answer is no. For a service that does this per request, it might be yes.

Pitfalls that make a measurement lie

• Dead code gets deleted. If a benchmark's result is never used, the optimiser may remove the work. The harness above prints and compares the result for that reason. In a micro-benchmark, wrap inputs and outputs in std::hint::black_box.
• The first run is not the steady state. It pays for page faults, cold caches and lazy initialisation. Run a warm-up and take the best of several, as the harness does, or use a statistical harness such as criterion for anything you will compare over time.
• The input decides the answer. A scan over 300 routes is slow; over 3 routes it is faster than a hash. Profile with data shaped like production, not the easiest data you can generate. I used 300 routes because that is a plausible API, and I say so, because a different number would change the ranking of the first fix.
• Do not trust a profile you cannot name. If the top rows are runtime internals and not your functions, symbols are missing. Re-check debug = true and that the binary you ran is the one you built.
• One machine, one number. The figures here are from one laptop. They are good evidence that version 3 is much faster than version 1; they are not a promise of 7.8 times anywhere else, and you should rerun on the hardware that matters.

The order to look at things

This guide followed an order that is worth keeping as a habit. First, decide what you are measuring and write the check that the answer stays correct. Second, use a release build. Third, take a sampling profile and read the self-time table before the pretty picture. Fourth, attack the largest row with the cheapest correct change, usually a data structure or an algorithm. Fifth, count allocations if the allocator shows up, because allocation is the most common hidden constant factor in Rust programs that clone, collect and format freely. Sixth, measure again, and only then decide whether the next row is worth the complexity. Stop when the program is fast enough for its job, not when the profile is flat.

Where this does not apply

• A flat profile. If the time is spread across dozens of small functions with no wide box, there is no single fix. Gains then come from architecture (less work, batching, caching), not from tuning a function.
• I/O and waiting. A sampling profiler of CPU samples shows nothing for a program that spends its time blocked on a disk, a network or a lock. Use wall-clock tracing for those, such as tracing spans with timestamps.
• Borrowing is not free of cost. Version 3 ties the map to the input's lifetime. That is fine for a batch job that reads a file and exits, and awkward for a long-lived service that needs the results to outlive the buffer. There the extra allocations of version 2 may be the right price.
• Do not optimise what you cannot show is slow. Version 1 is perfectly good for 4,000 lines. A refactor that makes code harder to read needs a measured reason, and this guide's reason is the table above.
• Linux specifics were not run. The profile here is from macOS. The method is the same on Linux with perf, but the symbol names and the allocator rows will differ, so expect to read a different table.

The core lesson fits in one measured sentence: a 195 ms program became a 25 ms program by deleting a linear scan and 2.4 million allocations, and the profile and the allocation counter named both before anything was changed.