Profiling with counters and gdb

A stopwatch says that a program takes a second. It does not say which part of the second belongs to which function, and a guess at the answer is wrong often enough to be expensive. Profiling is the step between the measurement and the fix: counting how often the code runs, and looking at the program while it is inside the loop.

This lesson counts calls and branches with atomic counters, then opens the same program in gdb and reads a value at the breakpoint. It ends with the coverage build that this toolchain can start and cannot finish, and with the static counter the compiler refuses to change.

A counter in the hot path

The simplest profile is a number per function: how often it ran and what it saw. The counter has to be reachable from every call and it cannot be a local, so it is a static, and a static that changes from several threads is an AtomicUsize.

The program parses three lines and counts both the calls and the words. The counters are relaxed, because nothing depends on their order: the program reads them after all the work is done.

use std::sync::atomic::{AtomicUsize, Ordering}; static CALLS: AtomicUsize = AtomicUsize::new(0); static WORDS: AtomicUsize = AtomicUsize::new(0); fn parse(line: &str) -> usize { CALLS.fetch_add(1, Ordering::Relaxed); let words = line.split_whitespace().count(); WORDS.fetch_add(words, Ordering::Relaxed); words } fn main() { let document = "the quick brown fox\njumps over the lazy dog\nand runs away"; let mut total = 0; for line in document.lines() { total += parse(line); } println!( "lines {} words {} counted {}", CALLS.load(Ordering::Relaxed), WORDS.load(Ordering::Relaxed), total ); }

rustc --edition 2024 counter.rs
./counter

lines 3 words 12 counted 12

The counted total matches the counters, which is the property to check first: a counter that disagrees with the work is measuring the wrong thing. The lesson on atomics explains the ordering argument, and for a counter that only reports at the end the relaxed order is the cheap and correct choice.

A counter costs an atomic increment per call, which is a few nanoseconds and a shared cache line. It is cheap enough to leave in a debug build and it is not free in a loop that runs a hundred million times, which is why the counters of a finished program usually sit behind a feature flag.

Counters per branch

A counter per branch answers a better question than a call count: which arm of the match is the hot one. The program below scans two short strings and sorts every byte into vowels, digits and the rest, which is the shape of a tokenizer that spends its time in one arm.

use std::sync::atomic::{AtomicUsize, Ordering}; static VOWELS: AtomicUsize = AtomicUsize::new(0); static DIGITS: AtomicUsize = AtomicUsize::new(0); static OTHER: AtomicUsize = AtomicUsize::new(0); fn scan(text: &str) { for byte in text.bytes() { match byte { b'a' | b'e' | b'i' | b'o' | b'u' => VOWELS.fetch_add(1, Ordering::Relaxed), b'0'..=b'9' => DIGITS.fetch_add(1, Ordering::Relaxed), _ => OTHER.fetch_add(1, Ordering::Relaxed), }; } } fn main() { scan("rust 2024 edition"); scan("aeiou 12345"); println!( "vowels {} digits {} other {}", VOWELS.load(Ordering::Relaxed), DIGITS.load(Ordering::Relaxed), OTHER.load(Ordering::Relaxed) ); }

rustc --edition 2024 hist.rs
./hist

vowels 10 digits 9 other 9

The match expression returns the result of each fetch_add, which is why the arms end with a semicolon after the brace: the values are discarded and the loop body is a statement. Ten vowels in two lines and nine bytes in each of the other buckets is a picture of the input, not of the machine, and a real profile multiplies these counts by the cost of each arm.

The lesson on bytes and flags builds the same classification without counters. What the counters add is the knowledge of which arm to optimize, and in a tokenizer the answer is usually the whitespace skip, which runs once per token but touches more bytes than any other arm.

gdb on the slow loop

Counters say how often something happened. When the question is what a value was at that moment, a debugger is quicker than a print statement, because the program does not have to be edited and rebuilt. The build needs -g, and the breakpoint goes on a line of the source or on a mangled function name, not on the plain name of a Rust function.

The program calls one function twice, with five and with a thousand. gdb stops at the first line of the function on each call, prints the argument and continues, which is the smallest complete session.

fn work(n: u64) -> u64 { let mut total = 0; for i in 0..n { total += i % 7; } total } fn main() { println!("{}", work(5)); println!("{}", work(1000)); }

rustc --edition 2024 -g slow.rs
gdb -q -batch -iex 'set auto-load python-scripts off' -ex 'set disable-randomization off' -ex 'set print address off' -ex 'break slow.rs:2' -ex run -ex 'print n' -ex continue -ex 'print n' -ex continue ./slow

Breakpoint 1: file slow.rs, line 2.

Breakpoint 1, slow::work (n=5) at slow.rs:2
2 let mut total = 0;
$1 = 5
10

Breakpoint 1, slow::work (n=1000) at slow.rs:2
2 let mut total = 0;
$2 = 1000
2997
[Inferior 1 (process 943) exited normally]

The two numbers at the breakpoints are the arguments of the two calls, and the program printed ten and 2997 between them. The process number in the last line changes on every run. The lesson on debugging with gdb steps line by line and reads the accumulator; here the breakpoint is the stopwatch, because a function that is entered a thousand times and takes a microsecond each is where the second went.

A conditional breakpoint counts without stopping: break slow.rs:4 if i == 500 stops on the five hundredth iteration and nowhere else. That is the cheap way to see the state in the middle of a long loop without printing a line per iteration.

The instrumented build

The compiler can add counters of its own. -C instrument-coverage builds the program with a counter per region, and every run appends its counts to a .profraw file next to the binary.

The program has a branch with two arms, which is exactly what a coverage report is about: it says whether each arm ran. The build, the run and the file are the whole step, and the file is the input of a tool that merges it into a report.

fn classify(n: u32) -> &'static str { if n % 2 == 0 { "even" } else { "odd" } } fn main() { for n in 1..=3 { println!("{} {}", n, classify(n)); } }

rustc --edition 2024 -C instrument-coverage cover.rs -o cover
./cover
ls *.profraw

1 odd
2 even
3 odd
default_2989007113815828473_0_1213.profraw

The name of the file carries the build and the process, so it changes on every run, and a program that runs many times leaves many of them. The merge is done by llvm-profdata and the report by llvm-cov, which come with the LLVM tools of a rustup installation. This toolchain has neither, so the file here is proof that the counters were emitted and not a coverage report.

The toolchain also has no perf and no valgrind, and rustc does not accept the C -pg flag that gprof would need. What is left is exactly what this lesson uses: counters for the counts, Instant for the durations, and gdb for the moment. That set answers most questions about a slow program, and it works on every machine that can build it.

The static that cannot change

A C++ programmer writes static int calls = 0; inside a function and increments it. The Rust translation of that line is a static item without mut, and it is a constant: the language has no shared mutable global that any function may write, because that would be a data race waiting for a second thread.

The program below is the direct translation and the compiler stops at the addition with E0594. The note points at the declaration that made the name immutable.

static CALLS: u32 = 0; fn main() { CALLS += 1; println!("{CALLS}"); }

rustc --edition 2024 static_err.rs

error[E0594]: cannot assign to immutable static item `CALLS`
--> static_err.rs:4:5
|
1 | static CALLS: u32 = 0;
| ----------------- this `static` cannot be written to
...
4 | CALLS += 1;
| ^^^^^^^^^^ cannot assign

error: aborting due to 1 previous error

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

The fix is the first program of this lesson: an atomic, or a Mutex, or a Cell in a thread-local. static mut exists and needs an unsafe block on every access, which is the compiler asking for the argument that the counter really is used from one thread. The lesson on unsafe shows what that block takes on. The next lesson looks at the cost the counters and the data structures pay for the memory they sit in.

Exercises

  1. Add a counter to a function that inserts into a HashMap and print how many inserts replaced an existing key.
  2. Break in gdb on the line of a loop with a condition and print the accumulator at the tenth iteration.
  3. Build a program with -C instrument-coverage, run it twice and explain why two .profraw files appear.

Questions

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

  1. Why is a profiling counter a static rather than a local variable?

    Answer

    The counter must be reachable from every call and outlive them

    Each call has its own locals, so the total has to live outside them.

  2. What does a counter per branch of a match tell you?

    Answer

    Which arm runs most often, and so which one is worth optimizing

    The counts show where the bytes and the time go in the input.

  3. Why does the gdb breakpoint name a source line instead of break work?

    Answer

    Rust function names are mangled, so the plain name is often not a symbol

    The symbol table holds the mangled name, and the file and line always resolve.

  4. What does rustc -C instrument-coverage produce when the program runs?

    Answer

    A .profraw file with the counters of every region

    The counts are written on exit, and llvm-profdata merges them into a report.

  5. Why is Ordering::Relaxed enough for these counters?

    Answer

    The counters are read only after the work that increments them has finished

    No thread depends on seeing another thread's increment during the run.

  6. What does this program print? use std::sync::atomic::{AtomicUsize, Ordering}; static HITS: AtomicUsize = AtomicUsize::new(0); fn bump(n: usize) { for _ in 0..n { HITS.fetch_add(1, Ordering::Relaxed); } } fn main() { bump(3); bump(4); println!("{}", HITS.load(Ordering::Relaxed)); }

    Answer

    7

    The two calls add three and four to the same counter.

  7. What does this program print? use std::sync::atomic::{AtomicUsize, Ordering}; fn main() { let calls = AtomicUsize::new(0); calls.fetch_add(2, Ordering::Relaxed); calls.fetch_add(3, Ordering::Relaxed); println!("{} {}", calls.load(Ordering::Relaxed), calls.swap(0, Ordering::Relaxed)); }

    Answer

    5 5

    The counter holds five, and swap returns the old value before it writes zero.

  8. What does this program print? fn main() { let text = "abc123"; let mut digits = 0; let mut letters = 0; for byte in text.bytes() { if byte.is_ascii_digit() { digits += 1; } else { letters += 1; } } println!("{} {}", letters, digits); }

    Answer

    3 3

    Three letters and three digits, and bytes gives one u8 per ASCII character.

  9. What is the first line of the compiler output for this program? static CALLS: u32 = 0; fn bump() { CALLS += 1; } fn main() { bump(); println!("{CALLS}"); }

    Answer

    error[E0594]: cannot assign to immutable static item CALLS

    A static without mut is a constant, and the assignment is refused with E0594.

  10. What is the first line of the compiler output for this program? use std::sync::atomic::AtomicUsize; fn main() { let hits = AtomicUsize::new(3); println!("{}", hits); }

    Answer

    error[E0277]: Atomic<usize> doesn't implement std::fmt::Display

    An atomic is not a number for formatting; load returns the value inside it.

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