From 81bc1bb0af12f7cc7ecad0f2337f640554411875 Mon Sep 17 00:00:00 2001 From: Elena Torro Date: Tue, 9 Dec 2025 12:06:59 +0100 Subject: [PATCH] :wrench: Log performance when building using profile-macros --- frontend/src/app/render_wasm/api.cljs | 34 +++++++++----- render-wasm/src/main.rs | 36 +++++++++++++-- render-wasm/src/performance.rs | 66 +++++++++++++++++++++++++-- render-wasm/src/render.rs | 10 +++- render-wasm/src/render/options.rs | 3 +- 5 files changed, 125 insertions(+), 24 deletions(-) diff --git a/frontend/src/app/render_wasm/api.cljs b/frontend/src/app/render_wasm/api.cljs index d291566ae8..11d0ee71f3 100644 --- a/frontend/src/app/render_wasm/api.cljs +++ b/frontend/src/app/render_wasm/api.cljs @@ -874,25 +874,37 @@ (def render-finish (letfn [(do-render [ts] + (perf/begin-measure "render-finish") (h/call wasm/internal-module "_set_view_end") - (render ts))] + (render ts) + (perf/end-measure "render-finish"))] (fns/debounce do-render DEBOUNCE_DELAY_MS))) (def render-pan - (fns/throttle render THROTTLE_DELAY_MS)) + (letfn [(do-render-pan [ts] + (perf/begin-measure "render-pan") + (render ts) + (perf/end-measure "render-pan"))] + (fns/throttle do-render-pan THROTTLE_DELAY_MS))) (defn set-view-box [prev-zoom zoom vbox] - ;; Enable fast mode at the start of pan/zoom interaction - ;; This will be disabled when render-finish fires (after debounce delay) - (h/call wasm/internal-module "_set_view_start") - (h/call wasm/internal-module "_set_view" zoom (- (:x vbox)) (- (:y vbox))) + (let [is-pan (mth/close? prev-zoom zoom)] + (perf/begin-measure "set-view-box") + (h/call wasm/internal-module "_set_view_start") + (h/call wasm/internal-module "_set_view" zoom (- (:x vbox)) (- (:y vbox))) - (if (mth/close? prev-zoom zoom) - (do (render-pan) - (render-finish)) - (do (h/call wasm/internal-module "_render_from_cache" 0) - (render-finish)))) + (if is-pan + (do (perf/end-measure "set-view-box") + (perf/begin-measure "set-view-box::pan") + (render-pan) + (render-finish) + (perf/end-measure "set-view-box::pan")) + (do (perf/end-measure "set-view-box") + (perf/begin-measure "set-view-box::zoom") + (h/call wasm/internal-module "_render_from_cache" 0) + (render-finish) + (perf/end-measure "set-view-box::zoom"))))) (defn set-object [objects shape] diff --git a/render-wasm/src/main.rs b/render-wasm/src/main.rs index 1039f30aa8..1280028997 100644 --- a/render-wasm/src/main.rs +++ b/render-wasm/src/main.rs @@ -230,36 +230,62 @@ pub extern "C" fn resize_viewbox(width: i32, height: i32) { #[no_mangle] pub extern "C" fn set_view(zoom: f32, x: f32, y: f32) { with_state_mut!(state, { + performance::begin_measure!("set_view"); let render_state = state.render_state_mut(); render_state.set_view(zoom, x, y); + performance::end_measure!("set_view"); }); } -/// Called at the start of pan/zoom interaction to enable fast rendering mode. -/// In fast mode, expensive operations like shadows are skipped for better performance. +#[cfg(feature = "profile-macros")] +static mut VIEW_INTERACTION_START: i32 = 0; + #[no_mangle] pub extern "C" fn set_view_start() { with_state_mut!(state, { + #[cfg(feature = "profile-macros")] + unsafe { + VIEW_INTERACTION_START = performance::get_time(); + } + performance::begin_measure!("set_view_start"); state.render_state.options.set_fast_mode(true); + performance::end_measure!("set_view_start"); }); } #[no_mangle] pub extern "C" fn set_view_end() { with_state_mut!(state, { - // Disable fast mode when interaction ends + let _end_start = performance::begin_timed_log!("set_view_end"); + performance::begin_measure!("set_view_end"); state.render_state.options.set_fast_mode(false); - // We can have renders in progress state.render_state.cancel_animation_frame(); + + let zoom_changed = state.render_state.zoom_changed(); // Only rebuild tile indices when zoom has changed. // During pan-only operations, shapes stay in the same tiles // because tile_size = 1/scale * TILE_SIZE (depends only on zoom). - if state.render_state.zoom_changed() { + if zoom_changed { + let _rebuild_start = performance::begin_timed_log!("rebuild_tiles"); + performance::begin_measure!("set_view_end::rebuild_tiles"); if state.render_state.options.is_profile_rebuild_tiles() { state.rebuild_tiles(); } else { state.rebuild_tiles_shallow(); } + performance::end_measure!("set_view_end::rebuild_tiles"); + performance::end_timed_log!("rebuild_tiles", _rebuild_start); + } + performance::end_measure!("set_view_end"); + performance::end_timed_log!("set_view_end", _end_start); + #[cfg(feature = "profile-macros")] + { + let total_time = performance::get_time() - unsafe { VIEW_INTERACTION_START }; + performance::console_log!( + "[PERF] view_interaction (zoom_changed={}): {}ms", + zoom_changed, + total_time + ); } }); } diff --git a/render-wasm/src/performance.rs b/render-wasm/src/performance.rs index 0d508b1b89..6f9eb233de 100644 --- a/render-wasm/src/performance.rs +++ b/render-wasm/src/performance.rs @@ -1,7 +1,3 @@ -#[allow(unused_imports)] -#[cfg(target_arch = "wasm32")] -use crate::get_now; - #[allow(dead_code)] #[cfg(target_arch = "wasm32")] pub fn get_time() -> i32 { @@ -15,6 +11,68 @@ pub fn get_time() -> i32 { now.elapsed().as_millis() as i32 } +/// Log a message to the browser console (only when profile-macros feature is enabled) +#[macro_export] +macro_rules! console_log { + ($($arg:tt)*) => { + #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))] + { + use $crate::run_script; + run_script!(format!("console.log('{}')", format!($($arg)*))); + } + #[cfg(all(feature = "profile-macros", not(target_arch = "wasm32")))] + { + println!($($arg)*); + } + }; +} + +/// Begin a timed section with logging (only when profile-macros feature is enabled) +/// Returns the start time - store it and pass to end_timed_log! +#[macro_export] +macro_rules! begin_timed_log { + ($name:expr) => {{ + #[cfg(feature = "profile-macros")] + { + $crate::performance::get_time() + } + #[cfg(not(feature = "profile-macros"))] + { + 0.0 + } + }}; +} + +/// End a timed section and log the duration (only when profile-macros feature is enabled) +#[macro_export] +macro_rules! end_timed_log { + ($name:expr, $start:expr) => {{ + #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))] + { + let duration = $crate::performance::get_time() - $start; + use $crate::run_script; + run_script!(format!( + "console.log('[PERF] {}: {:.2}ms')", + $name, duration + )); + } + #[cfg(all(feature = "profile-macros", not(target_arch = "wasm32")))] + { + let duration = $crate::performance::get_time() - $start; + println!("[PERF] {}: {:.2}ms", $name, duration); + } + }}; +} + +#[allow(unused_imports)] +pub use console_log; + +#[allow(unused_imports)] +pub use begin_timed_log; + +#[allow(unused_imports)] +pub use end_timed_log; + #[macro_export] macro_rules! mark { ($name:expr) => { diff --git a/render-wasm/src/render.rs b/render-wasm/src/render.rs index cc743f79af..86e338f7c2 100644 --- a/render-wasm/src/render.rs +++ b/render-wasm/src/render.rs @@ -928,6 +928,8 @@ impl RenderState { } pub fn render_from_cache(&mut self, shapes: ShapesPoolRef) { + let _start = performance::begin_timed_log!("render_from_cache"); + performance::begin_measure!("render_from_cache"); let scale = self.get_cached_scale(); if let Some(snapshot) = &self.cached_target_snapshot { let canvas = self.surfaces.canvas(SurfaceId::Target); @@ -965,6 +967,8 @@ impl RenderState { self.flush_and_submit(); } + performance::end_measure!("render_from_cache"); + performance::end_timed_log!("render_from_cache", _start); } pub fn start_render_loop( @@ -974,6 +978,7 @@ impl RenderState { timestamp: i32, sync_render: bool, ) -> Result<(), String> { + let _start = performance::begin_timed_log!("start_render_loop"); let scale = self.get_scale(); self.tile_viewbox.update(self.viewbox, scale); @@ -1004,10 +1009,12 @@ impl RenderState { // FIXME - review debug // debug::render_debug_tiles_for_viewbox(self); + let _tile_start = performance::begin_timed_log!("tile_cache_update"); performance::begin_measure!("tile_cache"); self.pending_tiles .update(&self.tile_viewbox, &self.surfaces); performance::end_measure!("tile_cache"); + performance::end_timed_log!("tile_cache_update", _tile_start); self.pending_nodes.clear(); if self.pending_nodes.capacity() < tree.len() { @@ -1031,6 +1038,7 @@ impl RenderState { } performance::end_measure!("start_render_loop"); + performance::end_timed_log!("start_render_loop", _start); Ok(()) } @@ -2057,8 +2065,6 @@ impl RenderState { self.cached_viewbox.zoom() * self.options.dpr() } - /// Returns true if the zoom level has changed since the last cached viewbox. - /// Used to optimize pan-only operations where tile indices don't need to be rebuilt. pub fn zoom_changed(&self) -> bool { (self.viewbox.zoom - self.cached_viewbox.zoom).abs() > f32::EPSILON } diff --git a/render-wasm/src/render/options.rs b/render-wasm/src/render/options.rs index 7e87f9e80f..9dd57309e7 100644 --- a/render-wasm/src/render/options.rs +++ b/render-wasm/src/render/options.rs @@ -15,8 +15,7 @@ impl RenderOptions { self.flags & options::PROFILE_REBUILD_TILES == options::PROFILE_REBUILD_TILES } - /// Fast mode is enabled during interactive pan/zoom operations. - /// When active, expensive operations like shadows are skipped for better performance. + /// Use fast mode to enable / disable expensive operations pub fn is_fast_mode(&self) -> bool { self.flags & options::FAST_MODE == options::FAST_MODE }