🔧 Log performance when building using profile-macros

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
+  (let [is-pan (mth/close? prev-zoom zoom)]
-  ;; This will be disabled when render-finish fires (after debounce delay)
+    (perf/begin-measure "set-view-box")
-  (h/call wasm/internal-module "_set_view_start")
+    (h/call wasm/internal-module "_set_view_start")
-  (h/call wasm/internal-module "_set_view" zoom (- (:x vbox)) (- (:y vbox)))
+    (h/call wasm/internal-module "_set_view" zoom (- (:x vbox)) (- (:y vbox)))
 
-  (if (mth/close? prev-zoom zoom)
+    (if is-pan
-    (do (render-pan)
+      (do (perf/end-measure "set-view-box")
-        (render-finish))
+          (perf/begin-measure "set-view-box::pan")
-    (do (h/call wasm/internal-module "_render_from_cache" 0)
+          (render-pan)
-        (render-finish))))
+          (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]

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.
+#[cfg(feature = "profile-macros")]
-/// In fast mode, expensive operations like shadows are skipped for better performance.
+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
+            );
         }
     });
 }

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) => {

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
     }

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.
+    /// Use fast mode to enable / disable expensive operations
-    /// When active, expensive operations like shadows are skipped for better performance.
     pub fn is_fast_mode(&self) -> bool {
         self.flags & options::FAST_MODE == options::FAST_MODE
     }