diff --git a/README.md b/README.md index 2d4e08a22..4a7bfd51b 100644 --- a/README.md +++ b/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`. diff --git a/src/wasm-lib/Cargo.lock b/src/wasm-lib/Cargo.lock index 1ba437775..b4ad250ef 100644 --- a/src/wasm-lib/Cargo.lock +++ b/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" diff --git a/src/wasm-lib/kcl/Cargo.toml b/src/wasm-lib/kcl/Cargo.toml index 1992a0243..0285e1c43 100644 --- a/src/wasm-lib/kcl/Cargo.toml +++ b/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 = [] diff --git a/src/wasm-lib/kcl/src/engine/conn.rs b/src/wasm-lib/kcl/src/engine/conn.rs index 3df07bade..fdb429999 100644 --- a/src/wasm-lib/kcl/src/engine/conn.rs +++ b/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); diff --git a/src/wasm-lib/kcl/src/executor.rs b/src/wasm-lib/kcl/src/executor.rs index 4be8ee5a8..04ca70af1 100644 --- a/src/wasm-lib/kcl/src/executor.rs +++ b/src/wasm-lib/kcl/src/executor.rs @@ -1909,6 +1909,7 @@ impl ExecutorContext { program: &Program, exec_state: &mut ExecState, ) -> Result, 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. diff --git a/src/wasm-lib/kcl/src/lib.rs b/src/wasm-lib/kcl/src/lib.rs index 8d3f9d68d..259c10857 100644 --- a/src/wasm-lib/kcl/src/lib.rs +++ b/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)] diff --git a/src/wasm-lib/kcl/src/log.rs b/src/wasm-lib/kcl/src/log.rs new file mode 100644 index 000000000..0fa2bf8c6 --- /dev/null +++ b/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) { + 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(); + } + } +} diff --git a/src/wasm-lib/kcl/src/parser/parser_impl.rs b/src/wasm-lib/kcl/src/parser/parser_impl.rs index 4baec59c7..9f23d51c3 100644 --- a/src/wasm-lib/kcl/src/parser/parser_impl.rs +++ b/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();