Skip to content
Learn Rust
Theme

Performance: measure, then change

Performance work is mostly measuring. This page runs the measurements in the course’s image (Linux on ARM64, Rust 1.99.1) and keeps to two rules. A time is printed only to show a direction, and it is labelled as one run. The rest are counts (allocator calls, instructions), which came out the same in the runs here, and sizes in bytes, which belong to this path and target. Steps whose output changes say so.

RememberMeasure a release build. Count what you can count. Let a time tell you which of two things is smaller, never a number to quote.

Project layout
perf-lab/
├── src/
│   ├── bin/
│   │   ├── allocs.rs           a counting allocator
│   │   ├── fold.rs             loops the compiler can answer without running
│   │   ├── overflow.rs         what release changes besides speed
│   │   ├── unwind.rs           panic = abort
│   │   └── work.rs             debug against release
│   ├── lib.rs                  three functions the page compiles to assembly
│   └── main.rs
├── asm.sh                      prints one function from the assembly
├── Cargo.lock                  created by Cargo
└── Cargo.toml                  the profiles
RustCargo.toml
[package]
name = "perf-lab"
version = "0.1.0"
edition = "2024"
default-run = "app"
[[bin]]
name = "app"
path = "src/main.rs"
# Named profiles built on top of `release`: one setting changed each (and `tiny`, all of
# them together). `cargo build --profile small` builds into target/small/.
[profile.small]
inherits = "release"
opt-level = "z"
[profile.lto]
inherits = "release"
lto = true
[profile.one-unit]
inherits = "release"
codegen-units = 1
[profile.abort]
inherits = "release"
panic = "abort"
[profile.stripped]
inherits = "release"
strip = true
[profile.tiny]
inherits = "release"
opt-level = "z"
lto = true
codegen-units = 1
panic = "abort"
strip = true

cargo run builds the dev profile and cargo run --release builds the release profile (Cargo’s profile table). The same source gives the same answer, and the program asserts that its loop and its iterator chain agree:

Rustsrc/bin/work.rs
use std::time::Instant;
// How many steps the Collatz process takes to get from n to 1.
fn collatz_steps(mut n: u64) -> u64 {
let mut steps = 0;
while n != 1 {
n = if n % 2 == 0 { n / 2 } else { 3 * n + 1 };
steps += 1;
}
steps
}
fn main() {
let limit = 300_000;
println!("debug assertions on: {}", cfg!(debug_assertions));
let start = Instant::now();
let mut with_loop = 0;
for n in 1..=limit {
with_loop += collatz_steps(n);
}
let loop_time = start.elapsed();
let start = Instant::now();
let with_iter: u64 = (1..=limit).map(collatz_steps).sum();
let iter_time = start.elapsed();
// The two versions are the same computation, so the answers must match.
assert_eq!(with_loop, with_iter);
println!("total steps for 1..={limit}: {with_iter}");
println!("for loop: {loop_time:?}");
println!("iterator chain: {iter_time:?}");
}
$ cargo run --bin work # debug build; one run on this VM, 8 cores (colima), varies
debug assertions on: true
total steps for 1..=300000: 35669725
for loop:       133.072524ms
iterator chain: 135.173913ms
$ cargo run --release --bin work # one run on this VM, 8 cores (colima), varies
debug assertions on: false
total steps for 1..=300000: 35669725
for loop:       26.300602ms
iterator chain: 26.242352ms

This output changes from run to run. This is one real run.

In this run the debug build printed the larger time for both versions. The code explains it better than a ratio. Three functions compiled for release and for debug (sum_to is (0..n).sum() and sum_loop is a for loop):

assembly for ARM64
$ cargo rustc -q --release --lib -- --emit asm
$ sh asm.sh release sum_const
_RNvCs1sbkSINsBSH_8perf_lab9sum_const:
	mov	w0, #40748
	movk	w0, #7, lsl #16
	ret
$ sh asm.sh release sum_to
_RNvCs1sbkSINsBSH_8perf_lab6sum_to:
	cbz	x0, .LBB0_2
	sub	x8, x0, #1
	sub	x9, x0, #2
	mul	x10, x8, x9
	umulh	x9, x8, x9
	extr	x9, x9, x10, #1
	add	x0, x8, x9
	ret
$ sh asm.sh release sum_loop
_RNvCs1sbkSINsBSH_8perf_lab8sum_loop:
	cbz	x0, .LBB1_2
	sub	x8, x0, #1
	sub	x9, x0, #2
	mul	x10, x8, x9
	umulh	x9, x8, x9
	extr	x9, x9, x10, #1
	add	x0, x8, x9
	ret
$ cargo rustc --lib -- --emit asm   # the debug build
$ sh asm.sh debug sum_to
_RNvCs6D0RQGRaSru_8perf_lab6sum_to:
	sub	sp, sp, #32
	stp	x29, x30, [sp, #16]
	add	x29, sp, #16
	mov	x1, x0
	str	x1, [sp, #8]
	mov	x0, xzr
	bl	_RINvYINtNtNtCsaWcbhsS8OaW_4core3ops5range5RangeyENtNtNtNtBa_4iter6traits8iterator8Iterator3sumyECs6D0RQGRaSru_8perf_lab
	ldp	x29, x30, [sp, #16]
	add	sp, sp, #32
	ret
$ sh asm.sh debug sum_loop
_RNvCs6D0RQGRaSru_8perf_lab8sum_loop:
	sub	sp, sp, #80
	stp	x29, x30, [sp, #64]
	add	x29, sp, #64
	mov	x1, x0
	stur	x1, [x29, #-16]
	mov	x0, xzr
	str	xzr, [sp, #8]
	bl	_RNvXNtNtNtCsaWcbhsS8OaW_4core4iter6traits7collectINtNtNtB8_3ops5range5RangeyENtB2_12IntoIterator9into_iterCs6D0RQGRaSru_8perf_lab
	str	x0, [sp, #16]
	str	x1, [sp, #24]
	b	.LBB5_1
	add	x0, sp, #16
	bl	_RNvXs4_NtNtCsaWcbhsS8OaW_4core4iter5rangeINtNtNtB9_3ops5range5RangeyENtNtNtB7_6traits8iterator8Iterator4nextCs6D0RQGRaSru_8perf_lab
	str	x0, [sp, #32]
	str	x1, [sp, #40]
	ldr	x8, [sp, #32]
	tbnz	w8, #0, .LBB5_2
	b	.LBB5_3
	ldr	x8, [sp, #40]
	stur	x8, [x29, #-8]
	ldr	x9, [sp, #8]
	add	x8, x9, x8
	str	x8, [sp]
	subs	x8, x8, x9
	b.lo	.LBB5_5
	b	.LBB5_4
	ldr	x0, [sp, #8]
	ldp	x29, x30, [sp, #64]
	add	sp, sp, #80
	ret
	ldr	x8, [sp]
	str	x8, [sp, #8]
	b	.LBB5_1
	adrp	x0, .Lanon.fff5426ee47afe1ffe0adc2e8d0daeb7.3
	add	x0, x0, :lo12:.Lanon.fff5426ee47afe1ffe0adc2e8d0daeb7.3
	bl	_RNvNtNtCsaWcbhsS8OaW_4core9panicking11panic_const24panic_const_add_overflow
$ for each function: count the call instructions (bl) in sh asm.sh debug|release <function>
sum_const: calls in debug 1, in release 0
sum_to: calls in debug 1, in release 0
sum_loop: calls in debug 3, in release 0
$ diff the instructions of sum_to and sum_loop in the release build (label numbers aside)
sum_to and sum_loop: same instructions
  • In release, sum_const is a constant and sum_to has no loop at all: the compiler worked out a formula (mul, umulh).
  • In release, sum_to and sum_loop came out as the same instructions. That is one case, not a law about iterators.
  • In debug, sum_to makes one call (to Iterator::sum, not inlined) and sum_loop makes three, where release makes none. The debug sum_loop also loads and stores total in memory on each pass.

The second difference is behaviour. The Cargo docs say that when overflow-checks is enabled, “a panic will occur on overflow”. It was on in debug, off in release, and is a setting of its own:

terminal
$ cargo build --bin overflow && ./target/debug/overflow   # the thread id in the panic line is replaced by N
debug assertions on: true
wrapping_add: 0
checked_add:  None

thread 'main' (N) panicked at src/bin/overflow.rs:9:34:
attempt to add with overflow
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
$ cargo build -q --release --bin overflow && ./target/release/overflow
debug assertions on: false
wrapping_add: 0
checked_add:  None
x + 1:        0
$ cargo build --release --bin overflow --config profile.release.overflow-checks=true && ./target/release/overflow   # thread id replaced by N
debug assertions on: false
wrapping_add: 0
checked_add:  None

thread 'main' (N) panicked at src/bin/overflow.rs:9:34:
attempt to add with overflow
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

So “release is the same program, faster” is not quite true: an overflow that panics in debug wraps in release unless you turn the check on. Integer overflow is covered earlier in the course.

Each profile in Cargo.toml changes one setting from release (tiny changes all of them). The listing is the size of the same small program (a word counter in src/main.rs) under each, on this target. Another program or target gives other sizes:

binary sizes
$ cargo build --bin app
$ for p in release small lto one-unit abort stripped tiny; do cargo build --profile $p --bin app; done
$ stat -c '%s bytes  %n' target/*/app   # this path, Linux ARM64, rustc 1.99.1; the debug size changed with the build directory, varies
   542504 bytes  target/abort/app
  5199912 bytes  target/debug/app
   444224 bytes  target/lto/app
   542824 bytes  target/one-unit/app
   543912 bytes  target/release/app
   547984 bytes  target/small/app
   398168 bytes  target/stripped/app
   332528 bytes  target/tiny/app
$ cargo run -q --profile tiny
   the: 4
     a: 1
   and: 1
20 distinct words

This output changes from run to run. This is one real run.

What the listing shows for this program:

  • The debug build is the largest by far. Debug information (the debug setting) makes up most of the difference: release with debug = true came out about as large as the debug build (second task below). The debug size also changed with the build directory.
  • strip and lto each made the release binary smaller, and tiny (all five settings) is the smallest.
  • opt-level = "z" alone did not make it smaller. The Cargo docs warn of surprising results, such as ‘the “s” and “z” levels not being necessarily smaller’ (profiles). min-sized-rust notes that “The prebuilt libstd is optimized for speed, not size”, a likely reason here: a small program’s opt-level reaches only its own code.
  • The Performance Book describes lto and codegen-units = 1 as run-time options too. This page times neither.

panic = "abort" changes behaviour, not only size. With the default, catch_unwind caught the panic and the guard’s Drop ran. With abort the process was killed by a signal and neither line printed (catch_unwind says it catches only unwinding panics):

Rustsrc/bin/unwind.rs
use std::panic;
struct Noisy;
impl Drop for Noisy {
fn drop(&mut self) {
println!("Noisy dropped");
}
}
fn main() {
panic::set_hook(Box::new(|_| {})); // keep the output about the setting, not the message
let result = panic::catch_unwind(|| {
let _guard = Noisy;
panic!("boom");
});
println!("caught: {}", result.is_err());
}
$ cargo run --release --bin unwind
Noisy dropped
caught: true
$ cargo run --profile abort --bin unwind; echo "exit code: $?" # the process id is replaced by N; "core dumped" depends on the system, varies
bash: line N: N Aborted                 (core dumped) cargo run --profile abort --bin unwind
exit code: 134

This output changes from run to run. This is one real run.

Time is noisy. The number of calls to the allocator did not change between runs. A global allocator that wraps the system one and counts its calls takes a dozen lines (the formatting lesson uses the same pattern). unsafe impl is boilerplate here (GlobalAlloc). It counts calls, not bytes, and a realloc is a call:

Rustsrc/bin/allocs.rs
use std::alloc::{GlobalAlloc, Layout, System};
use std::fmt::Write as _;
use std::hint::black_box;
use std::rc::Rc;
use std::sync::atomic::{AtomicUsize, Ordering::Relaxed};
// Counts calls to the system allocator. (`unsafe impl` is boilerplate here: the
// Unsafe lesson explains why it is needed.)
struct Counting;
static CALLS: AtomicUsize = AtomicUsize::new(0);
unsafe impl GlobalAlloc for Counting {
unsafe fn alloc(&self, layout: Layout) -> *mut u8 {
CALLS.fetch_add(1, Relaxed);
unsafe { System.alloc(layout) }
}
unsafe fn dealloc(&self, ptr: *mut u8, layout: Layout) {
unsafe { System.dealloc(ptr, layout) }
}
unsafe fn realloc(&self, ptr: *mut u8, layout: Layout, new_size: usize) -> *mut u8 {
CALLS.fetch_add(1, Relaxed); // growing a buffer in place or by copying: one call
unsafe { System.realloc(ptr, layout, new_size) }
}
}
#[global_allocator]
static COUNTING: Counting = Counting;
// Runs `work` and returns how many times it asked the allocator for memory.
fn count<T>(work: impl FnOnce() -> T) -> usize {
let before = CALLS.load(Relaxed);
black_box(work());
CALLS.load(Relaxed) - before
}
fn main() {
let line = String::from("alpha beta gamma delta epsilon zeta eta theta");
// Owned pieces versus borrowed pieces of the same line.
println!("split into Vec<String>: {}", count(|| line.split(' ').map(String::from).collect::<Vec<_>>()));
println!("split into Vec<&str>: {}", count(|| line.split(' ').collect::<Vec<_>>()));
// Cloning: a String copies its text; an Rc only bumps a counter.
let shared = Rc::new(line.clone());
println!("String::clone: {}", count(|| line.clone()));
println!("Rc::clone: {}", count(|| Rc::clone(&shared)));
// Growing a Vec one push at a time, or asking for the room first.
println!("1000 pushes, no hint: {}", count(|| {
let mut v = Vec::new();
for i in 0..1000u32 {
v.push(i);
}
v
}));
println!("1000 pushes, capacity: {}", count(|| {
let mut v = Vec::with_capacity(1000);
for i in 0..1000u32 {
v.push(i);
}
v
}));
// Building 100 lines of text: a new String for each, or one buffer written into.
println!("format! x100: {}", count(|| (0..100).map(|i| format!("item {i}")).collect::<Vec<_>>()));
println!("write! into one String: {}", count(|| {
let mut out = String::new();
for i in 0..100 {
writeln!(out, "item {i}").unwrap();
}
out
}));
}
$ cargo run --bin allocs
split into Vec<String>: 10
split into Vec<&str>:   2
String::clone:          1
Rc::clone:              0
1000 pushes, no hint:   9
1000 pushes, capacity:  1
format! x100:           101
write! into one String: 8
$ cargo run --release --bin allocs
split into Vec<String>: 10
split into Vec<&str>:   2
String::clone:          1
Rc::clone:              0
1000 pushes, no hint:   9
1000 pushes, capacity:  1
format! x100:           101
write! into one String: 8

The counts were the same in debug and release. They show:

  • Splitting into Vec<&str> made fewer allocations than into Vec<String>: the &str pieces borrow the line (Strings).
  • String::clone allocated once and Rc::clone not at all (Smart pointers). A clone is not always a copy of the data.
  • A Vec grown by push asked the allocator repeatedly; with_capacity asked once (Capacity and growth). Whether that matters is a question only a benchmark answers.
  • format! per item allocated a String per item; write! into one String only grew it.

A loop whose result is unused, or whose answer has a formula, may not run at all. std::hint::black_box hides a value from the optimiser, and its docs say it works on a “best-effort” basis. This is what that means in practice (release build, one run on this VM, 8 cores (colima), varies):

Rustsrc/bin/fold.rs
use std::hint::black_box;
use std::time::Instant;
// A loop whose total has a short formula: the compiler can skip the looping.
fn sum_squares(n: u64) -> u64 {
(0..n).map(|i| i.wrapping_mul(i)).fold(0, u64::wrapping_add)
}
// A loop that scrambles the bits each time round: no formula, so it has to run.
fn mix(n: u64) -> u64 {
let mut x = 88172645463325252u64;
for _ in 0..n {
x ^= x << 13;
x ^= x >> 7;
x ^= x << 17;
}
x
}
fn time(label: &str, work: impl FnOnce() -> u64) {
let start = Instant::now();
let result = work();
println!("{label:<36} result {result:>20}, took {:?}", start.elapsed());
}
fn main() {
time("sum_squares(100_000_000)", || sum_squares(100_000_000));
time("sum_squares(black_box(100_000_000))", || sum_squares(black_box(100_000_000)));
time("mix(100)", || mix(100));
time("mix(black_box(100))", || mix(black_box(100)));
time("mix(100_000_000)", || mix(100_000_000));
time("mix(black_box(100_000_000))", || mix(black_box(100_000_000)));
}
$ cargo run --release --bin fold # one run on this VM, 8 cores (colima), varies
sum_squares(100_000_000)             result   662921401752298880, took 42ns
sum_squares(black_box(100_000_000))  result   662921401752298880, took 0ns
mix(100)                             result 10653220568048883440, took 0ns
mix(black_box(100))                  result 10653220568048883440, took 167ns
mix(100_000_000)                     result 13637911440367556603, took 139.737943ms
mix(black_box(100_000_000))          result 13637911440367556603, took 140.87787ms
$ cargo rustc --release --bin fold -- --emit asm; then count the umulh instructions in the .s file
1

This output changes from run to run. This is one real run.

sum_squares of a hundred million printed a time in nanoseconds, with or without black_box on the input: the compiler used a formula for the total, so the loop never ran. The assembly step backs that up: the release build contains a umulh instruction, the multiply-high the formula used in the asm session. black_box hid the number, and the formula still worked for any number. mix has no formula, so with a large count it ran for milliseconds either way. With a small count, mix(100) printed a smaller time without black_box than with it in this run. Three things help a benchmark: the input passed through black_box, the result passed through it too, and work the compiler cannot shortcut. Criterion passes the result through black_box for you; the input is yours to hide, as benches/mix.rs does. It also repeats the call and reports a range. The Performance Book lists it, with Divan, as a more sophisticated alternative to the built-in #[bench] tests, which need nightly Rust. It is a separate crate, so its first run compiles it (needs network):

Rustbenches/mix.rs
use criterion::{Criterion, criterion_group, criterion_main};
use mix_bench::mix;
use std::hint::black_box;
fn bench_mix(c: &mut Criterion) {
// The input and the result both go through black_box, so the compiler cannot
// precompute the answer or drop the call.
c.bench_function("mix 1000 rounds", |b| b.iter(|| black_box(mix(black_box(88172645463325252), 1000))));
}
criterion_group!(benches, bench_mix);
criterion_main!(benches);
$ cargo bench --bench mix -- --warm-up-time 1 --measurement-time 2 # needs network the first time; one run on this VM, varies
mix 1000 rounds         time:   [1.3309 µs 1.3371 µs 1.3432 µs]

This output changes from run to run. This is one real run.

A profiler tells you where the time went, which a benchmark does not. The usual Linux tools, perf and cargo flamegraph (which relies on perf), and samply (which uses perf events on Linux), are named here but not run: perf installs with apt inside the session (needs network), but this VM’s setting refuses it.

terminal
$ apt-get install linux-perf   # needs network
perf version 6.12.113
$ cat /proc/sys/kernel/perf_event_paranoid
4
$ perf stat -e task-clock true 2>&1 | head -2
Error:
Access to performance monitoring and observability operations is limited.

Where the image has the tool, the cell is a run. The other cells name a tool and are marked not run.

Language Optimised or not Count allocations Benchmark tool
Rust --release, [profile.*] counting allocator (above) Criterion (run above)
Go go tool compile has -N (no optimisation) and -l (no inlining), help text below; no build run testing.AllocsPerRun (run below) go test -bench, in the testing package, not run
Python not run sys.getallocatedblocks (run below) timeit, not run
TypeScript not run not run node --cpu-prof for profiles (Node CLI), not run
Java, Kotlin not run not run JMH, not run
C# not run not run BenchmarkDotNet, not run
C, C++ -O0 and -O2 (C run below; g++ not run) not run not run
the same questions, where they run
$ go run allocs.go   # Go, testing.AllocsPerRun
strings.Split:            1
1000 appends, no hint:    9
1000 appends, capacity:   1
$ go tool compile -help   # the two flags that switch optimisation and inlining off
  -N	disable optimizations
  -l	disable inlining
$ python3 allocs.py   # Python 3.13, sys.getallocatedblocks; the count can vary, varies
blocks gained by list(range(1000)): 746
blocks gained by list(range(200)):  2
$ gcc -O0 -S sum.c   # C, no optimisation
sum_to:
	sub	sp, sp, #32
	str	x0, [sp, 8]
	str	xzr, [sp, 24]
	str	xzr, [sp, 16]
	b	.L2
	ldr	x1, [sp, 24]
	ldr	x0, [sp, 16]
	add	x0, x1, x0
	str	x0, [sp, 24]
	ldr	x0, [sp, 16]
	add	x0, x0, 1
	str	x0, [sp, 16]
	ldr	x1, [sp, 16]
	ldr	x0, [sp, 8]
	cmp	x1, x0
	bcc	.L3
	ldr	x0, [sp, 24]
	add	sp, sp, 32
	ret
$ gcc -O2 -S sum.c   # C, optimised
sum_to:
	mov	x2, x0
	cbz	x0, .L4
	mov	x1, 0
	mov	x0, 0
	add	x0, x0, x1
	add	x1, x1, 1
	cmp	x2, x1
	bne	.L3
	ret
	mov	x0, 0
	ret

This output changes from run to run. This is one real run.

  • Go printed 1 for strings.Split where Rust’s Vec<&str> split took 2; the two jobs are different code, so that is not a comparison of the languages. The appends matched: 9 for a thousand without a size hint and 1 with make(..., 0, 1000), as Rust’s 9 and 1. Both grow a slice by reallocating.
  • Python gained 746 blocks for a list of a thousand integers and 2 for a list of two hundred. The Python 3.13 docs say CPython keeps one shared object for each integer from -5 to 256, so larger ones are objects of their own. The sys docs warn that this count can vary between calls.
  • C at -O0 kept total in memory on every pass, as the debug Rust sum_loop did in the asm session. At -O2 it kept it in a register. The -O2 listing still has the loop: GCC 14 did not turn this one into a formula, where rustc did. That is one loop and one compiler version, not a verdict on either.
Belief What the run showed
“Release is the same program, only faster.” An overflow panicked in debug and wrapped in release, until overflow-checks was set.
“Cloning copies the data.” String::clone allocated once, Rc::clone not at all.
“A benchmark that takes nanoseconds shows a fast program.” The formula loop took nanoseconds because it did not run.
“opt-level = "z" gives a smaller binary.” Alone, it was bigger than plain release here (this program, this target).
“Iterator chains cost more than loops.” In this release build sum_to and sum_loop were the same instructions. In debug, sum_to made 1 call and sum_loop 3.
“More threads make any loop faster.” Rayon printed the parallel version slower for 10 items.

Each task is a step in the session below, run in the image.

  1. Give the debug profile opt-level = 3 from the command line: cargo run --bin work --config profile.dev.opt-level=3. debug assertions on still prints true, and the time printed is smaller than the plain debug run. Optimisation and checks are separate settings.
  2. Build release with --config profile.release.debug=true and list the size. The binary is about as large as the debug one: the debug information is most of the difference.
  3. Change with_capacity(1000) to with_capacity(10) in allocs.rs. The pushes now take more than one allocation but fewer than with no hint, because the buffer still has to grow.
terminal
$ cargo run --bin work --config profile.dev.opt-level=3   # one run on this VM, varies
debug assertions on: true
total steps for 1..=300000: 35669725
for loop:       38.423315ms
iterator chain: 37.779227ms
$ cargo build --release --config profile.release.debug=true; stat -c '%s bytes  %n' target/release/app   # varies with the build directory
5009408 bytes  target/release/app
$ sed -i 's/with_capacity(1000)/with_capacity(10)/' src/bin/allocs.rs; cargo run --bin allocs | grep pushes
1000 pushes, no hint:   9
1000 pushes, capacity:  8

This output changes from run to run. This is one real run.