165. Profiling the Rust VM

Where does the second and a half go?

In the committed benchmark run, drip-rs ran fib.drip in 1460 ms. That number came from a stopwatch around the whole process. It says nothing about what the VM was doing inside. Chapter 24 warned against guessing, and guesses about hot code are wrong surprisingly often. So before the next chapter changes anything, we measure where the work goes.

Two ways to watch a program

A sampling profiler such as Linux perf interrupts the program many times a second and writes down the call stack. Functions that show up in more samples took more time. It sees real time, cache misses and all, but its numbers are estimates.

The book’s VM has no perf, but it has Valgrind. Its tool callgrind runs the program on a simulated CPU and counts every machine instruction it executes, with the function and source line each belongs to, and who called whom, how often^[1]. Nothing is estimated. The event it counts is called Ir, instructions read.

A profile of fib

I built drip-rs with cargo build --release (rustc 1.97, into a scratch directory) and ran it under valgrind 3.22 on the book’s shared VM:

valgrind --tool=callgrind \
  --callgrind-out-file=cg.out \
  target/release/drip-rs fib.drip
callgrind_annotate cg.out

It took 89 seconds, and fib’s own clock printed 88.6. That’s about 60 times slower than a normal run. The top of the report, with the names trimmed from forms like ???:<drip::vm::Vm>::run [path]:

20,186,274,402 (100.0%)  PROGRAM TOTALS
15,676,869,738 (77.66%)  Vm::run
 2,418,717,018 (11.98%)  Vm::call
 1,194,428,240 ( 5.92%)  Table::get
   716,657,004 ( 3.55%)  Vm::call_value

Twenty billion instructions. The slowdown doesn’t change the count: these are the instructions the program runs at full speed too. And the count barely moves between runs. I profiled zoo.drip twice and got 7,528,846,449 and 7,528,846,360. On a machine where wall times wander by a quarter, that steadiness is worth a lot.

Self and inclusive

That list is sorted by self cost: instructions in the function’s own code. --inclusive=yes adds in everything each function called^[1]:

20,185,841,592 (100.0%)  Vm::run
 3,135,374,121 (15.53%)  Vm::call_value
 2,418,717,118 (11.98%)  Vm::call
 1,194,428,240 ( 5.92%)  Table::get
   179,164,224 ( 0.89%)  Vm::close_upvalues

call_value does 3.55% itself, and 15.53% counting call. Now check the profile against something you can count. --tree=calling says run called call_value 29,860,705 times. fib(35) makes 29,860,703 calls (twice fib(36), minus one), and the script calls clock() twice. It matches exactly.

More arithmetic. A call to fib runs 7 bytecodes if n < 2 and 17 if not. That’s 358,328,431 bytecodes, about 56 machine instructions each. Table::get costs 40 instructions per call: every recursive call looks up the global fib by name. And close_upvalues runs on every return, though fib captures nothing.

Where are push and pop?

run does 77.66% itself. Where are read_byte, push, pop and peek? With lto and optimization, rustc inlined them: their code was copied into run, so there’s no function left to charge. To see inside, I rebuilt with line tables, CARGO_PROFILE_RELEASE_DEBUG=line-tables-only. The instruction count stayed within 0.00001%: 20,186,276,675. Now callgrind_annotate splits run by the file each instruction came from (std paths trimmed):

6,464,842,447 (32.03%)  vm.rs
2,911,418,677 (14.42%)  vec/mod.rs
2,523,229,490 (12.50%)  slice/index.rs
1,060,055,003 ( 5.25%)  raw_vec/mod.rs

vec/mod.rs is Vec::push, pop and len; slice/index.rs is indexing, bounds check included; raw_vec is the capacity check in push. Per line, the top two are fetching the next byte:

1,328,801,331 ( 6.58%)
    let byte = self.chunk.code[self.ip];
1,224,288,866 ( 6.06%)
    self.ip += 1;

Flame graphs

A long list is hard to read as a shape. A flame graph draws one: each function on a stack is a box, stacked on its caller, and as wide as its share of the samples^[2]. cargo flamegraph would make one from perf. Neither is installed here, so the diagram below is built from callgrind’s inclusive numbers by hand. Each box is as wide as its instructions, not its time.

The input is folded stacks: one line per distinct stack, with a count, such as main;run;call_value;call 2418717018. Width means share; left-to-right order means nothing, and flamegraph.pl sorts the boxes alphabetically^[2].

Notice how short the tower is. fib recurses 35 deep in Drip, but Drip’s calls are entries in the VM’s frames vector, not Rust calls. A profile of drip-rs shows the VM. To profile the Drip program, the VM itself would have to count per Drip function, chapter 109’s instrumentation. drip-rs doesn’t.

Instrumenting is the other road: make the program count for itself. Here is a toy VM tallying its opcodes:

#[derive(Clone, Copy, Debug)]
enum Op {
    Push(f64),
    Add,
    Jump(usize),
    Halt,
}

fn add(st: &mut Vec<f64>) {
    let b = st.pop().expect("b");
    let a = st.pop().expect("a");
    st.push(a + b);
}

fn main() {
    // A loop that never ends by itself:
    // the counter stops it.
    let code = [
        Op::Push(1.0),
        Op::Push(2.0),
        Op::Add,
        Op::Jump(0),
        Op::Halt,
    ];
    let mut counts = [0u64; 4];
    let mut st: Vec<f64> = vec![];
    let mut ip = 0;
    for _ in 0..1000 {
        let op = code[ip];
        ip += 1;
        let k = match op {
            Op::Push(_) => 0,
            Op::Add => 1,
            Op::Jump(_) => 2,
            Op::Halt => 3,
        };
        counts[k] += 1;
        match op {
            Op::Push(v) => st.push(v),
            Op::Add => add(&mut st),
            Op::Jump(t) => {
                st.clear();
                ip = t;
            }
            Op::Halt => break,
        }
    }
    let total: u64 =
        counts.iter().sum();
    let names =
        ["Push", "Add", "Jump", "Halt"];
    for k in 0..4 {
        let n = names[k];
        let c = counts[k];
        let p = 100.0 * c as f64
            / total as f64;
        println!("{n:5}{c:5}{p:6.1}%");
    }
}

Your turn

// A line of callgrind_annotate output.
#[derive(Debug, PartialEq)]
struct Row {
    ir: u64,
    pct: f64,
    name: String,
}

fn parse_row(line: &str)
    -> Option<Row> {
    todo!()
}

fn sum_named(rows: &[Row], needle: &str)
    -> u64 {
    todo!()
}

use std::collections::HashMap;

fn inclusive(folded: &[(&str, u64)])
    -> HashMap<String, u64> {
    HashMap::new()
}

What you learned

• Profiling measures where the work goes. Sampling profilers estimate time; callgrind counts instructions exactly, about 60× slower.
• Self cost is a function’s own instructions; inclusive adds its callees. Check a profile against counts you know: 29,860,703 calls.
• Inlining folds small functions into their callers. Line tables bring the lines back without changing the code.
• A flame graph stacks boxes by call depth, width by share. Order means nothing. drip-rs’s graph is flat because Drip calls aren’t Rust calls.
• Instruction counts are steady but are not time.