From b04e0801d6aeb9101555fa06757fb82fbe915f4d Mon Sep 17 00:00:00 2001 From: DuBearte <130190089+DuBearte@users.noreply.github.com> Date: Sat, 17 Oct 2026 07:26:20 -0400 Subject: [PATCH] Per-command timings for script runs and batches (#1868) Thanks @DuBearte. --- Cargo.lock | 1 + apps/solidcraft-cli/src/main.rs | 35 ++++-- apps/solidcraft-cli/tests/run_results.rs | 30 +++++ crates/engine/src/lib.rs | 29 ++++- crates/engine/src/timing.rs | 111 ++++++++++++++++++ crates/kernel/Cargo.toml | 1 + crates/kernel/src/body.rs | 20 ++++ crates/kernel/src/lib.rs | 1 + crates/kernel/src/ops.rs | 12 ++ crates/kernel/src/profile.rs | 136 +++++++++++++++++++++++ crates/mcp/src/backend.rs | 8 ++ crates/mcp/src/tests.rs | 41 +++++++ crates/mcp/src/tools.rs | 71 ++++++++---- crates/ui-egui/src/control.rs | 52 ++++++++- docs/book/src/guide/getting-started.md | 11 ++ docs/control-protocol.md | 2 +- docs/mcp.md | 2 +- 17 files changed, 526 insertions(+), 37 deletions(-) create mode 100644 crates/engine/src/timing.rs create mode 100644 crates/kernel/src/profile.rs diff --git a/Cargo.lock b/Cargo.lock index 56e97abc..3a74eaf0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4202,6 +4202,7 @@ dependencies = [ "truck-shapeops", "truck-stepio", "truck-topology", + "web-time", ] [[package]] diff --git a/apps/solidcraft-cli/src/main.rs b/apps/solidcraft-cli/src/main.rs index b078297a..8aca7563 100644 --- a/apps/solidcraft-cli/src/main.rs +++ b/apps/solidcraft-cli/src/main.rs @@ -1,7 +1,7 @@ //! SolidCraft headless command line. //! //! ```text -//! solidcraft-cli run [--in design|part.step|mesh.3mf] [--out FILE]... [--save FILE] [--quiet] [--results] [--json-out FILE] [--allow-errors] +//! solidcraft-cli run [--in design|part.step|mesh.3mf] [--out FILE]... [--save FILE] [--quiet] [--results] [--timings] [--profile] [--json-out FILE] [--allow-errors] //! solidcraft-cli eval [--json-out FILE] (alias: inspect) measurements as JSON //! solidcraft-cli script [--out script.json] the design's history as a command script //! solidcraft-cli bench-open [--parse-only] [--display LEVEL [--edit NAME EXPR]] loading timings as JSON lines @@ -37,9 +37,11 @@ use solidcraft_engine::Session; use solidcraft_engine::view::Guides; const USAGE: &str = "usage: - solidcraft-cli run [--in design.solidcraft|part.step] [--out FILE]... [--save FILE] [--quiet] [--results] [--json-out FILE] [--allow-errors] + solidcraft-cli run [--in design.solidcraft|part.step] [--out FILE]... [--save FILE] [--quiet] [--results] [--timings] [--profile] [--json-out FILE] [--allow-errors] solidcraft-cli run --in [--out FILE]... (a timeline feature that fails fails the run and nothing is written; --allow-errors writes anyway) + (--timings prints {timings: [{index, command, ms}], total_ms} for a script, with --results its results too; + --profile adds each command's profile: {boolean_ms, tessellate_ms, other_ms}, the kernel's share) solidcraft-cli eval [--json-out FILE] (alias: inspect; or --in FILE) (--json-out FILE writes the JSON that run (with --results, else the measurement) and eval print to FILE instead of stdout, as plain UTF-8: a shell's > can re-encode it, e.g. Windows PowerShell adds a byte-order mark) @@ -180,7 +182,11 @@ fn positional(args: &[String]) -> Option<&String> { let mut i = 0; while let Some(a) = args.get(i) { if a.starts_with("--") { - i += if matches!(a.as_str(), "--quiet" | "--results" | "--allow-errors" | "--no-grid" | "--no-axes") { 1 } else { 2 }; + i += if matches!(a.as_str(), "--quiet" | "--results" | "--timings" | "--profile" | "--allow-errors" | "--no-grid" | "--no-axes") { + 1 + } else { + 2 + }; continue; } return Some(a); @@ -224,15 +230,28 @@ fn cmd_run(args: &[String]) -> Result<(), String> { if path.is_none() && base.is_none() { return Err(USAGE.to_string()); } - let (mut s, results) = if args.iter().any(|a| a == "--results") { - // Collect every command's result (scripts only), then process requested files too. + 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"); + 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. let mut s = match base { Some(b) => load(b)?, None => Session::default(), }; - let v = read_json(path.ok_or("--results needs a script")?)?; - let r = s.run_script(&v).map_err(|e| e.to_string())?; - (s, Some(Value::Array(r))) + let needs = if want_results { "--results needs a script" } else { "--timings needs a script" }; + let v = read_json(path.ok_or(needs)?)?; + let out = if timings { + let (r, mut t) = s.run_script_timed(&v, profile).map_err(|e| e.to_string())?; + if want_results && let Some(o) = t.as_object_mut() { + o.insert("results".into(), Value::Array(r)); + } + t + } else { + Value::Array(s.run_script(&v).map_err(|e| e.to_string())?) + }; + (s, Some(out)) } else { (open(base, path)?, None) }; diff --git a/apps/solidcraft-cli/tests/run_results.rs b/apps/solidcraft-cli/tests/run_results.rs index 1da815e9..c5709904 100644 --- a/apps/solidcraft-cli/tests/run_results.rs +++ b/apps/solidcraft-cli/tests/run_results.rs @@ -179,3 +179,33 @@ fn unknown_command_suggests_the_closest_id() { assert_eq!(output.status.code(), Some(1)); assert!(String::from_utf8_lossy(&output.stderr).contains("did you mean `doc.open`?"), "{}", String::from_utf8_lossy(&output.stderr)); } + +/// #1833: `--timings` reports each command's time instead of the measurement, `--profile` adds +/// the kernel's share, `--results` puts the results beside them, and files are still written. +#[test] +fn timings_and_profile_report_each_command() { + let dir = Scratch::new(); + let saved = dir.0.join("timed.solidcraft"); + let t = json_output(cli().arg("run").arg(dir.script()).arg("--timings").arg("--save").arg(&saved).output().unwrap()); + let rows = t["timings"].as_array().unwrap(); + assert_eq!(rows.len(), 1); + assert_eq!((rows[0]["index"].as_u64(), rows[0]["command"].as_str()), (Some(0), Some("solid.box"))); + assert!(rows[0]["ms"].as_f64().is_some() && t["total_ms"].as_f64().is_some(), "{t}"); + assert!(rows[0].get("profile").is_none() && t.get("results").is_none(), "{t}"); + assert_eq!(body_count(&saved), 1); + + // --profile alone implies --timings; a flag before the script doesn't eat it. + let t = json_output(cli().arg("run").arg("--profile").arg(dir.script()).arg("--results").output().unwrap()); + let p = &t["timings"][0]["profile"]; + for k in ["boolean_ms", "tessellate_ms", "other_ms"] { + assert!(p[k].as_f64().is_some_and(|ms| ms >= 0.0), "{k}: {t}"); + } + assert_eq!(t["results"].as_array().map(Vec::len), Some(1), "{t}"); + + // --results alone stays a plain array. + assert!(json_output(cli().arg("run").arg(dir.script()).arg("--results").output().unwrap()).is_array()); + + let output = cli().arg("run").arg("--in").arg(&saved).arg("--timings").output().unwrap(); + assert!(!output.status.success()); + assert!(String::from_utf8_lossy(&output.stderr).contains("--timings needs a script")); +} diff --git a/crates/engine/src/lib.rs b/crates/engine/src/lib.rs index 6b60a557..99e82f61 100644 --- a/crates/engine/src/lib.rs +++ b/crates/engine/src/lib.rs @@ -22,6 +22,7 @@ pub mod render_jobs; pub mod sample; mod slicer_icon; pub mod slicers; +pub mod timing; pub mod view; use std::sync::Arc; @@ -956,6 +957,18 @@ impl Session { /// Run a script: a JSON array of `{"command": id, "params": {...}}` (or an object with a /// `commands` array). Stops at the first error. Returns each command's result. pub fn run_script(&mut self, script: &Value) -> Result> { + Ok(self.run_script_with(script, None)?.0) + } + + /// [`Session::run_script`], timing each command (#1833): the results and + /// `{"timings": [{"index", "command", "ms", "profile"?}], "total_ms"}`, with `profile` the + /// kernel's share of each command ([`timing`]). + pub fn run_script_timed(&mut self, script: &Value, profile: bool) -> Result<(Vec, Value)> { + let (results, timings) = self.run_script_with(script, Some(profile))?; + Ok((results, timings.unwrap_or(Value::Null))) + } + + fn run_script_with(&mut self, script: &Value, profile: Option) -> Result<(Vec, Option)> { let list = match script { Value::Array(a) => a.clone(), Value::Object(o) => { @@ -967,6 +980,8 @@ impl Session { return Err(EngineError::Other("script too long".into())); } let mut out = Vec::new(); + let mut steps = Vec::new(); + let clock = timing::Clock::start(); for (i, c) in list.iter().enumerate() { let id = c .get("command") @@ -974,10 +989,18 @@ impl Session { .and_then(Value::as_str) .ok_or_else(|| EngineError::Other(format!("script step {}: missing `command`", i + 1)))?; let p = c.get("params").cloned().unwrap_or(Value::Null); - let r = self.execute(id, &p).map_err(|e| EngineError::Other(format!("step {} ({id}): {e}", i + 1)))?; - out.push(r); + let r = match profile { + Some(profile) => { + let (r, step) = timing::time(profile, || self.execute(id, &p)); + steps.push(step.to_json(i, id)); + r + } + None => self.execute(id, &p), + }; + out.push(r.map_err(|e| EngineError::Other(format!("step {} ({id}): {e}", i + 1)))?); } - Ok(out) + let timings = profile.map(|_| serde_json::json!({"timings": steps, "total_ms": timing::round_ms(clock.ms())})); + Ok((out, timings)) } } diff --git a/crates/engine/src/timing.rs b/crates/engine/src/timing.rs new file mode 100644 index 00000000..a3dede46 --- /dev/null +++ b/crates/engine/src/timing.rs @@ -0,0 +1,111 @@ +//! Per-command timings for script runs and batches (#1833): how long each command took and, +//! when asked, how much of it went to kernel booleans and tessellation. The CLI's `run +//! --timings`, MCP `batch` and the app's `engine.batch` all report steps the same way: +//! `{"index", "command", "ms", "profile"?: {"boolean_ms", "tessellate_ms", "other_ms"}}`. + +use serde_json::{Value, json}; + +use crate::kernel::profile::{self, KernelTimes}; + +/// One step's time. +#[derive(Clone, Copy, Debug, Default, PartialEq)] +pub struct Step { + /// Wall time, ms. + pub ms: f64, + /// Kernel time within it, when profiled. + pub kernel: Option, +} + +/// A clock for a whole run (`total_ms`). +pub struct Clock(web_time::Instant); + +impl Clock { + pub fn start() -> Clock { + Clock(web_time::Instant::now()) + } + pub fn ms(&self) -> f64 { + self.0.elapsed().as_secs_f64() * 1000.0 + } +} + +/// Run `f` and time it; with `profile`, its kernel time too. +pub fn time(profile: bool, f: impl FnOnce() -> T) -> (T, Step) { + let clock = Clock::start(); + if profile { + let (r, k) = profile::capture(f); + (r, Step { ms: clock.ms(), kernel: Some(k) }) + } else { + let r = f(); + (r, Step { ms: clock.ms(), kernel: None }) + } +} + +/// 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 } +} + +impl Step { + /// The step's report entry (`index` from 0, as a batch's `failed.index`). + pub fn to_json(&self, index: usize, command: &str) -> Value { + let mut v = json!({"index": index, "command": command, "ms": round_ms(self.ms)}); + if let (Some(k), Some(o)) = (self.kernel, v.as_object_mut()) { + let other = (self.ms - k.boolean_ms - k.tessellate_ms).max(0.0); + o.insert( + "profile".into(), + json!({"boolean_ms": round_ms(k.boolean_ms), "tessellate_ms": round_ms(k.tessellate_ms), "other_ms": round_ms(other)}), + ); + } + v + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn steps_report_their_time_and_profile_only_when_asked() { + let (r, step) = time(false, || 7); + assert_eq!(r, 7); + let v = step.to_json(2, "solid.box"); + assert_eq!((v["index"].as_u64(), v["command"].as_str()), (Some(2), Some("solid.box"))); + assert!(v["ms"].as_f64().is_some_and(|ms| ms >= 0.0)); + assert!(v.get("profile").is_none()); + let step = Step { ms: 10.0, kernel: Some(KernelTimes { boolean_ms: 6.0, tessellate_ms: 3.0 }) }; + assert_eq!(step.to_json(0, "x")["profile"], json!({"boolean_ms": 6.0, "tessellate_ms": 3.0, "other_ms": 1.0})); + // Rounding can make the parts add up to a hair more than the whole: never a negative rest. + let step = Step { ms: 1.0, kernel: Some(KernelTimes { boolean_ms: 1.0000004, tessellate_ms: 0.0 }) }; + assert_eq!(step.to_json(0, "x")["profile"]["other_ms"], json!(0.0)); + assert_eq!(round_ms(f64::NAN), 0.0); + } + + #[test] + fn a_timed_script_reports_every_step_and_the_kernel_share_of_a_join() { + let script = json!({"commands": [ + {"command": "solid.box", "params": {"length": 10, "width": 10, "height": 10}}, + {"command": "solid.box", "params": {"length": 4, "width": 4, "height": 30, "operation": "join"}}, + ]}); + let mut s = crate::Session::default(); + let (results, t) = s.run_script_timed(&script, true).unwrap(); + assert_eq!(results.len(), 2); + let rows = t["timings"].as_array().unwrap(); + assert_eq!(rows.len(), 2); + assert_eq!(rows[1]["command"], "solid.box"); + assert_eq!(rows[1]["index"], 1); + let p = &rows[1]["profile"]; + assert!(p["boolean_ms"].as_f64().unwrap() > 0.0, "{t}"); + let sum: f64 = ["boolean_ms", "tessellate_ms", "other_ms"].iter().map(|k| p[k].as_f64().unwrap()).sum(); + assert!((sum - rows[1]["ms"].as_f64().unwrap()).abs() < 0.01, "{t}"); + let total = t["total_ms"].as_f64().unwrap(); + assert!(total + 0.01 >= rows.iter().map(|r| r["ms"].as_f64().unwrap()).sum::(), "{t}"); + // Without profile: the same rows, no kernel split; the plain run is unchanged. + let (_, t) = crate::Session::default().run_script_timed(&script, false).unwrap(); + assert!(t["timings"][0].get("profile").is_none()); + assert_eq!(crate::Session::default().run_script(&script).unwrap().len(), 2); + // A failing step still fails the run, with its step number. + let bad = json!([{"command": "solid.box", "params": {"length": -1}}]); + let e = crate::Session::default().run_script_timed(&bad, true).unwrap_err().to_string(); + assert!(e.contains("step 1"), "{e}"); + } +} diff --git a/crates/kernel/Cargo.toml b/crates/kernel/Cargo.toml index d174e08f..764db89f 100644 --- a/crates/kernel/Cargo.toml +++ b/crates/kernel/Cargo.toml @@ -20,6 +20,7 @@ truck-meshalgo = { workspace = true } truck-stepio = { workspace = true } truck-topology = { workspace = true } spade = { workspace = true } +web-time = { workspace = true } [target.'cfg(not(target_arch = "wasm32"))'.dependencies] rayon = { workspace = true } diff --git a/crates/kernel/src/body.rs b/crates/kernel/src/body.rs index 5f77d5d7..add84c75 100644 --- a/crates/kernel/src/body.rs +++ b/crates/kernel/src/body.rs @@ -1038,6 +1038,10 @@ impl Body { /// [`Body::tessellate_with`] in which no facet turns more than `angle` radians either /// (infinite: the chord tolerance alone). fn tessellate_within(&self, tol: f64, angle: f64, refine: bool) -> Result { + crate::profile::timed(crate::profile::Kind::Tessellate, || self.tessellate_within_untimed(tol, angle, refine)) + } + + fn tessellate_within_untimed(&self, tol: f64, angle: f64, refine: bool) -> Result { let tol = if tol.is_finite() && tol > 0.0 { tol } else { 0.05 }; let tol = tol.max(self.size() * 1e-6); if let Some(m) = &self.mesh { @@ -1148,6 +1152,10 @@ impl Body { } fn plan_within(&self, tol: f64, angle: Option) -> Result { + crate::profile::timed(crate::profile::Kind::Tessellate, || self.plan_within_untimed(tol, angle)) + } + + fn plan_within_untimed(&self, tol: f64, angle: Option) -> Result { if self.is_mesh() { return Err(KernelError::Invalid("a mesh body has no surfaces to tessellate".into())); } @@ -1266,6 +1274,10 @@ impl Body { /// body's [`Body::display_plan`] (shared edge nodes, structured grids), or the way /// [`Body::tessellate`] meshes when no plan can be made. pub fn display_mesh(&self, tol: f64) -> Result { + crate::profile::timed(crate::profile::Kind::Tessellate, || self.display_mesh_untimed(tol)) + } + + fn display_mesh_untimed(&self, tol: f64) -> Result { if self.is_mesh() { return self.flagged(self.tessellate(tol)?); } @@ -1285,6 +1297,10 @@ impl Body { /// sagitta of a small radius on a large body (a sheet-metal bend, a small hole), which the /// tolerance alone leaves as one flat facet. pub fn display_mesh_angular(&self, tol: f64, angle: f64) -> Result { + crate::profile::timed(crate::profile::Kind::Tessellate, || self.display_mesh_angular_untimed(tol, angle)) + } + + fn display_mesh_angular_untimed(&self, tol: f64, angle: f64) -> Result { if self.is_mesh() { return self.flagged(self.tessellate(tol)?); } @@ -1300,6 +1316,10 @@ impl Body { /// The display mesh of a plan made from this body ([`Body::display_plan`], /// [`Body::display_plan_angular`]): evaluated on the CPU, with its edges flagged. pub fn display_mesh_of(&self, plan: &solidcraft_geom::tess::TessPlan) -> Result { + crate::profile::timed(crate::profile::Kind::Tessellate, || self.display_mesh_of_untimed(plan)) + } + + fn display_mesh_of_untimed(&self, plan: &solidcraft_geom::tess::TessPlan) -> Result { self.flagged(plan.evaluate()) } diff --git a/crates/kernel/src/lib.rs b/crates/kernel/src/lib.rs index 8599daae..50d64209 100644 --- a/crates/kernel/src/lib.rs +++ b/crates/kernel/src/lib.rs @@ -104,6 +104,7 @@ mod prism; mod prism_curve; mod prism_local; mod prism_measure; +pub mod profile; pub mod provenance; mod record; mod seam_faces; diff --git a/crates/kernel/src/ops.rs b/crates/kernel/src/ops.rs index 78908bdf..eefe53c7 100644 --- a/crates/kernel/src/ops.rs +++ b/crates/kernel/src/ops.rs @@ -300,6 +300,10 @@ thread_local! { /// The result carries its exact history ([`Body::history`]) over the operands `[a, b]`, /// whichever way it was made, or none where a step it took does not report one. pub fn boolean(a: &Body, b: &Body, op: BoolOp) -> Result> { + crate::profile::timed(crate::profile::Kind::Boolean, || boolean_untimed(a, b, op)) +} + +fn boolean_untimed(a: &Body, b: &Body, op: BoolOp) -> Result> { // Earlier coarse bores can leave a junction a later pattern copy cannot intersect. // Resolve conical-cut junctions from the first copy, while the operands are unchanged. if op == BoolOp::Cut && !APART.with(|c| c.get()) && conical_cut_junction(a, b) { @@ -1273,6 +1277,10 @@ pub(crate) fn by_lumps(a: &Body, b: &Body, la: Vec, lb: Vec, op: Boo /// intersection work (many identical pattern tools, #261). `None` when any two may meet, or a /// body is a mesh: the caller unions those the usual way. pub fn union_apart(bodies: &[Body]) -> Result> { + crate::profile::timed(crate::profile::Kind::Boolean, || union_apart_untimed(bodies)) +} + +fn union_apart_untimed(bodies: &[Body]) -> Result> { if bodies.len() < 2 || bodies.len() > 10_000 || bodies.iter().any(Body::is_mesh) { return Ok(None); } @@ -1311,6 +1319,10 @@ pub fn union_apart(bodies: &[Body]) -> Result> { /// shows they are apart (profiles apart in their sketch, extruded alike). `None` for fewer than /// two bodies or a mesh. pub fn join_apart(bodies: &[Body]) -> Result> { + crate::profile::timed(crate::profile::Kind::Boolean, || join_apart_untimed(bodies)) +} + +fn join_apart_untimed(bodies: &[Body]) -> Result> { if bodies.len() < 2 || bodies.len() > 10_000 || bodies.iter().any(Body::is_mesh) { return Ok(None); } diff --git a/crates/kernel/src/profile.rs b/crates/kernel/src/profile.rs new file mode 100644 index 00000000..56dfbcf4 --- /dev/null +++ b/crates/kernel/src/profile.rs @@ -0,0 +1,136 @@ +//! Where a command's time goes inside the kernel (#1833): wall time in booleans and in +//! tessellation, measured on this thread while [`capture`] runs and not at all otherwise (one +//! thread-local check per timed call). +//! +//! Only the outermost timed call counts: a tessellation a boolean does to check its result is +//! the boolean's time, so the two never add up to more than the command took. Work a call hands +//! to other threads is inside that call's wall time. + +use std::cell::Cell; + +/// Kernel time spent while a [`capture`] ran, in milliseconds. +#[derive(Clone, Copy, Debug, Default, PartialEq)] +pub struct KernelTimes { + pub boolean_ms: f64, + pub tessellate_ms: f64, +} + +/// What a timed call is. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub(crate) enum Kind { + Boolean, + Tessellate, +} + +#[derive(Clone, Copy, Default)] +struct State { + /// A capture is running on this thread. + on: bool, + /// A timed call is running (nested ones aren't timed). + busy: bool, + times: KernelTimes, +} + +thread_local! { + static STATE: Cell = const { Cell::new(State { on: false, busy: false, times: KernelTimes { boolean_ms: 0.0, tessellate_ms: 0.0 } }) }; +} + +/// Run `f`, and the kernel time it spent in booleans and tessellation on this thread. Captures +/// nest: an inner capture's time is the outer one's too. +pub fn capture(f: impl FnOnce() -> T) -> (T, KernelTimes) { + struct Restore(State); + impl Drop for Restore { + fn drop(&mut self) { + let inner = STATE.with(Cell::get).times; + let mut outer = self.0; + if outer.on { + outer.times.boolean_ms += inner.boolean_ms; + outer.times.tessellate_ms += inner.tessellate_ms; + } + STATE.with(|s| s.set(outer)); + } + } + let outer = STATE.with(Cell::get); + STATE.with(|s| s.set(State { on: true, busy: outer.busy, times: KernelTimes::default() })); + let restore = Restore(outer); + let r = f(); + let times = STATE.with(Cell::get).times; + drop(restore); + (r, times) +} + +/// Time `f` as `kind` when a capture is running and no timed call is. +pub(crate) fn timed(kind: Kind, f: impl FnOnce() -> T) -> T { + let st = STATE.with(Cell::get); + if !st.on || st.busy { + return f(); + } + struct Busy { + kind: Kind, + started: web_time::Instant, + } + impl Drop for Busy { + fn drop(&mut self) { + let ms = self.started.elapsed().as_secs_f64() * 1000.0; + STATE.with(|s| { + let mut st = s.get(); + st.busy = false; + match self.kind { + Kind::Boolean => st.times.boolean_ms += ms, + Kind::Tessellate => st.times.tessellate_ms += ms, + } + s.set(st); + }); + } + } + STATE.with(|s| s.set(State { busy: true, ..st })); + let busy = Busy { kind, started: web_time::Instant::now() }; + let r = f(); + drop(busy); + r +} + +#[cfg(test)] +mod tests { + use super::*; + + fn spin(ms: u64) { + let t = web_time::Instant::now(); + while t.elapsed().as_millis() < u128::from(ms) {} + } + + #[test] + fn nothing_is_timed_outside_a_capture() { + timed(Kind::Boolean, || spin(2)); + let ((), t) = capture(|| ()); + assert_eq!(t, KernelTimes::default()); + } + + #[test] + fn only_the_outermost_call_counts() { + let started = web_time::Instant::now(); + let ((), t) = capture(|| { + timed(Kind::Boolean, || { + spin(3); + timed(Kind::Tessellate, || spin(3)); + }); + timed(Kind::Tessellate, || spin(2)); + }); + let elapsed = started.elapsed().as_secs_f64() * 1000.0; + assert!(t.boolean_ms >= 6.0 && t.tessellate_ms >= 2.0, "{t:?}"); + // The tessellation inside the boolean is not counted twice. + assert!(t.boolean_ms + t.tessellate_ms <= elapsed + 1e-6, "{t:?} in {elapsed} ms"); + } + + #[test] + fn inner_captures_add_to_the_outer_one_and_a_panic_restores_it() { + let ((), outer) = capture(|| { + let ((), inner) = capture(|| timed(Kind::Boolean, || spin(2))); + assert!(inner.boolean_ms >= 2.0); + let _ = std::panic::catch_unwind(|| capture(|| timed(Kind::Tessellate, || panic!("kernel")))); + }); + assert!(outer.boolean_ms >= 2.0, "{outer:?}"); + let st = STATE.with(Cell::get); + assert!(!st.on && !st.busy); + } +} diff --git a/crates/mcp/src/backend.rs b/crates/mcp/src/backend.rs index 7d107c16..e3b2c207 100644 --- a/crates/mcp/src/backend.rs +++ b/crates/mcp/src/backend.rs @@ -21,6 +21,11 @@ pub trait Backend { fn design_path(&self) -> Option { None } + /// Commands run in this process, on this thread (the kernel's time in them can be measured + /// here, #1833). + fn in_process(&self) -> bool { + false + } } /// Longest reply line accepted from the app. @@ -308,4 +313,7 @@ impl Backend for Headless { fn design_path(&self) -> Option { self.session.path.clone() } + fn in_process(&self) -> bool { + true + } } diff --git a/crates/mcp/src/tests.rs b/crates/mcp/src/tests.rs index dfa086c2..38d637aa 100644 --- a/crates/mcp/src/tests.rs +++ b/crates/mcp/src/tests.rs @@ -1479,3 +1479,44 @@ fn measure_items_gives_diameters_and_centre_distances() { assert!((two["min"].as_f64().unwrap() - 45.0).abs() < 1e-9 && (two["max"].as_f64().unwrap() - 55.0).abs() < 1e-9, "{two}"); assert!(two["distance_mm"].is_number() && two["from"].is_array(), "{two}"); } + +/// #1833: `timings` / `profile` time every step run, the failing one included, headless with the +/// kernel's share; bridged, the app is asked to time them and its numbers are passed on. +#[test] +fn batch_reports_timings_and_profile() { + let mut s = server(); + let steps = json!([ + {"command": "solid.box", "params": {"length": 10, "width": 10, "height": 10}}, + {"command": "solid.box", "params": {"length": 4, "width": 4, "height": 30, "operation": "join"}}, + ]); + let r = raw_tool(&mut s, "batch", json!({"commands": steps, "profile": true})); + let body: Value = serde_json::from_str(r["result"]["content"][0]["text"].as_str().unwrap()).unwrap(); + let rows = body["timings"].as_array().unwrap(); + assert_eq!(rows.len(), 2, "{body}"); + assert_eq!((rows[1]["index"].as_u64(), rows[1]["command"].as_str()), (Some(1), Some("solid.box"))); + assert!(rows[1]["profile"]["boolean_ms"].as_f64().unwrap() > 0.0, "{body}"); + assert!(body["total_ms"].as_f64().is_some(), "{body}"); + + let r = raw_tool( + &mut s, + "batch", + json!({"timings": true, "commands": [{"command": "solid.box", "params": {"length": 1, "width": 1, "height": 1}}, {"command": "NoSuchCommand"}]}), + ); + let body: Value = serde_json::from_str(r["result"]["content"][0]["text"].as_str().unwrap()).unwrap(); + assert_eq!(body["timings"].as_array().map(Vec::len), Some(2), "the failing step is timed too: {body}"); + assert!(body["timings"][0].get("profile").is_none()); + // Not asked: no timings. + let d = tool(&mut s, "batch", json!({"commands": [{"command": "solid.box", "params": {"length": 1, "width": 1, "height": 1}}]})); + assert!(d.get("timings").is_none(), "{d}"); + + let reply = + json!({"completed": 1, "results": [{"x": 1}], "undone": 0, "timings": [{"index": 0, "command": "a.one", "ms": 2.5}], "total_ms": 2.6}); + let (b, body, _) = recorded_batch(Ok(reply), json!({"commands": [{"command": "a.one"}], "profile": true})); + assert_eq!(b.calls[0].1["timings"], true); + assert_eq!(b.calls[0].1["profile"], true); + assert_eq!((body["timings"][0]["ms"].as_f64(), body["total_ms"].as_f64()), (Some(2.5), Some(2.6)), "{body}"); + // An app without engine.batch is timed step by step here, without a kernel split it can't measure. + let (_, body, _) = recorded_batch(Err("unknown method `engine.batch`".into()), json!({"commands": [{"command": "a.one"}], "profile": true})); + assert_eq!(body["timings"][0]["command"], "a.one", "{body}"); + assert!(body["timings"][0].get("profile").is_none(), "{body}"); +} diff --git a/crates/mcp/src/tools.rs b/crates/mcp/src/tools.rs index 138361d0..7d97daaa 100644 --- a/crates/mcp/src/tools.rs +++ b/crates/mcp/src/tools.rs @@ -5,6 +5,7 @@ use std::sync::atomic::{AtomicU64, Ordering}; use serde_json::{Map, Value, json}; use solidcraft_engine::io::vfs; +use solidcraft_engine::timing; use crate::backend::Backend; @@ -109,6 +110,8 @@ pub fn tool_definitions() -> Vec { "items": {"type": "object", "properties": {"command": {"type": "string"}, "params": {"type": "object"}}, "required": ["command"]}, }, "rollback": {"type": "boolean", "description": "Undo completed steps when one fails (default true)"}, + "timings": {"type": "boolean", "description": "Add `timings`: [{index, command, ms}] for every step run (the failing one included) and `total_ms` (default false)"}, + "profile": {"type": "boolean", "description": "Like timings, and each step's `profile`: {boolean_ms, tessellate_ms, other_ms}, its time in kernel booleans, in tessellation and the rest (default false)"}, "verbose": {"type": "boolean", "description": "false: a compact reply. Feature steps leave out the full body list (created_bodies, changed_bodies and removed_bodies stay), sketch steps the ids they repeat outside `created` (default true)"}, }), &["commands"], @@ -496,10 +499,16 @@ fn batch(b: &mut dyn Backend, a: &Map) -> Value { } let rollback = a.get("rollback").and_then(Value::as_bool).unwrap_or(true); let verbose = a.get("verbose").and_then(Value::as_bool).unwrap_or(true); + let profile = a.get("profile").and_then(Value::as_bool).unwrap_or(false); + let timed = profile || a.get("timings").and_then(Value::as_bool).unwrap_or(false); // An app that runs batches itself answers the whole batch in one request, so one frame // (#743). One too long for a control line goes step by step: the app would refuse it unrun. // The margin covers the envelope and the `allow_paths` the backend adds. - let params = json!({"commands": steps, "rollback": rollback}); + let mut params = json!({"commands": steps, "rollback": rollback}); + if timed && let Some(o) = params.as_object_mut() { + o.insert("timings".into(), Value::Bool(true)); + o.insert("profile".into(), Value::Bool(profile)); + } if params.to_string().len() + 64 * 1024 <= solidcraft_engine::MAX_LINE { match b.call("engine.batch", params) { Ok(r) => return batch_reply(&r, rollback, verbose), @@ -516,42 +525,57 @@ fn batch(b: &mut dyn Backend, a: &Map) -> Value { } let start = if rollback { Undo::begin(b) } else { Undo::None }; let mut results = Vec::with_capacity(steps.len()); + let mut rows = Vec::new(); + let clock = timing::Clock::start(); + // The kernel's share can only be measured where the commands run: in this process. + let profile = profile && b.in_process(); for (i, step) in steps.iter().enumerate() { let command = step.get("command").or_else(|| step.get("id")).and_then(Value::as_str); - let r = match command { + let (r, took) = timing::time(profile, || match command { Some(id) => exec(b, id, step.get("params").cloned().filter(|p| !p.is_null()).unwrap_or(json!({}))), None => Err("missing `command`".to_string()), - }; + }); + if timed { + rows.push(took.to_json(i, command.unwrap_or_default())); + } match r { Ok(v) => results.push(if verbose { v } else { compact(v) }), Err(e) => { let undone = start.rollback(b, i); - return text_result( - &json!({ - "ok": false, - "completed": i, - "failed": {"index": i, "command": command, "error": e}, - "rolled_back": rollback, - "undone": undone, - "results": results, - }), - true, - ); + let reply = json!({ + "ok": false, + "completed": i, + "failed": {"index": i, "command": command, "error": e}, + "rolled_back": rollback, + "undone": undone, + "results": results, + }); + return text_result(&with_timings(reply, timed, rows, clock.ms()), true); } } } start.finish(b); - text_result(&json!({"ok": true, "completed": results.len(), "results": results}), false) + let reply = json!({"ok": true, "completed": results.len(), "results": results}); + text_result(&with_timings(reply, timed, rows, clock.ms()), false) +} + +/// `reply` with `timings` and `total_ms` when they were asked for. +fn with_timings(mut reply: Value, timed: bool, rows: Vec, total_ms: f64) -> Value { + if timed && let Some(o) = reply.as_object_mut() { + o.insert("timings".into(), Value::Array(rows)); + o.insert("total_ms".into(), json!(timing::round_ms(total_ms))); + } + reply } /// The `batch` reply from the app's `engine.batch` answer, shaped as the per-step path shapes it. fn batch_reply(r: &Value, rollback: bool, verbose: bool) -> Value { let results: Vec = r["results"].as_array().cloned().unwrap_or_default().into_iter().map(|v| if verbose { v } else { compact(v) }).collect(); - match r.get("failed").filter(|f| !f.is_null()) { - None => text_result(&json!({"ok": true, "completed": results.len(), "results": results}), false), - Some(failed) => text_result( - &json!({ + let (mut reply, error) = match r.get("failed").filter(|f| !f.is_null()) { + None => (json!({"ok": true, "completed": results.len(), "results": results}), false), + Some(failed) => ( + json!({ "ok": false, "completed": r["completed"], "failed": failed, @@ -561,7 +585,16 @@ fn batch_reply(r: &Value, rollback: bool, verbose: bool) -> Value { }), true, ), + }; + // The app timed the steps where they ran. + if let Some(o) = reply.as_object_mut() { + for k in ["timings", "total_ms"] { + if let Some(v) = r.get(k).filter(|v| !v.is_null()) { + o.insert(k.into(), v.clone()); + } + } } + text_result(&reply, error) } /// A command's result without what the design already had (`execute` or `batch` with `verbose: false`): a diff --git a/crates/ui-egui/src/control.rs b/crates/ui-egui/src/control.rs index 48c6fe40..0ed0b48f 100644 --- a/crates/ui-egui/src/control.rs +++ b/crates/ui-egui/src/control.rs @@ -44,6 +44,7 @@ use std::sync::mpsc::Sender; use serde_json::{Value, json}; use solidcraft_engine::io::vfs; use solidcraft_engine::render::StandardView; +use solidcraft_engine::timing; use crate::SolveApp; @@ -121,7 +122,9 @@ const MAX_BATCH: usize = 10_000; /// bypass. const LOADS_A_FILE: [&str; 3] = ["doc.open", "file.insert_step", "file.insert_mesh"]; -/// `engine.batch {commands, rollback?}`: the steps in one request, so in one frame (#743). Each +/// `engine.batch {commands, rollback?, timings?, profile?}`: the steps in one request, so in one +/// frame (#743). With `timings` the reply adds each step's time and `total_ms`, with `profile` +/// each step's kernel share too (`solidcraft_engine::timing`, #1833). Each /// step runs as `engine.execute` runs it; the first failure stops the batch and, with /// `rollback` (the default), the design goes back to its checkpoint. Step failures are part of /// the reply; refusals (`engine.batch unavailable: …`) come before anything runs, so the client @@ -138,26 +141,43 @@ fn batch(app: &mut SolveApp, p: &Value) -> Outcome { return err(format!("engine.batch unavailable: step {i} ({c}) loads a file")); } let rollback = p.get("rollback").and_then(Value::as_bool).unwrap_or(true); + let profile = p.get("profile").and_then(Value::as_bool).unwrap_or(false); + let timed = profile || p.get("timings").and_then(Value::as_bool).unwrap_or(false); + let mut rows = Vec::new(); + let clock = timing::Clock::start(); let checkpoint = if rollback { app.run("edit.checkpoint", json!({})).ok().and_then(|v| v["checkpoint"].as_u64()) } else { None }; let mut results = Vec::with_capacity(steps.len()); for (i, step) in steps.iter().enumerate() { - let r = match command(step) { + let (r, took) = timing::time(profile, || match command(step) { Some(id) => execute(app, id, step.get("params").cloned().filter(|v| !v.is_null()).unwrap_or(json!({}))), None => Err("missing `command`".to_string()), - }; + }); + if timed { + rows.push(took.to_json(i, command(step).unwrap_or_default())); + } match r { Ok(v) => results.push(v), Err(e) => { let restored = checkpoint.is_some_and(|id| app.run("edit.restore_checkpoint", json!({"checkpoint": id})).is_ok()); let failed = json!({"index": i, "command": command(step), "error": e}); - return ok(json!({"completed": i, "results": results, "failed": failed, "undone": if restored { i } else { 0 }})); + let reply = json!({"completed": i, "results": results, "failed": failed, "undone": if restored { i } else { 0 }}); + return ok(with_timings(reply, timed, rows, clock.ms())); } } } if let Some(id) = checkpoint { let _ = app.run("edit.restore_checkpoint", json!({"checkpoint": id, "forget": true})); } - ok(json!({"completed": results.len(), "results": results, "undone": 0})) + ok(with_timings(json!({"completed": results.len(), "results": results, "undone": 0}), timed, rows, clock.ms())) +} + +/// A batch reply with `timings` and `total_ms` when they were asked for. +fn with_timings(mut reply: Value, timed: bool, rows: Vec, total_ms: f64) -> Value { + if timed && let Some(o) = reply.as_object_mut() { + o.insert("timings".into(), Value::Array(rows)); + o.insert("total_ms".into(), json!(timing::round_ms(total_ms))); + } + reply } /// A request from an MCP server carries the folders its agent may use (`allow_paths`); every @@ -1115,6 +1135,28 @@ mod tests { assert_eq!(inspect(&mut h)["sketches"].as_array().map(Vec::len), Some(40)); } + /// #1833: `engine.batch` times its steps where they run, the failing one included, with the + /// kernel's share when `profile` asks; unasked, the reply is as before. + #[test] + fn engine_batch_times_its_steps() { + let mut h = crate::scenario::Harness::new(); + let steps = json!([ + {"command": "solid.box", "params": {"length": 10, "width": 10, "height": 10}}, + {"command": "solid.box", "params": {"length": 4, "width": 4, "height": 30, "operation": "join"}}, + ]); + let v = batch(&mut h, json!({"commands": steps, "profile": true})); + let rows = v["result"]["timings"].as_array().cloned().unwrap_or_default(); + assert_eq!(rows.len(), 2, "{v}"); + assert_eq!(rows[1]["index"], 1); + assert!(rows[1]["profile"]["boolean_ms"].as_f64().is_some_and(|ms| ms > 0.0), "{v}"); + assert!(v["result"]["total_ms"].as_f64().is_some(), "{v}"); + let v = batch(&mut h, json!({"timings": true, "commands": [{"command": "NoSuchCommand"}]})); + assert_eq!(v["result"]["timings"].as_array().map(Vec::len), Some(1), "{v}"); + assert!(v["result"]["timings"][0].get("profile").is_none(), "{v}"); + let v = batch(&mut h, json!({"commands": [{"command": "solid.box", "params": {"length": 1, "width": 1, "height": 1}}]})); + assert!(v["result"].get("timings").is_none() && v["result"].get("total_ms").is_none(), "{v}"); + } + #[test] fn engine_batch_rolls_back_at_the_first_failure() { let mut h = crate::scenario::Harness::new(); diff --git a/docs/book/src/guide/getting-started.md b/docs/book/src/guide/getting-started.md index b11b283e..516a0976 100644 --- a/docs/book/src/guide/getting-started.md +++ b/docs/book/src/guide/getting-started.md @@ -213,6 +213,17 @@ cargo run --release -p solidcraft-cli -- run examples/bracket.json --results --j cargo run --release -p solidcraft-cli -- eval examples/bracket.json --json-out measures.json ``` +To find the slow steps of a script, `--timings` prints how long each command took instead of +the measurement: `{"timings": [{"index", "command", "ms"}], "total_ms"}`, with `index` counted +from 0. `--profile` adds each command's `profile: {"boolean_ms", "tessellate_ms", "other_ms"}`, +its wall time in the kernel's booleans, in tessellation and in everything else. With +`--results` as well, the results go in the same object as `results`; `--results` alone still +prints a plain array. + +```sh +cargo run --release -p solidcraft-cli -- run examples/bracket.json --profile +``` + A design's history turns into a script that rebuilds it, which makes a bug that only shows on one design a one-file reproduction: diff --git a/docs/control-protocol.md b/docs/control-protocol.md index 36ccc8bf..b5ae2391 100644 --- a/docs/control-protocol.md +++ b/docs/control-protocol.md @@ -74,7 +74,7 @@ MCP server sends its folders this way on every request ([mcp.md](mcp.md)). Witho |---|---|---| | `engine.execute` | `command`: command id, `params`: JSON object | the command's result | | `engine.script` | `commands`: `[{command, params}, …]` | results, stops at the first error | -| `engine.batch` | `commands`: `[{command, params}, …]` (at most 10 000), `rollback?`: bool (default true) | `{completed, results, undone}`, plus `failed: {index, command, error}` when a step fails. Runs the steps in one request, so within one frame, each as `engine.execute` runs it. The first failure stops the batch, and with `rollback` the design goes back to how it was before it (`undone`: the steps taken back). Refused before anything runs, with an error starting `engine.batch unavailable`, while the agent cursor is shown or when a step loads a file (`doc.open`, `file.insert_step`, `file.insert_mesh`). Send such steps one by one. Answered when done, for up to 3600 s | +| `engine.batch` | `commands`: `[{command, params}, …]` (at most 10 000), `rollback?`: bool (default true), `timings?`, `profile?`: bool (default false) | `{completed, results, undone}`, plus `failed: {index, command, error}` when a step fails, and with `timings` `timings: [{index, command, ms}]` (the failing step included) and `total_ms`; `profile` adds each step's `profile: {boolean_ms, tessellate_ms, other_ms}`. Runs the steps in one request, so within one frame, each as `engine.execute` runs it. The first failure stops the batch, and with `rollback` the design goes back to how it was before it (`undone`: the steps taken back). Refused before anything runs, with an error starting `engine.batch unavailable`, while the agent cursor is shown or when a step loads a file (`doc.open`, `file.insert_step`, `file.insert_mesh`). Send such steps one by one. Answered when done, for up to 3600 s | | `engine.commands` | — | every command: id, label, tab, panel, icon, shortcut, params doc, enabled | | `document.inspect` | `measure?`: bool | parameters, timeline (errors, timings), bodies, sketches, selection | diff --git a/docs/mcp.md b/docs/mcp.md index 3f44efa3..1ddc2063 100644 --- a/docs/mcp.md +++ b/docs/mcp.md @@ -144,7 +144,7 @@ They cover the workflow, the command shapes, how to verify with `measure`, and t |---|---|---| | `list_commands` | `filter?` | The command catalog: id, label, tab/panel, shortcut, parameter docs, enabled now. `filter` matches id, label, tab and panel. | | `execute` | `command`, `params?`, `verbose?` (default true) | Run any command with JSON parameters (`list_commands` shows them). Failures leave the design unchanged. A feature command replies with the feature (`feature`, `name`), every body (`bodies`) and the bodies it created, changed and removed (`created_bodies`, `changed_bodies`, `removed_bodies`). `verbose: false` uses the same compact reply as `batch`. | -| `batch` | `commands: [{command, params}]`, `rollback?` (default true), `verbose?` (default true) | Run steps in order, stop at the first error and undo the completed steps. The reply names the failing step (`failed.index`, `failed.command`, `failed.error`) and every result before it. `verbose: false` keeps the reply small in large designs: feature steps leave out the full body list (`created_bodies`, `changed_bodies`, `removed_bodies` stay) and sketch steps the ids they repeat outside `created`. Bridged to an app that has `engine.batch`, the whole batch is one control request (one frame of the app). Older apps, and apps showing the agent cursor, get the steps one by one. | +| `batch` | `commands: [{command, params}]`, `rollback?` (default true), `verbose?` (default true), `timings?`, `profile?` (default false) | Run steps in order, stop at the first error and undo the completed steps. The reply names the failing step (`failed.index`, `failed.command`, `failed.error`) and every result before it. `verbose: false` keeps the reply small in large designs: feature steps leave out the full body list (`created_bodies`, `changed_bodies`, `removed_bodies` stay) and sketch steps the ids they repeat outside `created`. Bridged to an app that has `engine.batch`, the whole batch is one control request (one frame of the app). Older apps, and apps showing the agent cursor, get the steps one by one. `timings: true` adds `timings: [{index, command, ms}]` for every step run, the failing one included, and `total_ms`. `profile: true` also adds each step's `profile: {boolean_ms, tessellate_ms, other_ms}`, its time in kernel booleans, in tessellation and the rest. Steps are timed where they run: in the app when bridged. An app without `engine.batch` is timed step by step, without `profile`. | | `inspect_design` | `measure?` (default true), `sketches?` (default true) | Design properties (`metadata`: project, author… and other tools' keys; set them with `execute` `document.metadata.set`), parameters, timeline (type, suppressed, rolled back, error, warning, timing), bodies (volume, area, centre of mass, bbox, face/edge/vertex counts, visible; `removed_later: true` while a sketch is being edited on a rolled-back timeline and a later feature deletes the body, which is then not shown), sketches (curves, points, constraints, profiles, DOF, solve status, visible), selection, undo depth. Hide helper sketches, bodies or construction planes with `execute` `browser.visibility` (`{items, visible}` or `{folder, visible}`), and joint glyphs with `{joints: [id or name], visible}` or `{folder: "joints", visible}` (a hidden joint still constrains and drives; `joint.list` reports each joint's `visible`). | | `measure` | `body?` or `items?` | Volume (mm³), area (mm²), centre of mass, bbox and topology counts per body, with totals. With `items` (one or two selections as `execute` takes them: `face`, `edge`, `vertex`, `sketch_curve`, `profile`), the picked geometry instead: see below. | | `body_topology` | `body` | Edges (index, midpoint, length, ends) and faces (index, name, area, centroid, normal, `point`, and for a cylindrical face its `cylinder`: `origin`, `axis`, `radius`). An edge midpoint is the `[x,y,z]` that picks that edge for fillet and chamfer. A face's `point` lies on it and picks it (its centroid may not: that of a face with a hole is in the hole); a face's `name` picks it for the commands that take faces (`face.delete`, `solid.shell`, `solid.draft`, `solid.offset_face`, `solid.split_face`, `solid.replace_face`, and `face` of `sheet.convert`). |