Log simple performance metrics (#4596)

Signed-off-by: Nick Cameron <nrc@ncameron.org>

README.md

@@ -450,3 +450,9 @@ PS: for the debug panel, the following JSON is useful for snapping the camera
 ## KCL
 
 For how to contribute to KCL, [see our KCL README](https://github.com/KittyCAD/modeling-app/tree/main/src/wasm-lib/kcl).
+
+### Logging
+
+To display logging (to the terminal or console) set `ZOO_LOG=1`. This will log some warnings and simple performance metrics. To view these in test runs, use `-- --nocapture`.
+
+To enable memory metrics, build with `--features dhat-heap`.

src/wasm-lib/Cargo.lock

@@ -774,6 +774,22 @@ dependencies = [
  "syn 2.0.87",
 ]
 
+[[package]]
+name = "dhat"
+version = "0.3.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "98cd11d84628e233de0ce467de10b8633f4ddaecafadefc86e13b84b8739b827"
+dependencies = [
+ "backtrace",
+ "lazy_static",
+ "mintex",
+ "parking_lot 0.12.3",
+ "rustc-hash 1.1.0",
+ "serde",
+ "serde_json",
+ "thousands",
+]
+
 [[package]]
 name = "diff"
 version = "0.1.13"
@@ -1705,6 +1721,7 @@ dependencies = [
  "dashmap 6.1.0",
  "databake",
  "derive-docs",
+ "dhat",
  "expectorate",
  "fnv",
  "form_urlencoded",
@@ -1749,6 +1766,7 @@ dependencies = [
  "wasm-bindgen",
  "wasm-bindgen-futures",
  "web-sys",
+ "web-time",
  "winnow",
  "zip",
 ]
@@ -2056,6 +2074,12 @@ version = "0.5.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e53debba6bda7a793e5f99b8dacf19e626084f525f7829104ba9898f367d85ff"
 
+[[package]]
+name = "mintex"
+version = "0.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9bec4598fddb13cc7b528819e697852653252b760f1228b7642679bf2ff2cd07"
+
 [[package]]
 name = "mio"
 version = "1.0.2"
@@ -2644,7 +2668,7 @@ dependencies = [
  "pin-project-lite",
  "quinn-proto",
  "quinn-udp",
- "rustc-hash",
+ "rustc-hash 2.0.0",
  "rustls",
  "socket2",
  "thiserror 1.0.68",
@@ -2661,7 +2685,7 @@ dependencies = [
  "bytes",
  "rand 0.8.5",
  "ring",
- "rustc-hash",
+ "rustc-hash 2.0.0",
  "rustls",
  "slab",
  "thiserror 1.0.68",
@@ -3001,6 +3025,12 @@ version = "0.1.24"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "719b953e2095829ee67db738b3bfa9fa368c94900df327b3f07fe6e794d2fe1f"
 
+[[package]]
+name = "rustc-hash"
+version = "1.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "08d43f7aa6b08d49f382cde6a7982047c3426db949b1424bc4b7ec9ae12c6ce2"
+
 [[package]]
 name = "rustc-hash"
 version = "2.0.0"
@@ -3637,6 +3667,12 @@ dependencies = [
  "syn 2.0.87",
 ]
 
+[[package]]
+name = "thousands"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3bf63baf9f5039dadc247375c29eb13706706cfde997d0330d05aa63a77d8820"
+
 [[package]]
 name = "thread_local"
 version = "1.1.8"

src/wasm-lib/kcl/Cargo.toml

@@ -21,6 +21,7 @@ convert_case = "0.6.0"
 dashmap = "6.1.0"
 databake = { version = "0.1.8", features = ["derive"] }
 derive-docs = { version = "0.1.29", path = "../derive-docs" }
+dhat = { version = "0.3", optional = true }
 fnv = "1.0.7"
 form_urlencoded = "1.2.1"
 futures = { version = "0.3.31" }
@@ -51,6 +52,7 @@ url = { version = "2.5.3", features = ["serde"] }
 urlencoding = "2.1.3"
 uuid = { version = "1.11.0", features = ["v4", "js", "serde"] }
 validator = { version = "0.19.0", features = ["derive"] }
+web-time = "1.1"
 winnow = "0.6.18"
 zip = { version = "2.0.0", default-features = false }
 
@@ -72,6 +74,7 @@ tower-lsp = { version = "0.20.0", features = ["proposed"] }
 [features]
 default = ["engine"]
 cli = ["dep:clap"]
+dhat-heap = ["dep:dhat"]
 # For the lsp server, when run with stdout for rpc we want to disable println.
 # This is used for editor extensions that use the lsp server.
 disable-println = []

src/wasm-lib/kcl/src/engine/conn.rs

@@ -282,8 +282,8 @@ impl EngineConnection {
                     }
                     Err(e) => {
                         match &e {
-                            WebSocketReadError::Read(e) => eprintln!("could not read from WS: {:?}", e),
-                            WebSocketReadError::Deser(e) => eprintln!("could not deserialize msg from WS: {:?}", e),
+                            WebSocketReadError::Read(e) => crate::logln!("could not read from WS: {:?}", e),
+                            WebSocketReadError::Deser(e) => crate::logln!("could not deserialize msg from WS: {:?}", e),
                         }
                         *socket_health_tcp_read.lock().unwrap() = SocketHealth::Inactive;
                         return Err(e);

src/wasm-lib/kcl/src/executor.rs

@@ -1909,6 +1909,7 @@ impl ExecutorContext {
         program: &Program,
         exec_state: &mut ExecState,
     ) -> Result<Option<ModelingSessionData>, KclError> {
+        let _stats = crate::log::LogPerfStats::new("Interpretation");
         // TODO: Use the top-level file's path.
         exec_state.add_module(std::path::PathBuf::from(""));
         // Before we even start executing the program, set the units.

src/wasm-lib/kcl/src/lib.rs

@@ -8,11 +8,54 @@
 #[allow(unused_macros)]
 macro_rules! println {
     ($($rest:tt)*) => {
+        #[cfg(feature = "disable-println")]
+        {
+            let _ = format!($($rest)*);
+        }
         #[cfg(not(feature = "disable-println"))]
         std::println!($($rest)*)
     }
 }
 
+#[allow(unused_macros)]
+macro_rules! eprintln {
+    ($($rest:tt)*) => {
+        #[cfg(feature = "disable-println")]
+        {
+            let _ = format!($($rest)*);
+        }
+        #[cfg(not(feature = "disable-println"))]
+        std::eprintln!($($rest)*)
+    }
+}
+
+#[allow(unused_macros)]
+macro_rules! print {
+    ($($rest:tt)*) => {
+        #[cfg(feature = "disable-println")]
+        {
+            let _ = format!($($rest)*);
+        }
+        #[cfg(not(feature = "disable-println"))]
+        std::print!($($rest)*)
+    }
+}
+
+#[allow(unused_macros)]
+macro_rules! eprint {
+    ($($rest:tt)*) => {
+        #[cfg(feature = "disable-println")]
+        {
+            let _ = format!($($rest)*);
+        }
+        #[cfg(not(feature = "disable-println"))]
+        std::eprint!($($rest)*)
+    }
+}
+#[cfg(feature = "dhat-heap")]
+#[global_allocator]
+static ALLOC: dhat::Alloc = dhat::Alloc;
+
 mod ast;
 mod coredump;
 mod docs;
@@ -23,6 +66,7 @@ mod fs;
 mod function_param;
 mod kcl_value;
 pub mod lint;
+mod log;
 mod lsp;
 mod parser;
 mod settings;
@@ -71,6 +115,8 @@ pub mod std_utils {
     pub use crate::std::utils::{get_tangential_arc_to_info, is_points_ccw_wasm, TangentialArcInfoInput};
 }
 
+#[allow(unused_imports)]
+use crate::log::{log, logln};
 use serde::{Deserialize, Serialize};
 
 #[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]

src/wasm-lib/kcl/src/log.rs

@@ -0,0 +1,116 @@
+#![allow(dead_code)]
+#[cfg(feature = "dhat-heap")]
+use dhat::{HeapStats, Profiler};
+use std::env;
+use web_time::Instant;
+
+const LOG_ENV_VAR: &str = "ZOO_LOG";
+lazy_static::lazy_static! {
+    static ref ENABLED: bool = {
+        let env_var = env::var(LOG_ENV_VAR);
+        let Ok(env_var) = env_var else {
+            return false;
+        };
+        !env_var.is_empty()
+    };
+}
+
+#[cfg(feature = "dhat-heap")]
+lazy_static::lazy_static! {
+    static ref PROFILER: Profiler = Profiler::builder().testing().build();
+}
+
+/// Log a message
+pub(crate) fn log(msg: impl Into<String>) {
+    if *ENABLED {
+        log_inner(msg.into());
+    }
+}
+
+#[allow(unused_macros)]
+macro_rules! logln {
+    ($($rest:tt)*) => {
+        crate::log::log(format!($($rest)*))
+    }
+}
+pub(crate) use logln;
+
+#[cfg(not(feature = "disable-println"))]
+#[inline]
+fn log_inner(msg: String) {
+    eprintln!("{msg}");
+}
+
+#[cfg(all(feature = "disable-println", target_arch = "wasm32"))]
+#[inline]
+fn log_inner(msg: String) {
+    web_sys::console::log_1(&msg.into());
+}
+
+#[cfg(all(feature = "disable-println", not(target_arch = "wasm32")))]
+#[inline]
+fn log_inner(_msg: String) {}
+
+/// A helper struct for recording and logging basic performance metrics.
+///
+/// It will log the metrics when dropped or if `log_now` is called.
+pub(crate) struct LogPerfStats<'a> {
+    msg: &'a str,
+    start_time: Instant,
+    #[cfg(feature = "dhat-heap")]
+    start_stats: HeapStats,
+    cancelled: bool,
+}
+
+impl<'a> LogPerfStats<'a> {
+    #[cfg(not(feature = "dhat-heap"))]
+    pub fn new(msg: &'a str) -> Self {
+        LogPerfStats {
+            msg,
+            start_time: Instant::now(),
+            cancelled: false,
+        }
+    }
+
+    #[cfg(feature = "dhat-heap")]
+    pub fn new(msg: &'a str) -> Self {
+        lazy_static::initialize(&PROFILER);
+        LogPerfStats {
+            msg,
+            start_time: Instant::now(),
+            start_stats: HeapStats::get(),
+            cancelled: false,
+        }
+    }
+
+    pub fn log_now(&self) {
+        let time = Instant::now().duration_since(self.start_time).as_secs_f64() * 1000.0;
+        logln!("{}\n  time: {time:.3}ms", self.msg);
+        #[cfg(feature = "dhat-heap")]
+        {
+            let stats = HeapStats::get();
+            let blocks = stats.total_blocks - self.start_stats.total_blocks;
+            let bytes = (stats.total_bytes - self.start_stats.total_bytes) as f64 / 1_000_000.0;
+            let cur = stats.curr_bytes as f64 / 1000.0;
+            let max = stats.curr_bytes as f64 / 1000.0;
+
+            logln!("  memory:");
+            logln!("    allocations:          {bytes:.5} MB ({blocks} blocks)");
+            logln!("    currently allocated:  {cur:.3} KB");
+            logln!("    max allocated:        {max:.3} KB");
+        }
+    }
+
+    /// After `cancel`ing, this object will not log its stats on drop (you can still can `log_now`).
+    pub fn cancel(&mut self) {
+        self.cancelled = true;
+    }
+}
+
+impl<'a> Drop for LogPerfStats<'a> {
+    fn drop(&mut self) {
+        if !self.cancelled {
+            self.log_now();
+        }
+    }
+}

src/wasm-lib/kcl/src/parser/parser_impl.rs

@@ -38,6 +38,7 @@ thread_local! {
 pub type TokenSlice<'slice, 'input> = &'slice mut &'input [Token];
 
 pub fn run_parser(i: TokenSlice) -> super::ParseResult {
+    let _stats = crate::log::LogPerfStats::new("Parsing");
     ParseContext::init();
 
     let result = program.parse(i).save_err();