🎉 Add performance measuring functions (#6229)

frontend/deps.edn

@@ -49,7 +49,6 @@
     cider/cider-nrepl {:mvn/version "0.48.0"}}}
 
   :shadow-cljs
-  {:jvm-opts ["--sun-misc-unsafe-memory-access=allow"]
-   :main-opts ["-m" "shadow.cljs.devtools.cli"]}
-
+  {:main-opts ["-m" "shadow.cljs.devtools.cli"]
+   :jvm-opts ["--sun-misc-unsafe-memory-access=allow" "-Dpenpot.wasm.profile-marks=true"]}
   }}

frontend/src/app/render_wasm/api.cljs

@@ -22,6 +22,7 @@
    [app.render-wasm.deserializers :as dr]
    [app.render-wasm.helpers :as h]
    [app.render-wasm.mem :as mem]
+   [app.render-wasm.performance :as perf]
    [app.render-wasm.serializers :as sr]
    [app.render-wasm.wasm :as wasm]
    [app.util.debug :as dbg]
@@ -190,6 +191,7 @@
   [shape-ids]
   (let [num-shapes (count shape-ids)]
     (when (> num-shapes 0)
+      (perf/begin-measure "set-shape-children")
       (let [offset (mem/alloc-bytes (* CHILD-ENTRY-SIZE num-shapes))
             heap (mem/get-heap-u32)]
 
@@ -198,8 +200,11 @@
           (when-not (empty? entries)
             (let [id (first entries)]
               (sr/heapu32-set-uuid id heap (mem/ptr8->ptr32 current-offset))
-              (recur (rest entries) (+ current-offset CHILD-ENTRY-SIZE)))))))
-    (h/call wasm/internal-module "_set_children")))
+              (recur (rest entries) (+ current-offset CHILD-ENTRY-SIZE)))))
+
+        (let [result (h/call wasm/internal-module "_set_children")]
+          (perf/end-measure "set-shape-children")
+          result)))))
 
 (defn- get-string-length [string] (+ (count string) 1))
 
@@ -701,6 +706,7 @@
 
 (defn set-object
   [objects shape]
+  (perf/begin-measure "set-object")
   (let [id           (dm/get-prop shape :id)
         parent-id    (dm/get-prop shape :parent-id)
         type         (dm/get-prop shape :type)
@@ -771,12 +777,15 @@
     (when (ctl/grid-layout? shape)
       (set-grid-layout shape))
 
-    (into [] (concat
-              (if (and (= type :text) (some? content))
-                (set-shape-text-content content)
-                [])
-              (set-shape-fills fills)
-              (set-shape-strokes strokes)))))
+    (let [pending (into [] (concat
+                            (if (and (= type :text) (some? content))
+                              (set-shape-text-content content)
+                              [])
+                            (set-shape-fills fills)
+                            (set-shape-strokes strokes)))]
+      (perf/end-measure "set-object")
+      pending)))
+
 
 (defn process-object
   [shape]
@@ -791,6 +800,7 @@
 
 (defn set-objects
   [objects]
+  (perf/begin-measure "set-objects")
   (let [shapes        (into [] (vals objects))
         total-shapes  (count shapes)
         pending
@@ -800,6 +810,7 @@
                   pending' (set-object objects shape)]
               (recur (inc index) (into pending pending')))
             pending))]
+    (perf/end-measure "set-objects")
     (clear-drawing-cache)
     (request-render "set-objects")
     (when-let [pending (seq pending)]

frontend/src/app/render_wasm/performance.cljc

@@ -0,0 +1,41 @@
+;; This Source Code Form is subject to the terms of the Mozilla Public
+;; License, v. 2.0. If a copy of the MPL was not distributed with this
+;; file, You can obtain one at http://mozilla.org/MPL/2.0/.
+;;
+;; Copyright (c) KALEIDOS INC
+
+(ns app.render-wasm.performance
+  #?(:cljs (:require-macros [app.render-wasm.performance]))
+  (:require
+   [cuerdas.core :as str]))
+
+(defn enabled?
+  []
+  #?(:clj (= (System/getProperty "penpot.wasm.profile-marks") "true")
+     :cljs false))
+
+(defmacro begin-measure
+  [measure-name]
+  (when enabled?
+    (let [measure-name (str/concat measure-name "::begin")]
+      `(.mark js/performance ~measure-name))))
+
+(defmacro end-measure
+  [measure-name & [detail]]
+  (when enabled?
+    (let [begin-name (str/concat measure-name "::begin")
+          end-name (str/concat measure-name "::end")
+          detail `(cljs.core/js-obj ~@(mapcat (fn [[k v]] [(name k) v]) detail))
+          options `(cljs.core/js-obj "start" ~begin-name "end" ~end-name "detail" ~detail)]
+      `(do (.mark js/performance ~end-name)
+           (.measure js/performance ~measure-name ~options)))))
+
+(defmacro with-measure
+  "Measures the time of a function call. This should only be called in synchronous functions"
+  [[measure-name detail] body]
+  (if-not enabled?
+    body
+    `(let [_# (begin-measure ~measure-name)
+           result# ~body
+           _# (end-measure ~measure-name ~detail)]
+       result#)))

render-wasm/Cargo.toml

@@ -6,6 +6,12 @@ repository = "https://github.com/penpot/penpot"
 license-file = "../LICENSE"
 description = "Wasm-based canvas renderer for Penpot"
 
+[features]
+default = ["profile"]
+profile = ["profile-macros", "profile-raf"]
+profile-macros = []
+profile-raf = []
+
 [[bin]]
 name = "render_wasm"
 path = "src/main.rs"

render-wasm/src/emscripten.rs

@@ -26,6 +26,16 @@ macro_rules! run_script_int {
     }};
 }
 
+#[macro_export]
+macro_rules! get_now {
+    () => {{
+        extern "C" {
+            pub fn emscripten_get_now() -> f64;
+        }
+        unsafe { emscripten_get_now() }
+    }};
+}
+
 #[macro_export]
 macro_rules! init_gl {
     () => {{
@@ -43,3 +53,15 @@ macro_rules! init_gl {
         }
     }};
 }
+
+#[allow(unused_imports)]
+pub use run_script;
+
+#[allow(unused_imports)]
+pub use run_script_int;
+
+#[allow(unused_imports)]
+pub use get_now;
+
+#[allow(unused_imports)]
+pub use init_gl;

render-wasm/src/main.rs

@@ -5,6 +5,7 @@ mod debug;
 mod emscripten;
 mod math;
 mod mem;
+mod performance;
 mod render;
 mod shapes;
 mod state;

render-wasm/src/performance.rs

@@ -0,0 +1,166 @@
+use crate::get_now;
+
+#[allow(dead_code)]
+#[cfg(target_arch = "wasm32")]
+pub fn get_time() -> i32 {
+    get_now!() as i32
+}
+
+#[allow(dead_code)]
+#[cfg(not(target_arch = "wasm32"))]
+pub fn get_time() -> i32 {
+    let now = std::time::Instant::now();
+    now.elapsed().as_millis() as i32
+}
+
+#[macro_export]
+macro_rules! mark {
+    ($name:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::run_script;
+            run_script!(format!("performance.mark('{}')", $name));
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! measure {
+    ($name:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::run_script;
+            run_script!(format!("performance.measure('{}')", $name));
+        }
+    };
+    ($name:expr, $mark_begin:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::run_script;
+            run_script!(format!(
+                "performance.measure('{}','{}')",
+                $name, $mark_begin
+            ));
+        }
+    };
+    ($name:expr, $mark_begin:expr, $mark_end:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::run_script;
+            run_script!(format!(
+                "performance.measure('{}','{}','{}')",
+                $name, $mark_begin, $mark_end
+            ));
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! begin_mark_name {
+    ($name:expr) => {
+        format!("{}::begin", $name)
+    };
+}
+
+#[macro_export]
+macro_rules! end_mark_name {
+    ($name:expr) => {
+        format!("{}::end", $name)
+    };
+}
+
+#[macro_export]
+macro_rules! measure_marks {
+    ($name:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::{begin_mark_name, end_mark_name, measure};
+            measure!($name, begin_mark_name!($name), end_mark_name!($name));
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! clear_marks {
+    () => {
+        use crate::run_script;
+        run_script!("performance.clearMarks()");
+    };
+    ($($name:expr),*) => {
+        format!("{}", [$(format!("performance.clearMarks('{}')", $name)),*].join("; "))
+    };
+}
+
+#[macro_export]
+macro_rules! clear_measures {
+    () => {
+        use crate::run_script;
+        run_script!("performance.clearMeasures()");
+    };
+    ($($name:expr),*) => {
+        format!("{}", [$(format!("performance.clearMeasures('{}')", $name)),*].join("; "))
+    };
+}
+
+#[macro_export]
+macro_rules! begin_measure {
+    ($name:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::{begin_mark_name, mark};
+            mark!(begin_mark_name!($name));
+        }
+    };
+    ($name:expr, $clear_marks:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::{begin_mark_name, clear_marks, end_mark_name, mark};
+            if $clear_marks {
+                clear_marks!(begin_mark_name!($name), end_mark_name($name));
+            }
+            mark!(begin_mark_name!($name));
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! end_measure {
+    ($name:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::{end_mark_name, mark, measure_marks};
+            mark!(end_mark_name!($name));
+            measure_marks!($name);
+        }
+    };
+    ($name:expr, $clear_marks:expr) => {
+        #[cfg(all(feature = "profile-macros", target_arch = "wasm32"))]
+        {
+            use crate::{begin_mark_name, clear_marks, end_mark_name, mark, measure_marks};
+            mark!(end_mark_name!($name));
+            measure_marks!($name);
+            if $clear_marks {
+                clear_marks!(begin_mark_name!($name), end_mark_name($name));
+            }
+        }
+    };
+}
+
+// We need to reexport the macro to make it public.
+#[allow(unused_imports)]
+pub use clear_marks;
+
+#[allow(unused_imports)]
+pub use clear_measures;
+
+#[allow(unused_imports)]
+pub use mark;
+
+#[allow(unused_imports)]
+pub use measure;
+
+#[allow(unused_imports)]
+pub use begin_measure;
+
+#[allow(unused_imports)]
+pub use end_measure;

render-wasm/src/render.rs

@@ -3,6 +3,7 @@ use skia_safe::{self as skia, Matrix, RRect, Rect};
 use crate::uuid::Uuid;
 use std::collections::HashMap;
 
+use crate::performance;
 use crate::view::Viewbox;
 #[cfg(target_arch = "wasm32")]
 use crate::{run_script, run_script_int};
@@ -34,17 +35,6 @@ const VIEWPORT_INTEREST_AREA_THRESHOLD: i32 = 1;
 const MAX_BLOCKING_TIME_MS: i32 = 32;
 const NODE_BATCH_THRESHOLD: i32 = 10;
 
-#[cfg(target_arch = "wasm32")]
-fn get_time() -> i32 {
-    run_script_int!("performance.now()")
-}
-
-#[cfg(not(target_arch = "wasm32"))]
-fn get_time() -> i32 {
-    let now = std::time::Instant::now();
-    now.elapsed().as_millis() as i32
-}
-
 pub struct NodeRenderState {
     pub id: Uuid,
     // We use this bool to keep that we've traversed all the children inside this node.
@@ -220,6 +210,7 @@ impl RenderState {
     }
 
     pub fn apply_drawing_to_render_canvas(&mut self, shape: Option<&Shape>) {
+        performance::begin_measure!("apply_drawing_to_render_canvas");
         self.surfaces
             .flush_and_submit(&mut self.gpu_state, SurfaceId::DropShadows);
 
@@ -445,6 +436,8 @@ impl RenderState {
                 self.cancel_animation_frame(frame_id);
             }
         }
+        performance::begin_measure!("render");
+        performance::begin_measure!("start_render_loop");
         let scale = self.get_scale();
         self.reset_canvas();
         self.surfaces.apply_mut(
@@ -468,6 +461,8 @@ impl RenderState {
         let (sx, sy, ex, ey) = tiles::get_tiles_for_viewbox(self.viewbox);
         debug::render_debug_tiles_for_viewbox(self, isx, isy, iex, iey);
         let tile_center = ((iex - isx) / 2, (iey - isy) / 2);
+
+        performance::begin_measure!("tile_cache");
         self.pending_tiles = vec![];
         self.surfaces.cache_clear_visited();
         for y in isy..=iey {
@@ -475,7 +470,7 @@ impl RenderState {
                 let tile = (x, y);
                 let distance = tiles::manhattan_distance(tile, tile_center);
                 self.pending_tiles.push((x, y, distance));
-                // We only need to mark as visited the visible
+                // We only need to mark! as visited the visible
                 // tiles, the ones that are outside the viewport
                 // should not be rendered.
                 if x >= sx && x <= ex && y >= sy && y <= ey {
@@ -483,6 +478,8 @@ impl RenderState {
                 }
             }
         }
+        performance::end_measure!("tile_cache");
+
         self.pending_nodes = vec![];
         // reorder by distance to the center.
         self.pending_tiles.sort_by(|a, b| b.2.cmp(&a.2));
@@ -490,11 +487,14 @@ impl RenderState {
         self.render_in_progress = true;
         self.apply_drawing_to_render_canvas(None);
         self.process_animation_frame(tree, modifiers, timestamp)?;
+        performance::end_measure!("start_render_loop");
         Ok(())
     }
 
     #[cfg(target_arch = "wasm32")]
     pub fn request_animation_frame(&mut self) -> i32 {
+        #[cfg(feature = "profile-raf")]
+        performance::mark!("request_animation_frame");
         run_script_int!("requestAnimationFrame(_process_animation_frame)")
     }
 
@@ -505,6 +505,8 @@ impl RenderState {
 
     #[cfg(target_arch = "wasm32")]
     pub fn cancel_animation_frame(&mut self, frame_id: i32) {
+        #[cfg(feature = "profile-raf")]
+        performance::mark!("cancel_animation_frame");
         run_script!(format!("cancelAnimationFrame({})", frame_id))
     }
 
@@ -517,6 +519,7 @@ impl RenderState {
         modifiers: &HashMap<Uuid, Matrix>,
         timestamp: i32,
     ) -> Result<(), String> {
+        performance::begin_measure!("process_animation_frame");
         if self.render_in_progress {
             self.render_shape_tree(tree, modifiers, timestamp)?;
             self.flush();
@@ -526,16 +529,19 @@ impl RenderState {
                     self.cancel_animation_frame(frame_id);
                 }
                 self.render_request_id = Some(self.request_animation_frame());
+            } else {
+                performance::end_measure!("render");
             }
         }
+        performance::end_measure!("process_animation_frame");
         Ok(())
     }
 
     pub fn render_shape_enter(&mut self, element: &mut Shape, mask: bool) {
         // Masked groups needs two rendering passes, the first one rendering
         // the content and the second one rendering the mask so we need to do
-        // an extra save_layer to keep all the masked group separate from other
-        // already drawn elements.
+        // an extra save_layer to keep all the masked group separate from
+        // other already drawn elements.
         match element.shape_type {
             Type::Group(group) => {
                 if group.masked {
@@ -620,9 +626,11 @@ impl RenderState {
         while !should_stop {
             if let Some(current_tile) = self.current_tile {
                 if self.surfaces.has_cached_tile_surface(current_tile) {
+                    performance::begin_measure!("render_shape_tree::cached");
                     let tile_rect = self.get_current_tile_bounds();
                     self.surfaces
                         .draw_cached_tile_surface(current_tile, tile_rect);
+                    performance::end_measure!("render_shape_tree::cached");
 
                     if self.options.is_debug_visible() {
                         debug::render_workspace_current_tile(
@@ -633,6 +641,7 @@ impl RenderState {
                         );
                     }
                 } else {
+                    performance::begin_measure!("render_shape_tree::uncached");
                     let mut i = 0;
                     let mut is_empty = true;
                     while let Some(node_render_state) = self.pending_nodes.pop() {
@@ -745,12 +754,13 @@ impl RenderState {
 
                         // We try to avoid doing too many calls to get_time
                         if i % NODE_BATCH_THRESHOLD == 0
-                            && get_time() - timestamp > MAX_BLOCKING_TIME_MS
+                            && performance::get_time() - timestamp > MAX_BLOCKING_TIME_MS
                         {
                             return Ok(());
                         }
                         i += 1;
                     }
+                    performance::end_measure!("render_shape_tree::uncached");
                     let tile_rect = self.get_current_tile_bounds();
                     if !is_empty {
                         self.apply_render_to_final_canvas(tile_rect);
@@ -850,6 +860,7 @@ impl RenderState {
         tree: &mut HashMap<Uuid, Shape>,
         modifiers: &HashMap<Uuid, Matrix>,
     ) {
+        performance::begin_measure!("rebuild_tiles");
         self.tiles.invalidate();
         self.surfaces.remove_cached_tiles();
         let mut nodes = vec![Uuid::nil()];
@@ -867,6 +878,7 @@ impl RenderState {
                 }
             }
         }
+        performance::end_measure!("rebuild_tiles");
     }
 
     pub fn rebuild_modifier_tiles(