Profiler crate: nested per-thread spans, an aggregate table and a Chrome trace

solidcraft-profile (L0, standalone): spans with self and total time, SMLib-timed
records, a bounded trace (200k events) and an aggregate that stays; compiled in
with the `enabled` feature, off at run time until switched on.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Cargo.lock

@@ -4228,6 +4228,14 @@ dependencies = [
  "solidcraft-gpu",
 ]
 
+[[package]]
+name = "solidcraft-profile"
+version = "0.24.0"
+dependencies = [
+ "serde_json",
+ "web-time",
+]
+
 [[package]]
 name = "solidcraft-render"
 version = "0.24.0"

Cargo.toml

@@ -16,6 +16,7 @@ repository = "https://github.com/bherbruck/solidcraft"
 robust = "1.2"
 # internal
 solidcraft-geom = { path = "crates/geom" }
+solidcraft-profile = { path = "crates/profile" }
 solidcraft-sketch = { path = "crates/sketch" }
 solidcraft-kernel = { path = "crates/kernel" }
 solidcraft-smlib = { path = "crates/smlib" }

crates/profile/Cargo.toml

@@ -0,0 +1,20 @@
+[package]
+name = "solidcraft-profile"
+description = "SolidCraft profiler: nested, per-thread timed spans of SMLib calls, kernel operations, feature evaluation, commands and imports, as a table and a Chrome trace"
+version.workspace = true
+edition.workspace = true
+license.workspace = true
+
+[lints]
+workspace = true
+
+[features]
+# Compile the profiler in. Every app turns it on by default (its `profile` feature); off, every
+# call here is an empty inline function and the crate records nothing. On, recording still waits
+# for `set_enabled(true)`, and a span costs one relaxed atomic load until then.
+enabled = []
+
+[dependencies]
+serde_json = { workspace = true }
+# Instant that also works in the browser (std's panics on wasm32-unknown-unknown).
+web-time = { workspace = true }

crates/profile/src/lib.rs

@@ -0,0 +1,586 @@
+//! Where SolidCraft spends its time: nested, timed spans on every thread, for SMLib's C API
+//! calls (timed by the C API itself), kernel operations, feature evaluation, commands and the
+//! stages of a STEP or IGES import.
+//!
+//! - **Compiled in** with the `enabled` feature, which every app turns on by default (its own
+//!   `profile` feature), so a release can be profiled; a build without it records nothing and
+//!   every call here is an empty inline function.
+//! - **Off at run time** until [`set_enabled`] (`SOLIDCRAFT_PROFILE=1`, the CLI's `--profile`, the
+//!   app's preference, the `diagnostics.profile` command). Off, a span costs one relaxed atomic
+//!   load.
+//! - **Two outputs:** an aggregate per span name ([`report`]: count, total, self time, longest),
+//!   kept for the whole run, and the individual spans as a Chrome trace-event file
+//!   ([`write_chrome_trace`], for chrome://tracing or Perfetto), capped at [`MAX_EVENTS`]
+//!   (later spans still count in the aggregate; the report says how many were dropped).
+//!
+//! A span's self time is its time less its children's on the same thread. Its total counts only
+//! its outermost occurrence on a thread's stack, so a command run by a command, or a boolean
+//! inside a boolean, is not counted twice. Work a span hands to other threads shows there, under
+//! those threads' own spans.
+#![deny(clippy::unwrap_used, clippy::expect_used, clippy::panic, clippy::unimplemented, clippy::todo, clippy::unreachable)]
+
+use std::time::Duration;
+
+use serde_json::{Value, json};
+
+/// The profiler is compiled into this build.
+pub const COMPILED: bool = cfg!(any(feature = "enabled", test));
+
+/// Spans kept for the trace; later ones count in the aggregate only.
+pub const MAX_EVENTS: usize = 200_000;
+
+/// Distinct names [`intern`] keeps; later new names are all [`OTHER`].
+pub const MAX_NAMES: usize = 4096;
+
+/// The name of a span whose own name did not fit in [`MAX_NAMES`].
+pub const OTHER: &str = "other";
+
+/// One span name's aggregate.
+#[derive(Clone, Copy, Debug, Default, PartialEq)]
+pub struct Row {
+    /// What the span is: `smlib`, `kernel`, `feature`, `command`, `import`, …
+    pub category: &'static str,
+    pub name: &'static str,
+    /// Times the span ran.
+    pub count: u64,
+    /// Its time, counting only its outermost occurrence on each thread's stack.
+    pub total: Duration,
+    /// Its time less the time of the spans inside it.
+    pub self_time: Duration,
+    /// Its longest single run.
+    pub max: Duration,
+}
+
+/// What the profiler has recorded since it was last reset.
+#[derive(Clone, Debug, Default, PartialEq)]
+pub struct Report {
+    /// The profiler is compiled in.
+    pub compiled: bool,
+    /// It is recording now.
+    pub enabled: bool,
+    /// Wall time since the last reset (or since recording first started).
+    pub wall: Duration,
+    /// One row per span name, in no particular order.
+    pub rows: Vec<Row>,
+    /// Spans kept for the trace.
+    pub events: usize,
+    /// Spans past [`MAX_EVENTS`], left out of the trace (they are in the rows).
+    pub dropped: u64,
+}
+
+fn ms(d: Duration) -> f64 {
+    (d.as_secs_f64() * 1e6).round() / 1e3
+}
+
+impl Report {
+    /// The rows, the most self time first.
+    pub fn sorted(&self) -> Vec<Row> {
+        let mut rows = self.rows.clone();
+        rows.sort_by(|a, b| b.self_time.cmp(&a.self_time).then(b.total.cmp(&a.total)).then(a.name.cmp(b.name)));
+        rows
+    }
+
+    /// Self time per category, the most first: where the time went (SMLib or SolidCraft).
+    pub fn by_category(&self) -> Vec<(&'static str, Duration)> {
+        let mut out: Vec<(&'static str, Duration)> = Vec::new();
+        for r in &self.rows {
+            match out.iter_mut().find(|(c, _)| *c == r.category) {
+                Some((_, d)) => *d += r.self_time,
+                None => out.push((r.category, r.self_time)),
+            }
+        }
+        out.sort_by(|a, b| b.1.cmp(&a.1).then(a.0.cmp(b.0)));
+        out
+    }
+
+    /// What was recorded after `earlier` (a report of the same run, taken before): counts and
+    /// times are the differences. `max` is the longest run of the whole recording, which may
+    /// be older than `earlier`.
+    pub fn since(&self, earlier: &Report) -> Report {
+        let rows = self
+            .rows
+            .iter()
+            .filter_map(|r| {
+                let before = earlier.rows.iter().find(|e| e.category == r.category && e.name == r.name);
+                let row = match before {
+                    Some(e) => Row {
+                        count: r.count.saturating_sub(e.count),
+                        total: r.total.saturating_sub(e.total),
+                        self_time: r.self_time.saturating_sub(e.self_time),
+                        ..*r
+                    },
+                    None => *r,
+                };
+                (row.count > 0).then_some(row)
+            })
+            .collect();
+        Report {
+            compiled: self.compiled,
+            enabled: self.enabled,
+            wall: self.wall.saturating_sub(earlier.wall),
+            rows,
+            events: self.events.saturating_sub(earlier.events),
+            dropped: self.dropped.saturating_sub(earlier.dropped),
+        }
+    }
+
+    /// The report as JSON, with the `top` rows of most self time (0: all of them):
+    /// `{compiled, enabled, wall_ms, spans, dropped, by_category: [{category, self_ms, share}],
+    /// rows: [{category, name, count, total_ms, self_ms, max_ms}], rows_total}`.
+    pub fn to_json(&self, top: usize) -> Value {
+        let sorted = self.sorted();
+        let all: f64 = self.rows.iter().map(|r| r.self_time.as_secs_f64()).sum();
+        let by_category: Vec<Value> = self
+            .by_category()
+            .into_iter()
+            .map(|(c, d)| {
+                let share = if all > 0.0 { (d.as_secs_f64() / all * 1000.0).round() / 1000.0 } else { 0.0 };
+                json!({"category": c, "self_ms": ms(d), "share": share})
+            })
+            .collect();
+        let n = if top == 0 { sorted.len() } else { top.min(sorted.len()) };
+        let rows: Vec<Value> = sorted
+            .iter()
+            .take(n)
+            .map(|r| {
+                json!({"category": r.category, "name": r.name, "count": r.count, "total_ms": ms(r.total), "self_ms": ms(r.self_time), "max_ms": ms(r.max)})
+            })
+            .collect();
+        json!({
+            "compiled": self.compiled,
+            "enabled": self.enabled,
+            "wall_ms": ms(self.wall),
+            "spans": self.events as u64 + self.dropped,
+            "dropped": self.dropped,
+            "by_category": by_category,
+            "rows": rows,
+            "rows_total": sorted.len(),
+        })
+    }
+
+    /// The report as a text table with the `top` rows of most self time (0: all of them).
+    pub fn table(&self, top: usize) -> String {
+        use std::fmt::Write as _;
+        let mut s = String::new();
+        if !self.compiled {
+            s.push_str("profile: not compiled into this build (the `profile` feature is off)\n");
+            return s;
+        }
+        let spans = self.events as u64 + self.dropped;
+        let _ = writeln!(s, "profile: {:.1} ms wall, {spans} spans ({} not kept for the trace)", ms(self.wall), self.dropped);
+        let all: f64 = self.rows.iter().map(|r| r.self_time.as_secs_f64()).sum();
+        let parts: Vec<String> = self
+            .by_category()
+            .into_iter()
+            .map(|(c, d)| {
+                let share = if all > 0.0 { d.as_secs_f64() / all * 100.0 } else { 0.0 };
+                format!("{c} {:.1} ms ({share:.1}%)", ms(d))
+            })
+            .collect();
+        let _ = writeln!(s, "self time by category: {}", if parts.is_empty() { "nothing recorded".to_string() } else { parts.join(", ") });
+        let sorted = self.sorted();
+        let n = if top == 0 { sorted.len() } else { top.min(sorted.len()) };
+        let _ = writeln!(s, "{:>11} {:>11} {:>8} {:>10}  span", "self ms", "total ms", "count", "max ms");
+        for r in sorted.iter().take(n) {
+            let _ = writeln!(s, "{:>11.3} {:>11.3} {:>8} {:>10.3}  {} {}", ms(r.self_time), ms(r.total), r.count, ms(r.max), r.category, r.name);
+        }
+        if n < sorted.len() {
+            let _ = writeln!(s, "({} more span names)", sorted.len() - n);
+        }
+        s
+    }
+}
+
+/// A point in the recording to report from ([`Mark::report`]): an import's own share.
+#[derive(Clone, Debug)]
+pub struct Mark(Report);
+
+/// Mark the recording here.
+pub fn mark() -> Mark {
+    Mark(report())
+}
+
+impl Mark {
+    /// What was recorded since the mark (all threads: work running beside it counts too).
+    pub fn report(&self) -> Report {
+        report().since(&self.0)
+    }
+}
+
+/// A running span; it ends when dropped (also while a panic unwinds).
+#[must_use = "a span measures until it is dropped"]
+pub struct Span {
+    #[cfg(any(feature = "enabled", test))]
+    open: Option<imp::Open>,
+}
+
+impl Drop for Span {
+    #[inline]
+    fn drop(&mut self) {
+        #[cfg(any(feature = "enabled", test))]
+        if let Some(open) = self.open.take() {
+            imp::close(&open);
+        }
+    }
+}
+
+/// Start a span `name` of `category` on this thread, when recording.
+#[inline]
+pub fn span(category: &'static str, name: &'static str) -> Span {
+    #[cfg(any(feature = "enabled", test))]
+    {
+        Span { open: if enabled() { imp::open((category, name)) } else { None } }
+    }
+    #[cfg(not(any(feature = "enabled", test)))]
+    {
+        let _ = (category, name);
+        Span {}
+    }
+}
+
+/// Run `f` as a span.
+#[inline]
+pub fn scope<T>(category: &'static str, name: &'static str, f: impl FnOnce() -> T) -> T {
+    let _span = span(category, name);
+    f()
+}
+
+/// Record a span that just ended after `took`, timed by someone else (SMLib's C API times its
+/// own calls): a child of the span running on this thread.
+#[inline]
+pub fn record(category: &'static str, name: &'static str, took: Duration) {
+    #[cfg(any(feature = "enabled", test))]
+    if enabled() {
+        imp::record((category, name), u64::try_from(took.as_nanos()).unwrap_or(u64::MAX));
+    }
+    #[cfg(not(any(feature = "enabled", test)))]
+    let _ = (category, name, took);
+}
+
+/// `name` as a name a span can take, kept for the rest of the run (at most [`MAX_NAMES`]
+/// distinct ones; after that [`OTHER`]). For names only known at run time, such as SMLib's C
+/// function names; spans named in code use literals.
+pub fn intern(name: &str) -> &'static str {
+    #[cfg(any(feature = "enabled", test))]
+    {
+        imp::intern(name)
+    }
+    #[cfg(not(any(feature = "enabled", test)))]
+    {
+        let _ = name;
+        OTHER
+    }
+}
+
+/// Is the profiler recording?
+#[inline]
+pub fn enabled() -> bool {
+    #[cfg(any(feature = "enabled", test))]
+    {
+        imp::ON.load(std::sync::atomic::Ordering::Relaxed)
+    }
+    #[cfg(not(any(feature = "enabled", test)))]
+    {
+        false
+    }
+}
+
+/// Start or stop recording (nothing happens when the profiler is not compiled in). What was
+/// recorded stays until [`reset`].
+pub fn set_enabled(on: bool) {
+    #[cfg(any(feature = "enabled", test))]
+    imp::set_enabled(on);
+    #[cfg(not(any(feature = "enabled", test)))]
+    let _ = on;
+}
+
+/// Forget what was recorded; the wall time starts again now.
+pub fn reset() {
+    #[cfg(any(feature = "enabled", test))]
+    imp::reset();
+}
+
+/// What was recorded since the last reset.
+pub fn report() -> Report {
+    #[cfg(any(feature = "enabled", test))]
+    {
+        imp::report()
+    }
+    #[cfg(not(any(feature = "enabled", test)))]
+    {
+        Report::default()
+    }
+}
+
+/// Write the kept spans as a Chrome trace-event file (JSON object format: complete events, one
+/// track per thread), for chrome://tracing or Perfetto.
+pub fn write_chrome_trace(w: &mut dyn std::io::Write) -> std::io::Result<()> {
+    #[cfg(any(feature = "enabled", test))]
+    {
+        imp::write_chrome_trace(w)
+    }
+    #[cfg(not(any(feature = "enabled", test)))]
+    {
+        w.write_all(br#"{"displayTimeUnit":"ms","traceEvents":[]}"#)
+    }
+}
+
+#[cfg(any(feature = "enabled", test))]
+mod imp {
+    use std::cell::{Cell, RefCell};
+    use std::collections::HashMap;
+    use std::sync::atomic::{AtomicBool, Ordering};
+    use std::sync::{LazyLock, Mutex, MutexGuard, OnceLock, PoisonError};
+    use std::time::Duration;
+
+    use serde_json::json;
+    use web_time::Instant;
+
+    use super::{MAX_EVENTS, MAX_NAMES, OTHER, Report, Row};
+
+    pub(super) static ON: AtomicBool = AtomicBool::new(false);
+
+    type Key = (&'static str, &'static str);
+
+    /// Deeper spans on one thread are not recorded (a runaway recursion stays bounded).
+    const MAX_DEPTH: usize = 512;
+    /// Threads named in the trace.
+    const MAX_THREADS: usize = 4096;
+
+    #[derive(Clone, Copy, Default)]
+    struct Agg {
+        count: u64,
+        total_ns: u64,
+        self_ns: u64,
+        max_ns: u64,
+    }
+
+    #[derive(Clone, Copy)]
+    struct Event {
+        key: Key,
+        tid: u32,
+        start_ns: u64,
+        dur_ns: u64,
+    }
+
+    #[derive(Default)]
+    struct Global {
+        agg: HashMap<Key, Agg>,
+        events: Vec<Event>,
+        dropped: u64,
+        threads: Vec<(u32, String)>,
+        next_tid: u32,
+        since_ns: u64,
+    }
+
+    static GLOBAL: LazyLock<Mutex<Global>> = LazyLock::new(|| Mutex::new(Global::default()));
+    static NAMES: LazyLock<Mutex<HashMap<String, &'static str>>> = LazyLock::new(|| Mutex::new(HashMap::new()));
+
+    fn global() -> MutexGuard<'static, Global> {
+        // A panic while the lock was held leaves plain data behind: keep using it.
+        GLOBAL.lock().unwrap_or_else(PoisonError::into_inner)
+    }
+
+    fn epoch() -> Instant {
+        static EPOCH: OnceLock<Instant> = OnceLock::new();
+        *EPOCH.get_or_init(Instant::now)
+    }
+
+    fn now_ns() -> u64 {
+        u64::try_from(epoch().elapsed().as_nanos()).unwrap_or(u64::MAX)
+    }
+
+    struct Frame {
+        key: Key,
+        child_ns: u64,
+    }
+
+    thread_local! {
+        static STACK: RefCell<Vec<Frame>> = const { RefCell::new(Vec::new()) };
+        /// This thread's number in the trace (0: not given one yet).
+        static TID: Cell<u32> = const { Cell::new(0) };
+    }
+
+    pub(super) struct Open {
+        key: Key,
+        start_ns: u64,
+        depth: usize,
+    }
+
+    pub(super) fn open(key: Key) -> Option<Open> {
+        let depth = STACK
+            .try_with(|s| {
+                let mut s = s.try_borrow_mut().ok()?;
+                if s.len() >= MAX_DEPTH {
+                    return None;
+                }
+                s.push(Frame { key, child_ns: 0 });
+                Some(s.len() - 1)
+            })
+            .ok()
+            .flatten()?;
+        Some(Open { key, start_ns: now_ns(), depth })
+    }
+
+    pub(super) fn close(o: &Open) {
+        let dur = now_ns().saturating_sub(o.start_ns);
+        let (child, outermost) = STACK
+            .try_with(|s| {
+                let Ok(mut s) = s.try_borrow_mut() else { return (0, true) };
+                let child = s.get(o.depth).map_or(0, |f| f.child_ns);
+                // Spans opened inside this one and not closed yet (leaked) end with it.
+                s.truncate(o.depth);
+                let outermost = !s.iter().any(|f| f.key == o.key);
+                if let Some(parent) = s.last_mut() {
+                    parent.child_ns = parent.child_ns.saturating_add(dur);
+                }
+                (child, outermost)
+            })
+            .unwrap_or((0, true));
+        add(o.key, o.start_ns, dur, dur.saturating_sub(child), outermost);
+    }
+
+    pub(super) fn record(key: Key, dur: u64) {
+        let start = now_ns().saturating_sub(dur);
+        let outermost = STACK
+            .try_with(|s| {
+                let Ok(mut s) = s.try_borrow_mut() else { return true };
+                let outermost = !s.iter().any(|f| f.key == key);
+                if let Some(parent) = s.last_mut() {
+                    parent.child_ns = parent.child_ns.saturating_add(dur);
+                }
+                outermost
+            })
+            .unwrap_or(true);
+        add(key, start, dur, dur, outermost);
+    }
+
+    fn thread_id(g: &mut Global) -> u32 {
+        TID.try_with(|t| {
+            if t.get() == 0 {
+                g.next_tid = g.next_tid.saturating_add(1);
+                t.set(g.next_tid);
+                if g.threads.len() < MAX_THREADS {
+                    g.threads.push((g.next_tid, thread_name(g.next_tid)));
+                }
+            }
+            t.get()
+        })
+        .unwrap_or(0)
+    }
+
+    #[cfg(not(target_arch = "wasm32"))]
+    fn thread_name(tid: u32) -> String {
+        std::thread::current().name().map_or_else(|| format!("thread {tid}"), str::to_string)
+    }
+
+    #[cfg(target_arch = "wasm32")]
+    fn thread_name(_: u32) -> String {
+        "main".into()
+    }
+
+    fn add(key: Key, start_ns: u64, dur_ns: u64, self_ns: u64, outermost: bool) {
+        let mut g = global();
+        let tid = thread_id(&mut g);
+        let a = g.agg.entry(key).or_default();
+        a.count = a.count.saturating_add(1);
+        if outermost {
+            a.total_ns = a.total_ns.saturating_add(dur_ns);
+        }
+        a.self_ns = a.self_ns.saturating_add(self_ns);
+        a.max_ns = a.max_ns.max(dur_ns);
+        if g.events.len() < MAX_EVENTS {
+            g.events.push(Event { key, tid, start_ns, dur_ns });
+        } else {
+            g.dropped = g.dropped.saturating_add(1);
+        }
+    }
+
+    pub(super) fn intern(name: &str) -> &'static str {
+        let mut names = NAMES.lock().unwrap_or_else(PoisonError::into_inner);
+        if let Some(n) = names.get(name) {
+            return n;
+        }
+        if names.len() >= MAX_NAMES {
+            return OTHER;
+        }
+        let kept: &'static str = Box::leak(name.to_string().into_boxed_str());
+        names.insert(name.to_string(), kept);
+        kept
+    }
+
+    pub(super) fn set_enabled(on: bool) {
+        let was = ON.swap(on, Ordering::Relaxed);
+        if on && !was {
+            let now = now_ns();
+            let mut g = global();
+            // The wall time starts with the first recording.
+            if g.agg.is_empty() {
+                g.since_ns = now;
+            }
+        }
+    }
+
+    pub(super) fn reset() {
+        let now = now_ns();
+        let mut g = global();
+        g.agg.clear();
+        g.events = Vec::new();
+        g.dropped = 0;
+        g.since_ns = now;
+    }
+
+    pub(super) fn report() -> Report {
+        let now = now_ns();
+        let g = global();
+        let d = Duration::from_nanos;
+        let rows = g
+            .agg
+            .iter()
+            .map(|(k, a)| Row { category: k.0, name: k.1, count: a.count, total: d(a.total_ns), self_time: d(a.self_ns), max: d(a.max_ns) })
+            .collect();
+        Report {
+            compiled: true,
+            enabled: ON.load(Ordering::Relaxed),
+            wall: d(now.saturating_sub(g.since_ns)),
+            rows,
+            events: g.events.len(),
+            dropped: g.dropped,
+        }
+    }
+
+    pub(super) fn write_chrome_trace(w: &mut dyn std::io::Write) -> std::io::Result<()> {
+        // Copied out, so spans closing on other threads don't wait for the file.
+        let (events, threads, dropped) = {
+            let g = global();
+            (g.events.clone(), g.threads.clone(), g.dropped)
+        };
+        let us = |ns: u64| ns as f64 / 1000.0;
+        write!(w, "{{\"displayTimeUnit\":\"ms\",\"otherData\":{{\"dropped\":{dropped}}},\"traceEvents\":[")?;
+        let mut first = true;
+        let mut sep = |w: &mut dyn std::io::Write| -> std::io::Result<()> {
+            if !first {
+                w.write_all(b",\n")?;
+            }
+            first = false;
+            Ok(())
+        };
+        sep(w)?;
+        serde_json::to_writer(&mut *w, &json!({"ph": "M", "name": "process_name", "pid": 1, "tid": 0, "args": {"name": "SolidCraft"}}))?;
+        for (tid, name) in &threads {
+            sep(w)?;
+            serde_json::to_writer(&mut *w, &json!({"ph": "M", "name": "thread_name", "pid": 1, "tid": tid, "args": {"name": name}}))?;
+        }
+        for e in &events {
+            sep(w)?;
+            serde_json::to_writer(
+                &mut *w,
+                &json!({"ph": "X", "cat": e.key.0, "name": e.key.1, "pid": 1, "tid": e.tid, "ts": us(e.start_ns), "dur": us(e.dur_ns)}),
+            )?;
+        }
+        w.write_all(b"]}\n")
+    }
+}
+
+#[cfg(test)]
+mod tests;

crates/profile/src/tests.rs

@@ -0,0 +1,158 @@
+use super::*;
+
+/// The profiler is global: tests that switch it on and off run one at a time.
+static SERIAL: std::sync::Mutex<()> = std::sync::Mutex::new(());
+
+fn serial() -> std::sync::MutexGuard<'static, ()> {
+    SERIAL.lock().unwrap_or_else(std::sync::PoisonError::into_inner)
+}
+
+fn spin(ms: u64) {
+    let t = web_time::Instant::now();
+    while t.elapsed() < Duration::from_millis(ms) {}
+}
+
+fn row(r: &Report, name: &str) -> Row {
+    r.rows.iter().find(|x| x.name == name).copied().unwrap_or_else(|| panic!("no row {name}: {r:?}"))
+}
+
+#[test]
+fn nothing_is_recorded_while_off() {
+    let _s = serial();
+    set_enabled(false);
+    reset();
+    {
+        let _a = span("test", "off");
+        spin(1);
+    }
+    record("test", "off_record", Duration::from_millis(3));
+    assert!(report().rows.is_empty());
+}
+
+#[test]
+fn nested_spans_have_self_and_total_time() {
+    let _s = serial();
+    reset();
+    set_enabled(true);
+    {
+        let _outer = span("test", "outer");
+        spin(4);
+        {
+            let _inner = span("test", "inner");
+            spin(4);
+        }
+        // Timed by someone else (SMLib's C API): a child of `outer`.
+        record("smlib", "call", Duration::from_millis(2));
+    }
+    set_enabled(false);
+    let r = report();
+    let (outer, inner, call) = (row(&r, "outer"), row(&r, "inner"), row(&r, "call"));
+    assert_eq!((outer.count, inner.count, call.count), (1, 1, 1));
+    assert!(outer.total >= Duration::from_millis(8), "{outer:?}");
+    assert!(inner.self_time >= Duration::from_millis(4), "{inner:?}");
+    assert_eq!(call.self_time, Duration::from_millis(2));
+    // The outer span's self time leaves out both children.
+    assert_eq!(outer.self_time, outer.total - inner.total - call.total, "{r:?}");
+    assert_eq!(r.events, 3);
+    let cats = r.by_category();
+    assert_eq!(cats.iter().map(|c| c.0).collect::<Vec<_>>().len(), 2);
+    let t = r.table(10);
+    assert!(t.contains("test outer") && t.contains("smlib call") && t.contains("self time by category"), "{t}");
+}
+
+#[test]
+fn a_span_inside_one_of_the_same_name_counts_once_in_the_total() {
+    let _s = serial();
+    reset();
+    set_enabled(true);
+    {
+        let _a = span("command", "x");
+        spin(2);
+        let _b = span("command", "x");
+        spin(2);
+    }
+    set_enabled(false);
+    let x = row(&report(), "x");
+    assert_eq!(x.count, 2);
+    assert!(x.total >= x.max && x.total <= x.max + Duration::from_micros(1), "only the outer one: {x:?}");
+}
+
+#[test]
+fn a_mark_reports_only_what_came_after_it() {
+    let _s = serial();
+    reset();
+    set_enabled(true);
+    drop(span("test", "before"));
+    let m = mark();
+    drop(span("test", "after"));
+    drop(span("test", "after"));
+    set_enabled(false);
+    let r = m.report();
+    assert_eq!(r.rows.len(), 1, "{r:?}");
+    assert_eq!(row(&r, "after").count, 2);
+    let j = r.to_json(5);
+    assert_eq!(j["rows"][0]["name"], "after");
+    assert_eq!(j["rows_total"], 1);
+}
+
+#[test]
+fn spans_on_other_threads_get_their_own_track() {
+    let _s = serial();
+    reset();
+    set_enabled(true);
+    let _main = span("test", "main");
+    std::thread::Builder::new().name("worker".into()).spawn(|| drop(span("test", "on_worker"))).unwrap().join().unwrap();
+    drop(_main);
+    set_enabled(false);
+    let mut out = Vec::new();
+    write_chrome_trace(&mut out).unwrap();
+    let v: Value = serde_json::from_slice(&out).unwrap();
+    let events = v["traceEvents"].as_array().unwrap();
+    let tid = |name: &str| events.iter().find(|e| e["name"] == name).map(|e| e["tid"].clone()).unwrap();
+    assert_ne!(tid("main"), tid("on_worker"));
+    assert!(events.iter().any(|e| e["name"] == "thread_name" && e["args"]["name"] == "worker"), "{v}");
+    let main = events.iter().find(|e| e["name"] == "main").unwrap();
+    assert_eq!((main["ph"].as_str(), main["cat"].as_str()), (Some("X"), Some("test")));
+    assert!(main["dur"].as_f64().is_some_and(|d| d >= 0.0));
+}
+
+#[test]
+fn the_trace_is_capped_and_the_aggregate_is_not() {
+    let _s = serial();
+    reset();
+    set_enabled(true);
+    for _ in 0..MAX_EVENTS + 10 {
+        drop(span("test", "many"));
+    }
+    set_enabled(false);
+    let r = report();
+    assert_eq!((r.events, r.dropped, row(&r, "many").count), (MAX_EVENTS, 10, MAX_EVENTS as u64 + 10));
+    reset();
+    assert_eq!(report().events, 0);
+}
+
+#[test]
+fn a_panic_inside_a_span_still_closes_it() {
+    let _s = serial();
+    reset();
+    set_enabled(true);
+    let _ = std::panic::catch_unwind(|| {
+        let _outer = span("test", "unwound");
+        let _inner = span("test", "unwound_inner");
+        std::panic::panic_any("kernel");
+    });
+    drop(span("test", "after_panic"));
+    set_enabled(false);
+    let r = report();
+    assert_eq!(row(&r, "unwound").count, 1);
+    // The stack is clean again: the next span is a root, its total its own.
+    let after = row(&r, "after_panic");
+    assert_eq!(after.total, after.self_time);
+}
+
+#[test]
+fn interned_names_are_kept_and_bounded() {
+    let a = intern("smlib_boolean");
+    assert!(std::ptr::eq(a, intern("smlib_boolean")));
+    assert_eq!(a, "smlib_boolean");
+}

xtask/src/layers.rs

@@ -42,6 +42,8 @@ pub const TABLE: &[(&str, Class)] = &[
     ("derive", Class::Standalone),
     // the 3Dconnexion driver's client API on macOS (no workspace dependencies)
     ("3dx-client", Class::Standalone),
+    // the profiler: timed spans for every layer, SMLib's calls to commands (no workspace dependencies)
+    ("profile", Class::Standalone),
     ("sketch", Class::Layer(1)),
     // NVIDIA's SMLib behind its C API (kernel-smlib branch, ADR 0002); only the kernel uses it
     ("smlib", Class::Layer(1)),