From bc205bf860790176e265ca6f2587013f32bb97f1 Mon Sep 17 00:00:00 2001 From: jyviko <2501648+jyviko@users.noreply.github.com> Date: Tue, 27 Oct 2026 03:49:33 -0400 Subject: [PATCH] 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 --- Cargo.lock | 8 + Cargo.toml | 1 + crates/profile/Cargo.toml | 20 ++ crates/profile/src/lib.rs | 586 ++++++++++++++++++++++++++++++++++++ crates/profile/src/tests.rs | 158 ++++++++++ xtask/src/layers.rs | 2 + 6 files changed, 775 insertions(+) create mode 100644 crates/profile/Cargo.toml create mode 100644 crates/profile/src/lib.rs create mode 100644 crates/profile/src/tests.rs diff --git a/Cargo.lock b/Cargo.lock index fd5e712ba2..5e7847deec 100644 --- a/Cargo.lock +++ b/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" diff --git a/Cargo.toml b/Cargo.toml index 08be552730..5e8c5cffdf 100644 --- a/Cargo.toml +++ b/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" } diff --git a/crates/profile/Cargo.toml b/crates/profile/Cargo.toml new file mode 100644 index 0000000000..589bd57fda --- /dev/null +++ b/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 } diff --git a/crates/profile/src/lib.rs b/crates/profile/src/lib.rs new file mode 100644 index 0000000000..caff753f3b --- /dev/null +++ b/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, + /// 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 { + 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 = 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 = 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 = 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, +} + +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(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, + events: Vec, + dropped: u64, + threads: Vec<(u32, String)>, + next_tid: u32, + since_ns: u64, + } + + static GLOBAL: LazyLock> = LazyLock::new(|| Mutex::new(Global::default())); + static NAMES: LazyLock>> = 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 = 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> = const { RefCell::new(Vec::new()) }; + /// This thread's number in the trace (0: not given one yet). + static TID: Cell = const { Cell::new(0) }; + } + + pub(super) struct Open { + key: Key, + start_ns: u64, + depth: usize, + } + + pub(super) fn open(key: Key) -> Option { + 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; diff --git a/crates/profile/src/tests.rs b/crates/profile/src/tests.rs new file mode 100644 index 0000000000..a3da6ae4c4 --- /dev/null +++ b/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::>().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"); +} diff --git a/xtask/src/layers.rs b/xtask/src/layers.rs index 309bf40744..79b45c6281 100644 --- a/xtask/src/layers.rs +++ b/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)),