From d880307a9bd3d7930f78c47593637fd442edd265 Mon Sep 17 00:00:00 2001 From: Aitor Moreno Date: Thu, 10 Apr 2025 11:33:22 +0200 Subject: [PATCH] :tada: Add performance measuring functions (#6229) --- frontend/deps.edn | 5 +- frontend/src/app/render_wasm/api.cljs | 27 ++- frontend/src/app/render_wasm/performance.cljc | 41 +++++ render-wasm/Cargo.toml | 6 + render-wasm/src/emscripten.rs | 22 +++ render-wasm/src/main.rs | 1 + render-wasm/src/performance.rs | 166 ++++++++++++++++++ render-wasm/src/render.rs | 42 +++-- 8 files changed, 284 insertions(+), 26 deletions(-) create mode 100644 frontend/src/app/render_wasm/performance.cljc create mode 100644 render-wasm/src/performance.rs diff --git a/frontend/deps.edn b/frontend/deps.edn index 6a514ce23..24ea5efa5 100644 --- a/frontend/deps.edn +++ b/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"]} }} diff --git a/frontend/src/app/render_wasm/api.cljs b/frontend/src/app/render_wasm/api.cljs index 4825d3383..726e3d4d2 100644 --- a/frontend/src/app/render_wasm/api.cljs +++ b/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)] diff --git a/frontend/src/app/render_wasm/performance.cljc b/frontend/src/app/render_wasm/performance.cljc new file mode 100644 index 000000000..95c39c446 --- /dev/null +++ b/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#))) diff --git a/render-wasm/Cargo.toml b/render-wasm/Cargo.toml index 835423948..62543fd94 100644 --- a/render-wasm/Cargo.toml +++ b/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" diff --git a/render-wasm/src/emscripten.rs b/render-wasm/src/emscripten.rs index 43f0d45a9..69c4b9cfc 100644 --- a/render-wasm/src/emscripten.rs +++ b/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; diff --git a/render-wasm/src/main.rs b/render-wasm/src/main.rs index 17b23eef5..55b3ba70a 100644 --- a/render-wasm/src/main.rs +++ b/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; diff --git a/render-wasm/src/performance.rs b/render-wasm/src/performance.rs new file mode 100644 index 000000000..92292d9d4 --- /dev/null +++ b/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; diff --git a/render-wasm/src/render.rs b/render-wasm/src/render.rs index df75c7279..da08c37c6 100644 --- a/render-wasm/src/render.rs +++ b/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, 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, modifiers: &HashMap, ) { + 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(