Profiler: every SMLib C API call is a span, timed by the C API itself

The C API logs each call with its steady_clock time; the log sink records
that as an smlib span (child of whatever runs on the calling thread).

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

Cargo.lock

@@ -4270,6 +4270,7 @@ dependencies = [
  "log",
  "serde_json",
  "solidcraft-geom",
+ "solidcraft-profile",
  "web-time",
 ]
 

crates/smlib/Cargo.toml

@@ -27,6 +27,7 @@ native = []
 [dependencies]
 log = { workspace = true }
 solidcraft-geom = { workspace = true }
+solidcraft-profile = { workspace = true }
 
 [target.'cfg(target_arch = "wasm32")'.dependencies]
 # The clocks SMLib's C library asks for in a browser build (src/ffi.rs).
@@ -36,5 +37,6 @@ web-time = { workspace = true }
 cc = { version = "1.2", features = ["parallel"] }
 
 [dev-dependencies]
+solidcraft-profile = { workspace = true, features = ["enabled"] }
 flate2 = "1.1"
 serde_json = { workspace = true }

crates/smlib/src/lib.rs

@@ -137,7 +137,25 @@ fn c_path(p: &Path) -> Result<CString> {
     CString::new(p.to_string_lossy().as_bytes()).map_err(|_| Error::Argument)
 }
 
+/// One C API call's log line, `smlib_fn(args) -> status (1.234 ms)`: the function and the time
+/// the C API measured for it (inside its lock, so waiting for another thread's call is not in it).
+fn call_time(line: &str) -> Option<(&str, std::time::Duration)> {
+    let name = line.get(..line.find('(')?)?;
+    if !name.starts_with("smlib_") || !name.bytes().all(|b| b.is_ascii_alphanumeric() || b == b'_') {
+        return None;
+    }
+    let tail = line.strip_suffix(" ms)")?;
+    let ms: f64 = tail.get(tail.rfind(" (")? + 2..)?.parse().ok()?;
+    (ms.is_finite() && ms >= 0.0).then(|| (name, std::time::Duration::from_secs_f64(ms / 1000.0)))
+}
+
 fn log_line(level: i32, text: String) {
+    // Every call's log line carries the C API's own timing: the profiler's SMLib spans.
+    if solidcraft_profile::enabled()
+        && let Some((name, took)) = call_time(&text)
+    {
+        solidcraft_profile::record("smlib", solidcraft_profile::intern(name), took);
+    }
     if level == 0 {
         log::debug!(target: "smlib", "{text}");
     } else {

crates/smlib/src/tests.rs

@@ -68,3 +68,26 @@ fn without_native_every_call_says_so() {
     assert_eq!(Brep::make_box([0.0; 3], [1.0; 3]).unwrap_err(), Error::NotBuilt);
     assert_eq!(current_call(), None);
 }
+
+#[test]
+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"]
+    {
+        assert_eq!(call_time(bad), None, "{bad}");
+    }
+}
+
+#[cfg(feature = "native")]
+#[test]
+fn every_call_is_a_profiler_span_timed_by_the_c_api() {
+    solidcraft_profile::set_enabled(true);
+    let mark = solidcraft_profile::mark();
+    let b = Brep::make_box([0.0; 3], [1.0; 3]).unwrap();
+    let _ = b.volume(1e-7).unwrap();
+    let r = mark.report();
+    let names: Vec<&str> = r.rows.iter().filter(|r| r.category == "smlib").map(|r| r.name).collect();
+    assert!(names.contains(&"smlib_make_box") && names.contains(&"smlib_brep_volume"), "{r:?}");
+}