diff --git a/Cargo.lock b/Cargo.lock index a8d9f3a9b1..3793afab48 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4122,6 +4122,7 @@ dependencies = [ "solidcraft-derive", "solidcraft-geom", "solidcraft-kernel", + "solidcraft-profile", "solidcraft-render", "solidcraft-sketch", "thiserror 2.0.21", @@ -4142,6 +4143,7 @@ dependencies = [ "solidcraft-geom", "solidcraft-io", "solidcraft-kernel", + "solidcraft-profile", "solidcraft-render", "solidcraft-sketch", "thiserror 2.0.21", @@ -4198,6 +4200,7 @@ dependencies = [ "solidcraft-doc", "solidcraft-geom", "solidcraft-kernel", + "solidcraft-profile", "thiserror 2.0.21", "zip", ] @@ -4287,6 +4290,7 @@ name = "solidcraft-step" version = "0.24.0" dependencies = [ "solidcraft-geom", + "solidcraft-profile", ] [[package]] diff --git a/apps/solidcraft-cli/Cargo.toml b/apps/solidcraft-cli/Cargo.toml index 3628d387bb..258dd32f91 100644 --- a/apps/solidcraft-cli/Cargo.toml +++ b/apps/solidcraft-cli/Cargo.toml @@ -20,12 +20,15 @@ name = "solvecraft-cli" path = "src/alias.rs" [features] -default = ["raytrace-cpu", "smlib"] +default = ["raytrace-cpu", "smlib", "profile"] bundled-render-library = ["solidcraft-engine/bundled-render-library"] raytrace-cpu = ["solidcraft-engine/raytrace-cpu"] # Link SMLib into the kernel (solidcraft-engine/smlib; needs scripts/fetch-smlib.sh). SMLib is the # only kernel, so without it the command line models nothing. smlib = ["solidcraft-engine/smlib"] +# The profiler, compiled in so any build can say where its time goes (`--profile`, +# SOLIDCRAFT_PROFILE=1); it records nothing until asked. +profile = ["solidcraft-engine/profile"] [dependencies] solidcraft-engine = { workspace = true } diff --git a/apps/solidcraft-cli/src/main.rs b/apps/solidcraft-cli/src/main.rs index 1f75f11056..531380d0a1 100644 --- a/apps/solidcraft-cli/src/main.rs +++ b/apps/solidcraft-cli/src/main.rs @@ -36,6 +36,7 @@ mod kernel_cases; mod logger; mod oracle; mod preview; +mod profiling; mod recipe; mod render; mod spatial; @@ -58,13 +59,13 @@ struct Command { } /// `run`'s lines in the usage. -const USAGE_RUN: &str = " solidcraft-cli run [--in design.solidcraft|part.step] [--out FILE]... [--save FILE] [--quiet] [--results] [--timings] [--profile] [--json-out FILE] [--allow-errors]\n solidcraft-cli run --in [--out FILE]...\n (a timeline feature that fails fails the run and nothing is written; --allow-errors writes anyway)\n (--timings prints {timings: [{index, command, ms}], total_ms} for a script, with --results its results too;\n --profile adds each command's profile: {boolean_ms, tessellate_ms, other_ms}, the kernel's share)\n"; +const USAGE_RUN: &str = " solidcraft-cli run [--in design.solidcraft|part.step] [--out FILE]... [--save FILE] [--quiet] [--results] [--timings] [--profile] [--profile-out trace.json] [--json-out FILE] [--allow-errors]\n solidcraft-cli run --in [--out FILE]...\n (a timeline feature that fails fails the run and nothing is written; --allow-errors writes anyway)\n (--timings prints {timings: [{index, command, ms}], total_ms} for a script, with --results its results too;\n --profile adds each command's profile: {boolean_ms, tessellate_ms, other_ms}, the kernel's share)\n (--profile also records where the time goes, SMLib's calls, kernel operations, features, commands and import stages,\n and prints the table to stderr: count, total, self time and longest per span; --profile-out FILE writes the spans\n as a Chrome trace for chrome://tracing or ui.perfetto.dev; SOLIDCRAFT_PROFILE=1 does the same for any command)\n"; /// `eval`'s lines in the usage. -const USAGE_EVAL: &str = " solidcraft-cli eval [--in design.solidcraft|part.step] [--json-out FILE] (alias: inspect)\n solidcraft-cli eval --in [--json-out FILE]\n (with both inputs, runs the positional script on --in before measuring; does not automatically save the modified design)\n (--json-out FILE writes the JSON that run (with --results, else the measurement) and eval print to FILE instead of stdout,\n as plain UTF-8: a shell's > can re-encode it, e.g. Windows PowerShell adds a byte-order mark)\n"; +const USAGE_EVAL: &str = " solidcraft-cli eval [--in design.solidcraft|part.step] [--json-out FILE] [--profile] [--profile-out trace.json] (alias: inspect)\n solidcraft-cli eval --in [--json-out FILE]\n (with both inputs, runs the positional script on --in before measuring; does not automatically save the modified design)\n (--json-out FILE writes the JSON that run (with --results, else the measurement) and eval print to FILE instead of stdout,\n as plain UTF-8: a shell's > can re-encode it, e.g. Windows PowerShell adds a byte-order mark)\n (--profile and --profile-out as for run)\n"; /// `script`'s lines in the usage. const USAGE_SCRIPT: &str = " solidcraft-cli script [--out script.json]\n (the design's history as a command script that eval and run replay)\n"; /// `bench-open`'s lines in the usage. -const USAGE_BENCH_OPEN: &str = " solidcraft-cli bench-open [--parse-only] [--save OUT.solidcraft] [--display LEVEL [--edit NAME EXPR]] [--ops script.json]\n (--ops: after opening, run each command of the script and undo it, timing the command, the\n evaluations it caused and the view it leaves: placing and meshing what changed)\n"; +const USAGE_BENCH_OPEN: &str = " solidcraft-cli bench-open [--parse-only] [--save OUT.solidcraft] [--display LEVEL [--edit NAME EXPR]] [--ops script.json] [--profile] [--profile-out trace.json]\n (--profile and --profile-out as for run)\n (--ops: after opening, run each command of the script and undo it, timing the command, the\n evaluations it caused and the view it leaves: placing and meshing what changed)\n"; /// `bench-agent`'s lines in the usage. const USAGE_BENCH_AGENT: &str = " solidcraft-cli bench-agent [--scale F] [--save design.solidcraft] [--script-out script.json]\n"; /// `bench-assistant`'s lines in the usage. @@ -136,6 +137,19 @@ const COMMANDS: &[Command] = &[ fn main() -> ExitCode { let mut args: Vec = std::env::args().skip(1).collect(); logger::init(&mut args); + // `--profile` / `--profile-out` (run, eval, bench-open) or SOLIDCRAFT_PROFILE (any command): + // record from here, and print the table when the command ends. + let profiling = match args.first().map(String::as_str) { + Some("run" | "eval" | "inspect" | "bench-open") => profiling::start(&args[1..]), + _ => profiling::start(&[]), + }; + let profiling = match profiling { + Ok(p) => p, + Err(e) => { + eprintln!("error: {e}"); + return ExitCode::FAILURE; + } + }; let r = match args.first().map(String::as_str) { // Asked-for help is not an error: the command's usage on stdout, exit 0. It is read // before the command runs, so `--help` never starts a run (a fuzz run, a server). @@ -202,6 +216,11 @@ fn main() -> ExitCode { } _ => Err(usage()), }; + // The table also when the command failed: where it spent its time before failing. + let r = match (r, profiling.map(profiling::Profiling::finish)) { + (Ok(()), Some(Err(e))) => Err(e), + (r, _) => r, + }; match r { Ok(()) => ExitCode::SUCCESS, Err(e) => { @@ -314,6 +333,16 @@ fn positional(args: &[String]) -> Option<&String> { None } +/// Is `path` a command script (or a recipe), not a design: JSON that is no saved design. +fn is_script(path: &str) -> bool { + let Ok(bytes) = solidcraft_engine::io::vfs::read(path, solidcraft_engine::io::MAX_DESIGN_BYTES) else { return false }; + if solidcraft_engine::io::is_design_container(&bytes) { + return false; + } + serde_json::from_slice::(&bytes) + .is_ok_and(|v| !v.get("format").and_then(Value::as_str).is_some_and(|f| solidcraft_engine::doc::format::version_of(f).is_some())) +} + /// `--json-out FILE`: where the JSON a command prints goes instead of stdout. fn json_out(args: &[String]) -> Result, String> { if !args.iter().any(|a| a == "--json-out") { @@ -345,15 +374,23 @@ fn print_json(v: &Value, file: Option<&str>) -> Result<(), String> { fn cmd_run(args: &[String]) -> Result<(), String> { install_renderer(); let json_out = json_out(args)?; - known_args("run", args, &["--in", "--out", "--save", "--json-out"], &["--quiet", "--results", "--timings", "--profile", "--allow-errors"], true)?; + known_args( + "run", + args, + &["--in", "--out", "--save", "--json-out", "--profile-out"], + &["--quiet", "--results", "--timings", "--profile", "--allow-errors"], + true, + )?; let base = flag(args, "--in"); let path = positional(args); if path.is_none() && base.is_none() { return Err(usage()); } let want_results = args.iter().any(|a| a == "--results"); - // `--profile` times each command and splits out its kernel time; it implies `--timings`. - let profile = args.iter().any(|a| a == "--profile"); + // `--profile` records the profiler's spans (the table goes to stderr, `profiling.rs`); for a + // script it also times each command and splits out its kernel time, implying `--timings`. + let script = path.is_some_and(|p| is_script(p)); + let profile = script && args.iter().any(|a| a == "--profile" || a == "--profile-out"); let timings = profile || args.iter().any(|a| a == "--timings"); let (mut s, results) = if want_results || timings { // Collect every command's result or time (scripts only), then process requested files too. @@ -450,7 +487,7 @@ fn timeline_ok(s: &Session) -> Result<(), String> { fn cmd_eval(args: &[String]) -> Result<(), String> { let json_out = json_out(args)?; - known_args("eval", args, &["--in", "--json-out"], &[], true)?; + known_args("eval", args, &["--in", "--json-out", "--profile-out"], &["--profile"], true)?; let mut s = open(flag(args, "--in"), positional(args))?; let m = s.execute("inspect.measure", &json!({})).map_err(|e| e.to_string())?; let d = s.execute("document.inspect", &json!({})).map_err(|e| e.to_string())?; diff --git a/apps/solidcraft-cli/src/profiling.rs b/apps/solidcraft-cli/src/profiling.rs new file mode 100644 index 0000000000..3d0b91245e --- /dev/null +++ b/apps/solidcraft-cli/src/profiling.rs @@ -0,0 +1,50 @@ +//! `--profile` and `--profile-out FILE` for `run`, `eval` and `bench-open` (and +//! `SOLIDCRAFT_PROFILE=1` for any command): record where the time goes, SMLib's calls to the +//! commands, print the table to stderr when the command ends (stdout stays the command's JSON) +//! and write the spans as a Chrome trace for chrome://tracing or Perfetto. + +use solidcraft_engine::profile; + +/// Rows the table prints. +const TOP: usize = 30; + +/// A recording that prints its table when finished. +pub struct Profiling { + trace: Option, +} + +/// Start recording when `args` (after the command) ask for it, or `SOLIDCRAFT_PROFILE` does. +pub fn start(args: &[String]) -> Result, String> { + let trace = match args.iter().position(|a| a == "--profile-out") { + Some(i) => match args.get(i + 1) { + Some(f) if !f.starts_with("--") => Some(f.clone()), + _ => return Err("--profile-out needs a FILE".into()), + }, + None => None, + }; + let asked = trace.is_some() || args.iter().any(|a| a == "--profile"); + if !asked && !solidcraft_engine::timing::profile_from_env() { + return Ok(None); + } + if !profile::COMPILED { + return Err("this solidcraft-cli was built without the profiler (its `profile` feature)".into()); + } + profile::reset(); + profile::set_enabled(true); + Ok(Some(Profiling { trace })) +} + +impl Profiling { + /// Stop recording, print the table on stderr and write the trace. + pub fn finish(self) -> Result<(), String> { + profile::set_enabled(false); + eprint!("{}", profile::report().table(TOP)); + if let Some(path) = self.trace { + let mut bytes = Vec::new(); + profile::write_chrome_trace(&mut bytes).map_err(|e| format!("{path}: {e}"))?; + std::fs::write(&path, bytes).map_err(|e| format!("{path}: {e}"))?; + eprintln!("profile: trace written to {path} (open it in chrome://tracing or ui.perfetto.dev)"); + } + Ok(()) + } +} diff --git a/apps/solidcraft-web/Cargo.toml b/apps/solidcraft-web/Cargo.toml index 26782cb0e4..8faba6f93e 100644 --- a/apps/solidcraft-web/Cargo.toml +++ b/apps/solidcraft-web/Cargo.toml @@ -14,12 +14,15 @@ name = "solidcraft-web" path = "src/main.rs" [features] -default = ["smlib"] +default = ["smlib", "profile"] bundled-render-library = ["solidcraft-engine/bundled-render-library"] # Link SMLib into the kernel (solidcraft-engine/smlib; needs scripts/fetch-smlib.sh # wasm32-unknown-unknown, or the sources and wasi-sdk in WASI_SDK_PATH, crates/smlib/build.rs). SMLib # is the only kernel, so without it the web app models nothing. smlib = ["solidcraft-engine/smlib"] +# The profiler, compiled in so any build can say where its time goes (the Profile operations +# preference, SOLIDCRAFT_PROFILE=1, diagnostics.profile); it records nothing until asked. +profile = ["solidcraft-engine/profile"] [dependencies] solidcraft-engine = { workspace = true } diff --git a/apps/solidcraft/Cargo.toml b/apps/solidcraft/Cargo.toml index 8ffa40e897..6b1bd96c90 100644 --- a/apps/solidcraft/Cargo.toml +++ b/apps/solidcraft/Cargo.toml @@ -8,12 +8,15 @@ publish = false default-run = "solidcraft" [features] -default = ["raytrace-cpu", "bundled-render-library", "smlib"] +default = ["raytrace-cpu", "bundled-render-library", "smlib", "profile"] bundled-render-library = ["solidcraft-engine/bundled-render-library"] raytrace-cpu = ["solidcraft-engine/raytrace-cpu"] # Link SMLib into the kernel (solidcraft-engine/smlib; needs scripts/fetch-smlib.sh). SMLib is the # only kernel, so without it the app models nothing. smlib = ["solidcraft-engine/smlib"] +# The profiler, compiled in so any build can say where its time goes (the Profile operations +# preference, SOLIDCRAFT_PROFILE=1, diagnostics.profile); it records nothing until asked. +profile = ["solidcraft-engine/profile"] # The workspace lints, except unsafe_code: denied, not forbidden, so that src/open_documents.rs # (macOS file-open events), src/native_crash.rs (Windows exception filter), src/native_crash_macos.rs diff --git a/crates/doc/Cargo.toml b/crates/doc/Cargo.toml index 8960e0be1c..8093414b36 100644 --- a/crates/doc/Cargo.toml +++ b/crates/doc/Cargo.toml @@ -12,6 +12,7 @@ workspace = true solidcraft-geom = { workspace = true } solidcraft-sketch = { workspace = true } solidcraft-kernel = { workspace = true } +solidcraft-profile = { workspace = true } solidcraft-render = { workspace = true } solidcraft-derive = { workspace = true } serde = { workspace = true } diff --git a/crates/doc/src/eval.rs b/crates/doc/src/eval.rs index b068e7ea22..29caa08e7a 100644 --- a/crates/doc/src/eval.rs +++ b/crates/doc/src/eval.rs @@ -1751,6 +1751,7 @@ impl Model { /// Re-evaluate the document, reusing results up to the first changed feature. pub fn evaluate(&mut self, doc: &Document) { + let _span = solidcraft_profile::span("doc", "evaluate"); let (vals, perr) = evaluation_values(doc); self.param_errors = perr; self.frame_bodies.lock().unwrap_or_else(|e| e.into_inner()).next_generation(); @@ -1877,6 +1878,8 @@ impl Model { continue; } recomputed += 1; + // Each feature computed is a profiler span named after its kind. + let _feature_span = solidcraft_profile::span("feature", f.kind.type_name()); let before = state.clone(); let t0 = now(); let mut next = (*state).clone(); diff --git a/crates/engine/Cargo.toml b/crates/engine/Cargo.toml index cb20407079..61c83fed46 100644 --- a/crates/engine/Cargo.toml +++ b/crates/engine/Cargo.toml @@ -19,6 +19,10 @@ smlib = ["solidcraft-kernel/smlib"] # `src/schema/record.rs`), for checking a new contract against the whole test suite. param-audit = [] solver-profiling = ["solidcraft-sketch/solver-profiling"] +# Compile the profiler in (solidcraft-profile/enabled): every app turns it on by default, so any +# build can be profiled; it records only once switched on (SOLIDCRAFT_PROFILE=1, the CLI's +# --profile, the app's preference, diagnostics.profile). +profile = ["solidcraft-profile/enabled"] [[example]] name = "sketch_analysis_bench" @@ -39,6 +43,7 @@ solidcraft-kernel = { workspace = true } solidcraft-doc = { workspace = true } solidcraft-io = { workspace = true } solidcraft-render = { workspace = true } +solidcraft-profile = { workspace = true } image = { workspace = true, features = ["jpeg"] } serde = { workspace = true } serde_json = { workspace = true } @@ -50,6 +55,7 @@ log = { workspace = true } web-time = { workspace = true } [dev-dependencies] +solidcraft-profile = { workspace = true, features = ["enabled"] } # Model-cache tests also run in a source tarball build (no git commit). solidcraft-io = { workspace = true, features = ["trust-unknown-source"] } # Normal CI exercises profiling assertions without enabling the production feature. diff --git a/crates/engine/src/cmd/diagnostics.rs b/crates/engine/src/cmd/diagnostics.rs index 25a4756dcc..a918dace80 100644 --- a/crates/engine/src/cmd/diagnostics.rs +++ b/crates/engine/src/cmd/diagnostics.rs @@ -1,5 +1,6 @@ //! Crash reports, for agents and people (see `crate::crash` and docs/crash-reports.md): list -//! them, read one, delete them. They live on this computer and are never sent anywhere. +//! them, read one, delete them. They live on this computer and are never sent anywhere. And the +//! profiler (`solidcraft_profile`, docs/perf.md): where the time goes, SMLib's calls to commands. use serde_json::{Value, json}; @@ -22,6 +23,21 @@ pub static COMMANDS: &[CommandSpec] = &[ .icon("delete") .noundo() .params("id?: one report (default: all). Returns {deleted}"), + CommandSpec::new("diagnostics.profile", "Profile", crate::checked!("diagnostics.profile", profile)) + .icon("bug_report") + .noundo() + .contract(&PROFILE_CONTRACT) + .output(crate::schema::output_schema_for::) + .params( + "enabled?: bool (start or stop recording); reset?: bool (forget what was recorded); top?: rows (default 20, 0: all); \ + trace?: path (write the recorded spans as a Chrome trace-event file, for chrome://tracing or Perfetto). Returns what \ + was recorded before enabled and reset apply: {compiled, enabled, wall_ms, spans, dropped, by_category: [{category, \ + self_ms, share}], rows: [{category, name, count, total_ms, self_ms, max_ms}], rows_total, trace?}, the rows the most \ + self time first. Categories: smlib (SMLib's C API calls, timed by the C API), kernel, feature (one per feature \ + computed, by its type), doc, command, import (STEP/IGES stages), io. Self time is a span's time less the spans \ + inside it; total counts its outermost run only. Recording also starts with SOLIDCRAFT_PROFILE=1, the CLI's \ + --profile and the app's preference; off, it costs nothing measurable. Read-only", + ), CommandSpec::new("diagnostics.crash_test", "Crash Test", crash_test).icon("bug_report").noundo().enabled(crash_test_enabled).params( "mode: panic | kernel | abort. Checks that crash reports work: panic = an internal error in this command (caught; \ the design is unchanged), kernel = one inside the geometry kernel (caught), abort = the app ends at once (reported \ @@ -73,3 +89,42 @@ fn crash_test(_: &mut Session, p: &Value) -> Result { _ => Err(bad(cmd, "`mode` must be panic, kernel or abort")), } } + +const PROFILE_CONTRACT: crate::schema::TypedContract = crate::schema::TypedContract::new(); + +/// Rows `diagnostics.profile` returns at most. +const MAX_PROFILE_ROWS: u64 = 10_000; + +fn profile(_: &mut Session, p: &Value) -> Result { + let cmd = "diagnostics.profile"; + let flag = |key: &str| match p.get(key) { + None | Some(Value::Null) => Ok(None), + Some(Value::Bool(b)) => Ok(Some(*b)), + Some(_) => Err(bad(cmd, format!("`{key}` must be true or false"))), + }; + let (enabled, reset) = (flag("enabled")?, flag("reset")?); + let top = match p.get("top") { + None | Some(Value::Null) => 20, + Some(v) => v.as_u64().ok_or_else(|| bad(cmd, "`top` must be a whole number of rows (0: all)"))?.min(MAX_PROFILE_ROWS) as usize, + }; + let trace = match p.get("trace") { + None | Some(Value::Null) => None, + Some(_) => Some(str_(p, "trace").filter(|t| !t.trim().is_empty() && t.len() < 4096).ok_or_else(|| bad(cmd, "`trace` must be a file path"))?), + }; + let report = solidcraft_profile::report(); + let mut out = crate::schema::diagnostics::ProfileReport::new(&report, top); + if let Some(path) = trace { + let mut bytes = Vec::new(); + solidcraft_profile::write_chrome_trace(&mut bytes).map_err(|e| bad(cmd, format!("trace: {e}")))?; + solidcraft_io::vfs::write(path, &bytes).map_err(|e| EngineError::Other(format!("{path}: {e}")))?; + out.trace = Some(path.to_string()); + } + if reset == Some(true) { + solidcraft_profile::reset(); + } + if let Some(on) = enabled { + solidcraft_profile::set_enabled(on); + out.enabled = solidcraft_profile::enabled(); + } + serde_json::to_value(out).map_err(|e| EngineError::Other(format!("{cmd}: {e}"))) +} diff --git a/crates/engine/src/cmd/file.rs b/crates/engine/src/cmd/file.rs index cefc4e7b56..1b7de0a78e 100644 --- a/crates/engine/src/cmd/file.rs +++ b/crates/engine/src/cmd/file.rs @@ -141,7 +141,12 @@ fn quarter_turn_x() -> solidcraft_doc::Mat { /// Add an Import feature for a STEP file to the session's design, in a new component named /// after the file (#1386). +/// +/// While the profiler records, the reply's `profile` is the import's share of it (reading, +/// building the solids in SMLib, placing, meshing and evaluating them), as +/// `diagnostics.profile` reports it. fn add_step(s: &mut Session, path: &str, name: Option<&str>, options: &StepOptions) -> Result { + let profiled = solidcraft_profile::enabled().then(solidcraft_profile::mark); let sf = read_step(path, options.names)?; let fname = name.filter(|n| !n.trim().is_empty()).unwrap_or(&sf.name).to_string(); let cname = import::component_name(path, name); @@ -160,6 +165,10 @@ fn add_step(s: &mut Session, path: &str, name: Option<&str>, options: &StepOptio if let Some(turned) = turned { out["stand_up"] = json!(turned); } + if let Some(mark) = profiled { + let report = crate::schema::diagnostics::ProfileReport::new(&mark.report(), 20); + out["profile"] = serde_json::to_value(report).map_err(|e| EngineError::Other(format!("{path}: {e}")))?; + } Ok(out) } @@ -835,6 +844,32 @@ mod urdf_tests; mod tests { use super::*; + /// While the profiler records, a STEP import's reply carries its own profile: the import's + /// stages and SMLib's calls, as diagnostics.profile reports them. + #[cfg(feature = "smlib")] + #[test] + fn a_step_import_reports_its_profile_while_the_profiler_records() { + let _serial = crate::schema::diagnostics::PROFILE_TESTS.lock().unwrap_or_else(std::sync::PoisonError::into_inner); + let dir = std::env::temp_dir().join(format!("solidcraft-import-profile-{}", std::process::id())); + std::fs::create_dir_all(&dir).unwrap(); + let path = dir.join("block.step").to_string_lossy().to_string(); + let mut s = Session::default(); + s.execute("solid.box", &json!({"length": 20, "width": 10, "height": 5})).unwrap(); + s.execute("file.export", &json!({"path": path})).unwrap(); + // The first read of the file (a second one finds it in the import cache). + solidcraft_profile::set_enabled(true); + let out = Session::default().execute("file.insert_step", &json!({"path": path})).unwrap(); + solidcraft_profile::set_enabled(false); + let plain = Session::default().execute("file.insert_step", &json!({"path": path})).unwrap(); + assert!(plain.get("profile").is_none(), "nothing recorded, nothing reported: {plain}"); + let p = &out["profile"]; + let rows = p["rows"].as_array().unwrap(); + let has = |cat: &str| rows.iter().any(|r| r["category"] == cat); + assert!(has("import") && has("smlib"), "{p}"); + assert!(p["by_category"].as_array().is_some_and(|c| !c.is_empty()) && p["wall_ms"].as_f64().is_some_and(|w| w > 0.0), "{p}"); + let _ = std::fs::remove_dir_all(&dir); + } + /// #4747: a mesh export's `quality` follows curved faces more closely. A 3 mm hole in a /// 200 mm plate gets more triangles at fine and more again at finest, in STL and 3MF alike /// (Save As Mesh too); standard is what the export always gave; anything else is refused. diff --git a/crates/engine/src/lib.rs b/crates/engine/src/lib.rs index 260cbacb17..752d861a64 100644 --- a/crates/engine/src/lib.rs +++ b/crates/engine/src/lib.rs @@ -48,6 +48,7 @@ pub use solidcraft_doc::Visibility; pub use solidcraft_geom as geom; pub use solidcraft_io as io; pub use solidcraft_kernel as kernel; +pub use solidcraft_profile as profile; pub use solidcraft_render as render; pub use solidcraft_sketch as sketch; @@ -1118,6 +1119,8 @@ impl Session { /// the model up to date before anything reads it. pub fn execute(&mut self, id: &str, params: &Value) -> Result { let spec = find_command(id).ok_or_else(|| EngineError::UnknownCommand(id.to_string()))?; + // The command, the evaluation it causes and the refresh after it: one profiler span. + let _span = solidcraft_profile::span("command", spec.id); let host_viewport = self.render_viewport.clone(); let host_jobs = self.render_jobs.host.clone(); let additional_jobs = self.render_jobs.additional.clone(); diff --git a/crates/engine/src/schema/diagnostics.rs b/crates/engine/src/schema/diagnostics.rs new file mode 100644 index 0000000000..dd7cb1bb04 --- /dev/null +++ b/crates/engine/src/schema/diagnostics.rs @@ -0,0 +1,151 @@ +//! Contracts and result types for the commands in `cmd/diagnostics.rs`. + +use schemars::JsonSchema; +use serde::{Deserialize, Serialize}; +use serde_json::Value; + +/// `true`, `false` or null, with the handler's message for anything else. +fn flag<'de, D: serde::Deserializer<'de>>(d: D) -> Result, D::Error> { + match Value::deserialize(d)? { + Value::Null => Ok(None), + Value::Bool(b) => Ok(Some(b)), + _ => Err(serde::de::Error::custom("must be true or false")), + } +} + +/// A row count, with the handler's message for anything else. +fn rows<'de, D: serde::Deserializer<'de>>(d: D) -> Result, D::Error> { + match Value::deserialize(d)? { + Value::Null => Ok(None), + v => v.as_u64().map(Some).ok_or_else(|| serde::de::Error::custom("must be a whole number of rows (0: all)")), + } +} + +/// A file path, with the handler's message for anything else. +fn path<'de, D: serde::Deserializer<'de>>(d: D) -> Result, D::Error> { + match Value::deserialize(d)? { + Value::Null => Ok(None), + Value::String(s) if !s.trim().is_empty() && s.len() < 4096 => Ok(Some(s)), + _ => Err(serde::de::Error::custom("must be a file path")), + } +} + +/// What `diagnostics.profile` should do besides reporting. +#[derive(Debug, Default, Deserialize, JsonSchema)] +#[schemars(deny_unknown_fields)] +pub struct ProfileParams { + /// Start (`true`) or stop (`false`) recording, after the report is taken. + #[serde(default, deserialize_with = "flag")] + pub enabled: Option, + /// Forget what was recorded, after the report is taken. + #[serde(default, deserialize_with = "flag")] + pub reset: Option, + /// How many rows to return, the most self time first (default 20; 0: all of them). + #[serde(default, deserialize_with = "rows")] + pub top: Option, + /// Write the recorded spans here as a Chrome trace-event file (chrome://tracing, Perfetto). + #[serde(default, deserialize_with = "path")] + pub trace: Option, +} + +/// One category's share of the recorded self time. +#[derive(Debug, Serialize, JsonSchema)] +pub struct ProfileCategory { + /// `smlib` (SMLib's own time, measured by its C API), `kernel`, `feature`, `doc`, `command`, + /// `import`, `io`. + pub category: String, + pub self_ms: f64, + /// Of all recorded self time, 0–1. + pub share: f64, +} + +/// One span name's aggregate. +#[derive(Debug, Serialize, JsonSchema)] +pub struct ProfileRow { + pub category: String, + pub name: String, + pub count: u64, + /// Its time, counting only its outermost occurrence on each thread's stack. + pub total_ms: f64, + /// Its time less the time of the spans inside it. + pub self_ms: f64, + /// Its longest single run. + pub max_ms: f64, +} + +/// What the profiler recorded: the reply of `diagnostics.profile`, and an import's `profile`. +#[derive(Debug, Serialize, JsonSchema)] +pub struct ProfileReport { + /// The profiler is compiled into this build (the apps' `profile` feature). + pub compiled: bool, + /// It is recording (after this call's `enabled`). + pub enabled: bool, + /// Wall time the report covers. + pub wall_ms: f64, + /// Spans recorded. + pub spans: u64, + /// Spans left out of the trace (past its cap); they are in the rows. + pub dropped: u64, + /// Self time per category, the most first. + pub by_category: Vec, + /// The span names with the most self time, the most first. + pub rows: Vec, + /// Span names recorded (rows lists `top` of them). + pub rows_total: usize, + /// Where the Chrome trace was written, when `trace` asked for one. + #[serde(default, skip_serializing_if = "Option::is_none")] + pub trace: Option, +} + +fn ms(d: std::time::Duration) -> f64 { + (d.as_secs_f64() * 1e6).round() / 1e3 +} + +impl ProfileReport { + /// `report` with its `top` rows of most self time (0: all of them). + pub fn new(report: &solidcraft_profile::Report, top: usize) -> ProfileReport { + let sorted = report.sorted(); + let all: f64 = report.rows.iter().map(|r| r.self_time.as_secs_f64()).sum(); + let by_category = report + .by_category() + .into_iter() + .map(|(c, d)| ProfileCategory { + category: c.to_string(), + self_ms: ms(d), + share: if all > 0.0 { (d.as_secs_f64() / all * 1000.0).round() / 1000.0 } else { 0.0 }, + }) + .collect(); + let n = if top == 0 { sorted.len() } else { top.min(sorted.len()) }; + let rows = sorted + .iter() + .take(n) + .map(|r| ProfileRow { + category: r.category.to_string(), + name: r.name.to_string(), + count: r.count, + total_ms: ms(r.total), + self_ms: ms(r.self_time), + max_ms: ms(r.max), + }) + .collect(); + ProfileReport { + compiled: report.compiled, + enabled: report.enabled, + wall_ms: ms(report.wall), + spans: (report.events as u64).saturating_add(report.dropped), + dropped: report.dropped, + by_category, + rows, + rows_total: sorted.len(), + trace: None, + } + } +} + +/// Tests that switch the process-wide profiler on, off or reset it run one at a time. +#[cfg(test)] +pub(crate) static PROFILE_TESTS: std::sync::Mutex<()> = std::sync::Mutex::new(()); + +#[cfg(test)] +#[path = "diagnostics_tests.rs"] +mod tests; diff --git a/crates/engine/src/schema/diagnostics_tests.rs b/crates/engine/src/schema/diagnostics_tests.rs new file mode 100644 index 0000000000..df0f343bc5 --- /dev/null +++ b/crates/engine/src/schema/diagnostics_tests.rs @@ -0,0 +1,57 @@ +use serde_json::json; + +use super::ProfileParams; +use crate::Session; +use crate::schema::input_schema_for; +use crate::schema::tests::{assert_keys, assert_strict_keeps_todays_errors}; + +#[test] +fn schemas_and_the_key_check_agree() { + assert_keys(input_schema_for::(), &["enabled", "reset", "top", "trace"]); +} + +#[test] +fn strict_keeps_todays_errors() { + assert_strict_keeps_todays_errors(&[ + ("diagnostics.profile", json!({"enabled": "yes"})), + ("diagnostics.profile", json!({"reset": 1})), + ("diagnostics.profile", json!({"top": -1})), + ("diagnostics.profile", json!({"top": 2.5})), + ("diagnostics.profile", json!({"trace": 5})), + ]); +} + +/// The profiler records commands, the features they compute and the kernel below them, and +/// reports, resets and writes a Chrome trace through the command. +#[test] +fn diagnostics_profile_reports_commands_features_and_the_kernel() { + let _serial = super::PROFILE_TESTS.lock().unwrap_or_else(std::sync::PoisonError::into_inner); + let mut s = Session::default(); + s.execute("diagnostics.profile", &json!({"reset": true, "enabled": true})).unwrap(); + s.execute("solid.box", &json!({"length": 10, "width": 10, "height": 10})).unwrap(); + let r = s.execute("diagnostics.profile", &json!({"top": 0})).unwrap(); + assert_eq!((r["compiled"].as_bool(), r["enabled"].as_bool()), (Some(true), Some(true)), "{r}"); + let rows = r["rows"].as_array().unwrap(); + let row = |cat: &str, name: &str| rows.iter().find(|x| x["category"] == cat && x["name"] == name); + let cmd = row("command", "solid.box").unwrap_or_else(|| panic!("{r}")); + assert!(row("feature", "BoxFeature").is_some() && row("doc", "evaluate").is_some(), "{r}"); + assert!(row("kernel", "box_solid").is_some(), "{r}"); + assert!(cmd["self_ms"].as_f64().unwrap() <= cmd["total_ms"].as_f64().unwrap(), "{r}"); + assert_eq!(r["rows_total"].as_u64(), Some(rows.len() as u64)); + // `top` keeps the rows with the most self time. + let one = s.execute("diagnostics.profile", &json!({"top": 1})).unwrap(); + assert_eq!(one["rows"].as_array().map(Vec::len), Some(1)); + // A trace file, then stop and forget. + let dir = std::env::temp_dir().join(format!("solidcraft-profile-trace-{}", std::process::id())); + std::fs::create_dir_all(&dir).unwrap(); + let path = dir.join("trace.json").to_string_lossy().to_string(); + let t = s.execute("diagnostics.profile", &json!({"trace": path, "enabled": false, "reset": true})).unwrap(); + assert_eq!((t["trace"].as_str(), t["enabled"].as_bool()), (Some(path.as_str()), Some(false))); + let trace: serde_json::Value = serde_json::from_slice(&std::fs::read(&path).unwrap()).unwrap(); + assert!(trace["traceEvents"].as_array().unwrap().iter().any(|e| e["ph"] == "X" && e["name"] == "solid.box"), "{trace}"); + // Only the call that reset it (its own span ends after the reset). + let after = s.execute("diagnostics.profile", &json!({})).unwrap(); + let names: Vec<&str> = after["rows"].as_array().unwrap().iter().filter_map(|r| r["name"].as_str()).collect(); + assert_eq!(names, ["diagnostics.profile"], "{after}"); + let _ = std::fs::remove_dir_all(&dir); +} diff --git a/crates/engine/src/schema/mod.rs b/crates/engine/src/schema/mod.rs index f742836440..1ca4710f66 100644 --- a/crates/engine/src/schema/mod.rs +++ b/crates/engine/src/schema/mod.rs @@ -54,6 +54,7 @@ mod coverage_tests; mod tests; // The contracts, by command file. +pub mod diagnostics; pub mod features; pub mod inspect; diff --git a/crates/engine/src/timing.rs b/crates/engine/src/timing.rs index a3dede46f1..d05772a205 100644 --- a/crates/engine/src/timing.rs +++ b/crates/engine/src/timing.rs @@ -40,6 +40,20 @@ pub fn time(profile: bool, f: impl FnOnce() -> T) -> (T, Step) { } } +/// `SOLIDCRAFT_PROFILE` asks for the profiler from the start: `1`, `true`, `on` or `yes`. +pub fn profile_env_on(value: Option<&str>) -> bool { + value.map(|v| v.trim().to_ascii_lowercase()).is_some_and(|v| matches!(v.as_str(), "1" | "true" | "on" | "yes")) +} + +/// Start the profiler when `SOLIDCRAFT_PROFILE` asks for it (the apps call this at start-up); +/// true when it is recording. +pub fn profile_from_env() -> bool { + if profile_env_on(solidcraft_geom::env::var("PROFILE").as_deref()) { + solidcraft_profile::set_enabled(true); + } + solidcraft_profile::enabled() +} + /// Milliseconds to the microsecond, so the JSON stays readable. pub fn round_ms(ms: f64) -> f64 { if ms.is_finite() { (ms * 1000.0).round() / 1000.0 } else { 0.0 } @@ -64,6 +78,16 @@ impl Step { mod tests { use super::*; + #[test] + fn the_profile_variable_takes_the_usual_yes_words() { + for v in ["1", "true", " ON ", "yes"] { + assert!(profile_env_on(Some(v)), "{v}"); + } + for v in [None, Some(""), Some("0"), Some("off"), Some("2")] { + assert!(!profile_env_on(v), "{v:?}"); + } + } + #[test] fn steps_report_their_time_and_profile_only_when_asked() { let (r, step) = time(false, || 7); diff --git a/crates/io/Cargo.toml b/crates/io/Cargo.toml index e9a701fe1a..5789666c63 100644 --- a/crates/io/Cargo.toml +++ b/crates/io/Cargo.toml @@ -16,6 +16,7 @@ trust-unknown-source = [] solidcraft-geom = { workspace = true } solidcraft-kernel = { workspace = true } solidcraft-doc = { workspace = true } +solidcraft-profile = { workspace = true } thiserror = { workspace = true } log = { workspace = true } zip = { workspace = true } diff --git a/crates/io/src/design.rs b/crates/io/src/design.rs index a05d7e7f04..e6538d1d93 100644 --- a/crates/io/src/design.rs +++ b/crates/io/src/design.rs @@ -231,6 +231,7 @@ pub fn write_design_container_with_thumbnail( geometry: Option<&solidcraft_doc::SavedModel>, thumbnail: Option<&[u8]>, ) -> Result> { + let _span = solidcraft_profile::span("io", "write_design_container_with_thumbnail"); write_container(doc, compression, preview, geometry, thumbnail, MAX_DESIGN_BYTES) } @@ -654,6 +655,7 @@ pub(super) fn read(bytes: &[u8]) -> Result { /// keeps one seekable file handle instead of buffering the complete archive. JSON continues /// through the normal migrations. pub fn read_design_file(path: &str, notify: Option) -> Result<(Document, Option)> { + let _span = solidcraft_profile::span("io", "read_design_file"); #[cfg(not(target_arch = "wasm32"))] let mut source = { crate::vfs::check(path).map_err(invalid)?; diff --git a/crates/io/src/lib.rs b/crates/io/src/lib.rs index f4fafebaed..245f197a5e 100644 --- a/crates/io/src/lib.rs +++ b/crates/io/src/lib.rs @@ -207,6 +207,7 @@ pub fn step_import_feature(bytes: &[u8], file: &str) -> Result { /// [`step_import_feature`], with the bodies named after `names`. pub fn step_import_feature_named(bytes: &[u8], file: &str, names: StepNames) -> Result { + let _span = solidcraft_profile::span("import", "step_import_feature_named"); if bytes.len() > MAX_STEP_BYTES { return Err(IoError::Invalid(format!("STEP file too large ({} MB, limit {} MB)", bytes.len() >> 20, MAX_STEP_BYTES >> 20))); } @@ -264,6 +265,7 @@ pub struct MeshFeature { /// feature. A glTF file's bodies are all built where they are (see [`read_gltf`] for its node /// tree), and it can't read buffers in other files. pub fn mesh_import_feature(bytes: &[u8], file: &str) -> Result { + let _span = solidcraft_profile::span("import", "mesh_import_feature"); if is_gltf_path(file) { let mut no_files = |name: &str| Err(format!("`{name}` can't be read here")); let mut g = read_gltf(bytes, file, &mut no_files)?; @@ -541,6 +543,7 @@ pub fn export_with_quality( meta: &Metadata, quality: MeshQuality, ) -> Result> { + let _span = solidcraft_profile::span("io", "export_with_quality"); let sel: Vec<&solidcraft_doc::ModelBody> = state.bodies.iter().filter(|b| bodies.is_empty() || bodies.contains(&b.name)).collect(); if sel.is_empty() { return Err(IoError::Empty); @@ -620,6 +623,7 @@ fn mesh_object(b: &solidcraft_doc::ModelBody, tagged: bool, quality: MeshQuality /// part, built where the file placed it) is taken into its component's frame by that offset, /// as the world placement does, so the occurrences above it place it only once. pub fn step_assembly(doc: &Document, local: &ModelState, name: &str) -> Result> { + let _span = solidcraft_profile::span("io", "step_assembly"); use solidcraft_kernel::{ExportBody, ExportProduct}; let mut index: std::collections::HashMap = std::collections::HashMap::new(); index.insert(0, 0); @@ -652,6 +656,7 @@ pub fn step_assembly(doc: &Document, local: &ModelState, name: &str) -> Result Result { + let _span = solidcraft_profile::span("io", "read_design"); if bytes.len() > MAX_DESIGN_BYTES { return Err(IoError::Invalid("design file too large".into())); } diff --git a/crates/profile/src/lib.rs b/crates/profile/src/lib.rs index caff753f3b..6fae490090 100644 --- a/crates/profile/src/lib.rs +++ b/crates/profile/src/lib.rs @@ -21,8 +21,6 @@ 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)); @@ -124,40 +122,6 @@ impl Report { } } - /// 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 _; diff --git a/crates/profile/src/tests.rs b/crates/profile/src/tests.rs index a3da6ae4c4..85b3b95c9f 100644 --- a/crates/profile/src/tests.rs +++ b/crates/profile/src/tests.rs @@ -90,9 +90,6 @@ fn a_mark_reports_only_what_came_after_it() { 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] @@ -106,7 +103,7 @@ fn spans_on_other_threads_get_their_own_track() { set_enabled(false); let mut out = Vec::new(); write_chrome_trace(&mut out).unwrap(); - let v: Value = serde_json::from_slice(&out).unwrap(); + let v: serde_json::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")); diff --git a/crates/smlib/src/tests.rs b/crates/smlib/src/tests.rs index be3b386229..84f4064619 100644 --- a/crates/smlib/src/tests.rs +++ b/crates/smlib/src/tests.rs @@ -74,8 +74,7 @@ fn call_lines_give_the_function_and_the_c_api_time() { let (name, took) = call_time("smlib_boolean(op=1, a=#3 (12 faces), b=#4) -> 0 (12.345 ms)").unwrap(); assert_eq!((name, took), ("smlib_boolean", std::time::Duration::from_micros(12_345))); assert_eq!(call_time("smlib_make_box(origin=(0,0,0)) -> -1002 (0.001 ms)").map(|c| c.0), Some("smlib_make_box")); - for bad in ["SMLib warning at x.cpp:12: tolerance (in smlib_boolean(...))", "smlib_x() -> 0 (nan ms)", "smlib_x() -> 0 (-1 ms)", "", "smlib_x"] - { + for bad in ["SMLib warning at x.cpp:12: tolerance (in smlib_boolean(...))", "smlib_x() -> 0 (nan ms)", "smlib_x() -> 0 (-1 ms)", "", "smlib_x"] { assert_eq!(call_time(bad), None, "{bad}"); } } diff --git a/crates/step/Cargo.toml b/crates/step/Cargo.toml index 72e4f7afc6..80edcb5da1 100644 --- a/crates/step/Cargo.toml +++ b/crates/step/Cargo.toml @@ -10,3 +10,4 @@ workspace = true [dependencies] solidcraft-geom = { workspace = true } +solidcraft-profile = { workspace = true } diff --git a/crates/step/src/topology.rs b/crates/step/src/topology.rs index cfbec97fb0..fa01134f13 100644 --- a/crates/step/src/topology.rs +++ b/crates/step/src/topology.rs @@ -305,6 +305,8 @@ fn read_with<'a>( let p = e.params(); let name = p.first().and_then(Param::as_str).unwrap_or("").to_string(); let mut b = Builder::new(ex, reader, tolerance(&context), budget, trims); + // The file's faces, edges, vertices and their geometry read into the builder. + let topology = solidcraft_profile::span("import", "step.topology"); let (shells, kind) = match e.name() { "MANIFOLD_SOLID_BREP" => (vec![b.shell(rid(p.get(1), "outer shell")?)?], Kind::Solid), "BREP_WITH_VOIDS" => { @@ -331,6 +333,7 @@ fn read_with<'a>( } n => return Err(unsupported(n)), }; + drop(topology); b.finish(item, name, shells, kind) } @@ -689,6 +692,7 @@ impl<'b, 'a> Builder<'b, 'a> { /// Pcurves, outer loops, domains and the canonical order: the finished record. fn finish(mut self, item: u64, name: String, shells: Vec>, kind: Kind) -> R { + let _span = solidcraft_profile::span("import", "step.solid_record"); let mut notes = Vec::new(); let seams = self.add_seams()?; if seams > 0 { @@ -980,6 +984,7 @@ impl<'b, 'a> Builder<'b, 'a> { /// outer loop runs clockwise about the natural normal on a surface where that cannot be a /// face's outer boundary. fn face_pcurves(&mut self, fi: usize) -> R<(Vec>, [[f64; 2]; 2], bool, Option)> { + let _span = solidcraft_profile::span("import", "step.face_pcurves"); let face = self.faces.get(fi).ok_or("face reference")?; let label = face.surface.clone(); let edge_loops: Vec> = face @@ -1107,6 +1112,7 @@ impl Builder<'_, '_> { edge_loops: &[Vec<(u32, bool)>], exact: Vec>>, ) -> R> { + let _span = solidcraft_profile::span("import", "step.trim_face"); let (mut edge_at, mut vertex_at) = (HashMap::new(), HashMap::new()); let (mut edges, mut vertices) = (Vec::new(), Vec::new()); let mut loops = Vec::with_capacity(edge_loops.len());