crates/nornir-trace/src/lib.rs
//! # nornir-trace
//!
//! **Which functions ran, in what order, on which thread — read from a real run**,
//! for the Mímir 3D code map's replay (heads light on entry, a pulse runs along
//! the call spline, heat afterwards).
//!
//! Two sources, both pure here (bytes in, rows out — the runner that produced
//! them is the caller's):
//!
//! | source | how it is made | what it gives | module |
//! |---|---|---|---|
//! | **LLVM XRay**, basic mode | rustc `-Z instrument-xray=always`, linked with `-fxray-instrument` (clang pulls compiler-rt's XRay runtime), run with `XRAY_OPTIONS` | every instrumented function's entry and exit, TSC timestamp, thread id | [`xray`] |
//! | **`perf record -g`** | no rebuild: a sampling profiler over any binary | sampled call stacks → self / total time per function | [`perf`] |
//!
//! The XRay log is parsed **natively** ([`xray::parse_basic_log`]): its basic-mode
//! format is a 32-byte header and 32-byte records, and the function ids index the
//! binary's own `xray_instr_map` section ([`xray::function_addresses`]), whose
//! addresses the ELF symbol table names ([`xray::symbolize`]). No `llvm-xray`
//! binary is needed (rustup's `llvm-tools` does not ship one), and no YAML
//! round-trip of a million-record log.
//!
//! Symbols are demangled (`rustc-demangle`, hash dropped): `xt::middle`,
//! `<xt::Cart as core::ops::Drop>::drop`, `xt::tests::adds_up::{closure#0}`. Which
//! code-room function a symbol is, is the reader's (nornir's) to say — it holds
//! the room.
pub mod ebpf;
pub mod perf;
pub mod wire;
pub mod xray;
use serde::{Deserialize, Serialize};
pub use xray::LogInput;
/// A function was entered or left.
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, Serialize, Deserialize)]
#[serde(rename_all = "snake_case")]
pub enum EventKind {
Enter,
/// A normal return or a tail call out of the function (XRay's
/// `function-tail-exit`): either way the function's frame is gone.
Exit,
}
impl EventKind {
/// `enter` | `exit` — the stored spelling.
pub fn as_str(self) -> &'static str {
match self {
Self::Enter => "enter",
Self::Exit => "exit",
}
}
pub fn parse(s: &str) -> Option<Self> {
match s {
"enter" => Some(Self::Enter),
"exit" => Some(Self::Exit),
_ => None,
}
}
}
/// One function entry or exit of a run.
#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
pub struct TraceEvent {
/// The OS thread id the event happened on.
pub thread: u32,
/// The event's place in the run, in time order across threads (0-based).
pub seq_no: u64,
/// Nanoseconds since the run's first event.
pub t_ns: u64,
/// Index into [`TraceRun::functions`].
pub func: u32,
pub kind: EventKind,
}
/// One binary a run's events came from.
#[derive(Debug, Clone, PartialEq, Eq, Default, Serialize, Deserialize)]
pub struct TracedBinary {
/// Its file name (`code_room-5a220a9afb3ddc07`).
pub name: String,
/// Lowercase hex SHA-256 of the binary (the caller's to fill; empty = not
/// computed) — the key the binary lenses know a linked artifact by.
pub sha256: String,
/// How many functions it carries XRay sleds for.
pub instrumented: u32,
/// How many records its log held.
pub records: u64,
}
/// One function a run entered: its demangled symbol and where its code starts
/// (DWARF: the source line of its first instruction — the `fn` line, a
/// closure's own line). The location is the join key to the code room, the
/// symbol its fallback: a demangled name is not how the room spells a path.
#[derive(Debug, Clone, PartialEq, Eq, Default, Serialize, Deserialize)]
pub struct TracedFn {
pub symbol: String,
/// Absolute source path as the compiler saw it (`""` = no debug info).
#[serde(default)]
pub file: String,
/// 1-based (0 = unknown).
#[serde(default)]
pub line: u32,
}
/// A whole traced run: its functions and its events in time order.
#[derive(Debug, Clone, PartialEq, Eq, Default, Serialize, Deserialize)]
pub struct TraceRun {
/// Per function index (no duplicate symbols).
pub functions: Vec<TracedFn>,
pub events: Vec<TraceEvent>,
pub binaries: Vec<TracedBinary>,
/// Events beyond the cap were dropped (the earliest are kept).
pub truncated: bool,
/// Every entry/exit record the logs held, before the cap.
pub total_events: u64,
}
impl TraceRun {
/// The threads the run's events happened on, in first-seen order.
pub fn threads(&self) -> Vec<u32> {
let mut seen = Vec::new();
for e in &self.events {
if !seen.contains(&e.thread) {
seen.push(e.thread);
}
}
seen
}
/// Nanoseconds from the first event to the last.
pub fn duration_ns(&self) -> u64 {
self.events.last().map(|e| e.t_ns).unwrap_or(0)
}
/// **Total (inclusive) time per function**: the time between each entry and
/// its matching exit on the same thread, summed per function — a recursive
/// function counts its outermost frame only. An entry with no exit (the run
/// was cut) runs to the run's end. Indexed like [`TraceRun::functions`].
pub fn inclusive_ns(&self) -> Vec<u64> {
let mut total = vec![0u64; self.functions.len()];
let end = self.duration_ns();
// per thread: the open frames (func, t)
let mut stacks: std::collections::HashMap<u32, Vec<(u32, u64)>> = Default::default();
let mut depth: std::collections::HashMap<(u32, u32), u32> = Default::default();
for e in &self.events {
let st = stacks.entry(e.thread).or_default();
match e.kind {
EventKind::Enter => {
st.push((e.func, e.t_ns));
*depth.entry((e.thread, e.func)).or_default() += 1;
}
EventKind::Exit => {
// unwind to the matching frame (a frame whose exit was not
// recorded — a panic, an unlogged tail — closes here too)
while let Some((f, t0)) = st.pop() {
let d = depth.entry((e.thread, f)).or_default();
*d = d.saturating_sub(1);
if *d == 0 {
if let Some(slot) = total.get_mut(f as usize) {
*slot += e.t_ns.saturating_sub(t0);
}
}
if f == e.func {
break;
}
}
}
}
}
for (thread, st) in stacks {
for (f, t0) in st {
let d = depth.entry((thread, f)).or_default();
*d = d.saturating_sub(1);
if *d == 0 {
if let Some(slot) = total.get_mut(f as usize) {
*slot += end.saturating_sub(t0);
}
}
}
}
total
}
}
/// **A demangled symbol as the code room spells a function's path**
/// (`Room::display_path`): generic arguments dropped (`fold::<u32>` → `fold`),
/// a trait impl's method named through its self type
/// (`<xt::Cart as core::ops::Drop>::drop` → `xt::Cart::drop`), and a closure or
/// shim folded into the item that owns it (`runs_top::{closure#0}` →
/// `runs_top`). The name route of the join; the source location is the first.
pub fn room_path(sym: &str) -> String {
// 1. drop generic arguments, keep qualified-path brackets
let mut flat = String::with_capacity(sym.len());
let mut stack: Vec<bool> = Vec::new(); // true = qualified bracket
for c in sym.chars() {
let dropping = stack.iter().any(|q| !q);
match c {
'<' => {
let seg_start = flat.is_empty() || flat.ends_with('<') || flat.ends_with(' ');
if !dropping && seg_start {
stack.push(true);
flat.push('<');
} else {
if !dropping && flat.ends_with("::") {
flat.truncate(flat.len() - 2);
}
stack.push(false);
}
}
'>' => match stack.pop() {
Some(true) if !stack.iter().any(|q| !q) => flat.push('>'),
_ => {}
},
_ if !dropping => flat.push(c),
_ => {}
}
}
// 2. `<A as B>::m` / `<A>::m` → `A::m` (innermost first)
while let Some(close) = flat.find('>') {
let Some(open) = flat[..close].rfind('<') else { break };
let inner = &flat[open + 1..close];
let ty = inner.split(" as ").next().unwrap_or(inner).trim().to_string();
flat.replace_range(open..=close, &ty);
}
// 3. fold closures / shims into their owner
flat.split("::").filter(|seg| !seg.starts_with('{') && !seg.is_empty()).collect::<Vec<_>>().join("::")
}
#[cfg(test)]
mod tests {
use super::*;
fn ev(thread: u32, seq_no: u64, t_ns: u64, func: u32, kind: EventKind) -> TraceEvent {
TraceEvent { thread, seq_no, t_ns, func, kind }
}
#[test]
fn inclusive_time_pairs_entries_and_exits_per_thread_and_counts_recursion_once() {
use EventKind::*;
let run = TraceRun {
functions: ["a", "b", "rec"].map(|s| TracedFn { symbol: s.into(), ..Default::default() }).to_vec(),
events: vec![
ev(1, 0, 0, 0, Enter),
ev(2, 1, 5, 1, Enter), // another thread, overlapping
ev(1, 2, 10, 2, Enter),
ev(1, 3, 12, 2, Enter), // recursion
ev(1, 4, 20, 2, Exit),
ev(1, 5, 30, 2, Exit),
ev(2, 6, 35, 1, Exit),
ev(1, 7, 40, 0, Exit),
ev(1, 8, 50, 1, Enter), // never left: runs to the end
ev(2, 9, 60, 0, Enter),
ev(2, 10, 70, 0, Exit),
],
..Default::default()
};
assert_eq!(run.inclusive_ns(), vec![40 + 10, 30 + 20, 20]);
assert_eq!(run.threads(), vec![1, 2]);
assert_eq!(run.duration_ns(), 70);
}
#[test]
fn a_symbol_reads_as_the_rooms_path() {
for (sym, want) in [
("xt::middle", "xt::middle"),
("xt::fold::<u32, alloc::vec::Vec<u8>>", "xt::fold"),
("<xt::Cart as core::ops::drop::Drop>::drop", "xt::Cart::drop"),
("<xt::Bag<T> as xt::Count<u8>>::count", "xt::Bag::count"),
("<alloc::vec::Vec<T, A>>::push", "alloc::vec::Vec::push"),
("xt::tests::runs_top::{closure#0}", "xt::tests::runs_top"),
("<xt::run::{closure#0} as core::ops::FnOnce<()>>::call_once", "xt::run::call_once"),
] {
assert_eq!(room_path(sym), want, "{sym}");
}
}
}