crates/nornir-trace/src/perf.rs
//! **`perf record -g` → time per function**, no rebuild.
//!
//! The runner records with the software clock (so each sample's period IS the
//! nanoseconds it stands for) and prints the samples raw:
//!
//! ```text
//! perf record -e cpu-clock -F 999 -g -o <data> -- <program> <args>
//! perf script -i <data> -F tid,period,ip,sym --no-demangle
//! ```
//!
//! [`parse_script`] reads that text (one sample per blank-line-separated block: a
//! header line `tid period`, then one frame per line, leaf first) and
//! [`aggregate`] folds the samples into per-function **self** time (the function
//! was the leaf: the CPU was in it) and **total** time (it was anywhere on the
//! stack: it or what it called) — a recursive function counts once per sample.
//!
//! What perf needs from the box (it never changes it): `perf_event_open` for the
//! traced process — `kernel.perf_event_paranoid` ≤ 2 for user-space samples of
//! one's own processes (Debian/Ubuntu ship 3/4 = off for unprivileged users), or
//! `CAP_PERFMON` on the process; in a container, a seccomp profile that admits
//! `perf_event_open` (podman's default admits it only with `CAP_PERFMON` /
//! `CAP_SYS_ADMIN`).
use std::collections::{HashMap, HashSet};
use serde::{Deserialize, Serialize};
use crate::xray::demangle;
/// The `perf record` argv before the program (`-o <data> -- <program> …` follow).
pub const RECORD_ARGS: &[&str] = &["record", "-e", "cpu-clock", "-F", "999", "-g"];
/// The `perf script` fields [`parse_script`] reads.
pub const SCRIPT_FIELDS: &str = "tid,period,ip,sym,dso";
/// One sampled call stack.
#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
pub struct Sample {
pub thread: u32,
/// What the sample stands for (ns, with `cpu-clock`).
pub period: u64,
/// Demangled frames, leaf first (`[unknown]` frames dropped).
pub stack: Vec<String>,
/// The object each frame's code is in (`""` when perf did not say), by frame.
#[serde(default)]
pub dsos: Vec<String>,
}
/// One function's share of a profile.
#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
pub struct FnHeat {
pub symbol: String,
/// The object its code is in (the program, a shared library), as perf named it.
#[serde(default)]
pub dso: String,
/// Time the CPU was IN it (it was the leaf).
pub self_ns: u64,
/// Time it was on the stack (it or its callees).
pub total_ns: u64,
pub self_samples: u64,
pub total_samples: u64,
}
/// A whole profile: per-function heat, hottest total first.
#[derive(Debug, Clone, PartialEq, Eq, Default, Serialize, Deserialize)]
pub struct Profile {
pub samples: u64,
/// The sum of every sample's period.
pub total_ns: u64,
pub functions: Vec<FnHeat>,
}
/// **Read `perf script -F tid,period,ip,sym` output.** A block's first line is
/// the sample header (`tid period`, period optional → 1); every further line is
/// a frame (`ip symbol[+off] [(dso)]`). Mangled symbols are demangled here.
pub fn parse_script(text: &str) -> Vec<Sample> {
let mut out = Vec::new();
let mut cur: Option<Sample> = None;
for line in text.lines() {
if line.trim().is_empty() {
if let Some(s) = cur.take() {
out.push(s);
}
continue;
}
match cur.as_mut() {
None => {
let mut nums = line
.split_whitespace()
.filter_map(|t| t.trim_end_matches(':').parse::<u64>().ok());
let Some(tid) = nums.next() else { continue };
let period = nums.next().unwrap_or(1).max(1);
cur = Some(Sample { thread: tid as u32, period, stack: Vec::new(), dsos: Vec::new() });
}
Some(s) => {
let t = line.trim();
// `(dso)` at the end, when asked for
let (body, dso) = match (t.ends_with(')'), t.rfind(" (")) {
(true, Some(i)) => (&t[..i], &t[i + 2..t.len() - 1]),
_ => (t, ""),
};
let mut parts = body.split_whitespace();
let _ip = parts.next();
let Some(sym) = parts.next() else { continue };
let sym = sym.split("+0x").next().unwrap_or(sym);
if sym == "[unknown]" || sym.is_empty() {
continue;
}
s.stack.push(demangle(sym));
s.dsos.push(if dso == "[unknown]" { String::new() } else { dso.to_string() });
}
}
}
if let Some(s) = cur.take() {
out.push(s);
}
out
}
/// **Fold samples into per-function self / total time.**
pub fn aggregate(samples: &[Sample]) -> Profile {
let mut by: HashMap<&str, FnHeat> = HashMap::new();
let mut p = Profile::default();
for s in samples {
p.samples += 1;
p.total_ns += s.period;
let mut seen: HashSet<&str> = HashSet::new();
for (i, f) in s.stack.iter().enumerate() {
let h = by.entry(f.as_str()).or_insert_with(|| FnHeat {
symbol: f.clone(),
dso: s.dsos.get(i).cloned().unwrap_or_default(),
self_ns: 0,
total_ns: 0,
self_samples: 0,
total_samples: 0,
});
if i == 0 {
h.self_ns += s.period;
h.self_samples += 1;
}
if seen.insert(f.as_str()) {
h.total_ns += s.period;
h.total_samples += 1;
}
}
}
p.functions = by.into_values().collect();
p.functions.sort_by(|a, b| b.total_ns.cmp(&a.total_ns).then(a.symbol.cmp(&b.symbol)));
p
}
#[cfg(test)]
mod tests {
use super::*;
const SCRIPT: &str = "\
4242 1000000
55d0c2a4b1c0 _ZN2xt4leaf17h0123456789abcdefE+0x20 (/w/xt)
55d0c2a4b2c0 _ZN2xt6middle17h0123456789abcdefE+0x10 (/w/xt)
55d0c2a4b3c0 _ZN2xt3top17h0123456789abcdefE+0x8 (/w/xt)
4242 1000000
55d0c2a4b2c0 _ZN2xt6middle17h0123456789abcdefE+0x14 (/w/xt)
55d0c2a4b3c0 _ZN2xt3top17h0123456789abcdefE+0x8 (/w/xt)
4243 2000000
55d0c2a4b1c0 _ZN2xt4leaf17h0123456789abcdefE+0x20 (/w/xt)
55d0c2a4b1c0 _ZN2xt4leaf17h0123456789abcdefE+0x30 (/w/xt)
ffffffffffff [unknown] ([unknown])
55d0c2a4b3c0 _ZN2xt3top17h0123456789abcdefE+0x8 (/w/xt)
";
#[test]
fn perf_samples_sum_into_self_and_total_time_per_function() {
let samples = parse_script(SCRIPT);
assert_eq!(samples.len(), 3);
assert_eq!(samples[2].thread, 4243);
assert_eq!(samples[2].stack, vec!["xt::leaf", "xt::leaf", "xt::top"], "unknown frames dropped, demangled");
let p = aggregate(&samples);
assert_eq!((p.samples, p.total_ns), (3, 4_000_000));
let get = |f: &str| p.functions.iter().find(|h| h.symbol == f).unwrap().clone();
// top: on every stack, never the leaf
assert_eq!((get("xt::top").self_ns, get("xt::top").total_ns), (0, 4_000_000));
// middle: leaf once (1 ms), on two stacks (2 ms)
assert_eq!((get("xt::middle").self_ns, get("xt::middle").total_ns), (1_000_000, 2_000_000));
// leaf: leaf twice (1 + 2 ms); recursive in sample 3, counted once
let leaf = get("xt::leaf");
assert_eq!((leaf.self_ns, leaf.total_ns, leaf.self_samples, leaf.total_samples), (3_000_000, 3_000_000, 2, 2));
// self time sums to the whole profile (every sample has one leaf)
assert_eq!(p.functions.iter().map(|h| h.self_ns).sum::<u64>(), p.total_ns);
assert_eq!(p.functions[0].symbol, "xt::top", "hottest total first");
assert_eq!((p.functions[0].dso.as_str(), samples[0].dsos.len()), ("/w/xt", 3), "the object each frame is in");
}
}