From 3b98fbf70a6bd31dc8b2bceec7d24deb5ae32743 Mon Sep 17 00:00:00 2001 From: Alejandro Alonso Date: Mon, 3 Aug 2026 08:33:54 +0200 Subject: [PATCH] :construction: Add temporary ZOOM-PERF instrumentation for HQ profiling Log set_view_end and progressive tile/region walk timings to the console so post-zoom ViewportReady cost can be broken down while tuning the paint-once path. Remove before merging to develop. --- render-wasm/src/main.rs | 20 +- render-wasm/src/render.rs | 478 ++++++++++++++++++++++++++++- render-wasm/src/render/surfaces.rs | 40 +++ 3 files changed, 534 insertions(+), 4 deletions(-) diff --git a/render-wasm/src/main.rs b/render-wasm/src/main.rs index 2d007d18e4..c34313bcf9 100644 --- a/render-wasm/src/main.rs +++ b/render-wasm/src/main.rs @@ -358,16 +358,31 @@ pub extern "C" fn set_view_end() -> Result<()> { render_state.options.set_fast_mode(false); render_state.tile_viewbox.update(&render_state.viewbox); + let zoom_changed = render_state.zoom_changed(); + if zoom_changed { + render_state.zoom_perf_begin("set_view_end"); + } + if render_state.options.is_profile_rebuild_tiles() { state.rebuild_tiles(); - } else if render_state.zoom_changed() { + } else if zoom_changed { // Zoom changed: tile sizes differ so all cached tile // textures are invalid (wrong scale). Rebuild the tile // index and clear the tile texture cache, but *preserve* // the cache canvas so render_from_cache can show a scaled // preview of the old content while new tiles render. + let t0 = performance::get_time(); render_state.rebuild_tile_index(&state.shapes); + render_state.zoom_perf_log(&format!( + "set_view_end.rebuild_tile_index {}ms", + performance::get_time() - t0 + )); + let t1 = performance::get_time(); render_state.surfaces.invalidate_tile_cache(); + render_state.zoom_perf_log(&format!( + "set_view_end.invalidate_tile_cache {}ms", + performance::get_time() - t1 + )); } else { // Pure pan at the same zoom level: tile contents have not // changed — only the viewport position moved. Update the @@ -380,6 +395,9 @@ pub extern "C" fn set_view_end() -> Result<()> { if !render_state.options.is_profile_rebuild_tiles() { render_state.preserve_target_during_render = true; } + if zoom_changed { + render_state.zoom_perf_log("set_view_end done"); + } performance::end_measure!("set_view_end"); }); Ok(()) diff --git a/render-wasm/src/render.rs b/render-wasm/src/render.rs index b04c3a5dcf..9a44a7529a 100644 --- a/render-wasm/src/render.rs +++ b/render-wasm/src/render.rs @@ -425,6 +425,32 @@ pub(crate) struct RenderState { /// Visible tiles were already presented this pass; interest-ring fill may /// still be running. Final Full should not re-present. pub viewport_presented: bool, + /// Temporary: log post-zoom timings to the console (`[ZOOM-PERF]`). + zoom_perf_active: bool, + zoom_perf_t0: i32, + zoom_perf_frame: u32, + /// Per tile-chunk walker breakdown (reset before each uncached pass). + zoom_perf_shape_ms: i32, + zoom_perf_text_ms: i32, + zoom_perf_shadow_ms: i32, + zoom_perf_blur_ms: i32, + zoom_perf_enter_ms: i32, + zoom_perf_shadow_warmup_ms: i32, + zoom_perf_nodes: u32, + zoom_perf_text_nodes: u32, + zoom_perf_shadow_nodes: u32, + zoom_perf_direct_n: u32, + zoom_perf_layered_n: u32, + zoom_perf_fills_ms: i32, + zoom_perf_strokes_ms: i32, + zoom_perf_blit_ms: i32, + /// Layered deny reason counters (first-match; only when zoom_perf_active). + zoom_perf_layered_type_n: u32, + zoom_perf_layered_shadow_n: u32, + zoom_perf_layered_blur_n: u32, + zoom_perf_layered_blend_n: u32, + zoom_perf_layered_nested_n: u32, + zoom_perf_layered_other_n: u32, /// Multi-tile paint-once into Current, then crop to atlas slots. paint_region: Option, } @@ -619,10 +645,124 @@ impl RenderState { tile_atlas_flushed: false, drop_shadows_ops_warmed: false, viewport_presented: false, + zoom_perf_active: false, + zoom_perf_t0: 0, + zoom_perf_frame: 0, + zoom_perf_shape_ms: 0, + zoom_perf_text_ms: 0, + zoom_perf_shadow_ms: 0, + zoom_perf_blur_ms: 0, + zoom_perf_enter_ms: 0, + zoom_perf_shadow_warmup_ms: 0, + zoom_perf_nodes: 0, + zoom_perf_text_nodes: 0, + zoom_perf_shadow_nodes: 0, + zoom_perf_direct_n: 0, + zoom_perf_layered_n: 0, + zoom_perf_fills_ms: 0, + zoom_perf_strokes_ms: 0, + zoom_perf_blit_ms: 0, + zoom_perf_layered_type_n: 0, + zoom_perf_layered_shadow_n: 0, + zoom_perf_layered_blur_n: 0, + zoom_perf_layered_blend_n: 0, + zoom_perf_layered_nested_n: 0, + zoom_perf_layered_other_n: 0, paint_region: None, }) } + /// Temporary zoom profiling: println with ms since zoom-end started. + #[inline] + pub fn zoom_perf_log(&self, msg: &str) { + if !self.zoom_perf_active { + return; + } + let dt = performance::get_time() - self.zoom_perf_t0; + println!("[ZOOM-PERF] +{dt}ms {msg}"); + } + + fn zoom_perf_reset_walker(&mut self) { + self.zoom_perf_shape_ms = 0; + self.zoom_perf_text_ms = 0; + self.zoom_perf_shadow_ms = 0; + self.zoom_perf_blur_ms = 0; + self.zoom_perf_enter_ms = 0; + self.zoom_perf_shadow_warmup_ms = 0; + self.zoom_perf_nodes = 0; + self.zoom_perf_text_nodes = 0; + self.zoom_perf_shadow_nodes = 0; + self.zoom_perf_direct_n = 0; + self.zoom_perf_layered_n = 0; + self.zoom_perf_fills_ms = 0; + self.zoom_perf_strokes_ms = 0; + self.zoom_perf_blit_ms = 0; + self.zoom_perf_layered_type_n = 0; + self.zoom_perf_layered_shadow_n = 0; + self.zoom_perf_layered_blur_n = 0; + self.zoom_perf_layered_blend_n = 0; + self.zoom_perf_layered_nested_n = 0; + self.zoom_perf_layered_other_n = 0; + self.surfaces.reset_paint_diag_counters(); + } + + fn zoom_perf_walker_summary(&self) -> String { + format!( + "nodes={} text_n={} shadow_n={} direct={} layered={} (type={} shadow={} blur={} blend={} nested={} other={}) shape={}ms text={}ms fills={}ms strokes={}ms blit={}ms shadow={}ms blur={}ms enter={}ms shadow_warm={}ms | {}", + self.zoom_perf_nodes, + self.zoom_perf_text_nodes, + self.zoom_perf_shadow_nodes, + self.zoom_perf_direct_n, + self.zoom_perf_layered_n, + self.zoom_perf_layered_type_n, + self.zoom_perf_layered_shadow_n, + self.zoom_perf_layered_blur_n, + self.zoom_perf_layered_blend_n, + self.zoom_perf_layered_nested_n, + self.zoom_perf_layered_other_n, + self.zoom_perf_shape_ms, + self.zoom_perf_text_ms, + self.zoom_perf_fills_ms, + self.zoom_perf_strokes_ms, + self.zoom_perf_blit_ms, + self.zoom_perf_shadow_ms, + self.zoom_perf_blur_ms, + self.zoom_perf_enter_ms, + self.zoom_perf_shadow_warmup_ms, + self.surfaces.paint_diag_summary() + ) + } + + pub fn zoom_perf_begin(&mut self, reason: &str) { + self.zoom_perf_active = true; + self.zoom_perf_t0 = performance::get_time(); + self.zoom_perf_frame = 0; + self.surfaces.set_paint_diag(true); + println!( + "[ZOOM-PERF] BEGIN {reason} zoom={:.4} vbox=({:.1},{:.1},{:.1}x{:.1}) {}", + self.viewbox.zoom, + self.viewbox.area.left, + self.viewbox.area.top, + self.viewbox.area.width(), + self.viewbox.area.height(), + self.surfaces.paint_diag_summary() + ); + } + + pub fn zoom_perf_end(&mut self, reason: &str) { + if !self.zoom_perf_active { + return; + } + let dt = performance::get_time() - self.zoom_perf_t0; + println!( + "[ZOOM-PERF] END {reason} total={dt}ms frames={} {}", + self.zoom_perf_frame, + self.surfaces.paint_diag_summary() + ); + self.surfaces.set_paint_diag(false); + self.zoom_perf_active = false; + } + /// Combines every visible layer blur currently active (ancestors + shape) /// into a single equivalent blur. Layer blur radii compound by adding their /// variances (σ² = radius²), so we: @@ -1145,6 +1285,11 @@ impl RenderState { /// This function draws the "surface stack" into the specified "target" surface. pub fn draw_shape_surface_stack_into(&mut self, shape: Option<&Shape>, target: SurfaceId) { performance::begin_measure!("apply_drawing_to_render_canvas"); + let t_blit = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; let paint = skia::Paint::default(); @@ -1202,6 +1347,9 @@ impl RenderState { self.surfaces.clear_dirty(dirty_surfaces_to_clear); } + if self.zoom_perf_active { + self.zoom_perf_blit_ms += performance::get_time() - t_blit; + } } pub fn clear_focus_mode(&mut self) { @@ -1439,13 +1587,27 @@ impl RenderState { }); } + let zoom_perf = self.zoom_perf_active; + let t_fills = if zoom_perf { + performance::get_time() + } else { + 0 + }; fills::render(self, shape, &shape.fills, antialias, target_surface, None)?; + if zoom_perf { + self.zoom_perf_fills_ms += performance::get_time() - t_fills; + } // Clipped frames draw strokes in render_shape_exit over children. let skip_strokes = matches!(shape.shape_type, Type::Frame(_)) && shape.clip_content; if !skip_strokes { // Pass strokes in natural order; stroke merging handles top-most ordering internally. let visible_strokes: Vec<&Stroke> = shape.visible_strokes().collect(); + let t_strokes = if zoom_perf { + performance::get_time() + } else { + 0 + }; strokes::render( self, shape, @@ -1454,6 +1616,12 @@ impl RenderState { antialias, outset, )?; + if zoom_perf { + self.zoom_perf_strokes_ms += performance::get_time() - t_strokes; + } + } + if zoom_perf { + self.zoom_perf_direct_n += 1; } self.surfaces.apply_mut(target_surface as u32, |s| { @@ -1468,6 +1636,28 @@ impl RenderState { return Ok(()); } + if self.zoom_perf_active { + self.zoom_perf_layered_n += 1; + // Count the first matching deny reason. + if !type_ok { + self.zoom_perf_layered_type_n += 1; + } else if shadows_need_layered { + self.zoom_perf_layered_shadow_n += 1; + } else if shape.blur.is_some() + || shape.background_blur.is_some() + || has_inherited_blur + || shape.has_frame_clip_layer_blur() + { + self.zoom_perf_layered_blur_n += 1; + } else if shape.blend_mode().0 != skia::BlendMode::SrcOver { + self.zoom_perf_layered_blend_n += 1; + } else if needs_nested_fills { + self.zoom_perf_layered_nested_n += 1; + } else { + self.zoom_perf_layered_other_n += 1; + } + } + // Only save canvas state if we have clipping or transforms // For simple shapes without clipping, skip expensive save/restore let needs_save = @@ -1900,7 +2090,13 @@ impl RenderState { } let shape = &shape; + let zoom_perf = self.zoom_perf_active; + let t_fills = if zoom_perf { + performance::get_time() + } else { + 0 + }; if shape.fills.is_empty() && !matches!(shape.shape_type, Type::Group(_)) && !matches!(shape.shape_type, Type::Frame(_)) @@ -1930,6 +2126,9 @@ impl RenderState { outset, )?; } + if zoom_perf { + self.zoom_perf_fills_ms += performance::get_time() - t_fills; + } // Skip stroke rendering for clipped frames - they are drawn in render_shape_exit // over the children. Drawing twice would cause incorrect opacity blending. @@ -1937,6 +2136,11 @@ impl RenderState { if !skip_strokes { // Pass strokes in natural order; stroke merging handles top-most ordering internally. let visible_strokes: Vec<&Stroke> = shape.visible_strokes().collect(); + let t_strokes = if zoom_perf { + performance::get_time() + } else { + 0 + }; strokes::render( self, shape, @@ -1945,6 +2149,9 @@ impl RenderState { antialias, outset, )?; + if zoom_perf { + self.zoom_perf_strokes_ms += performance::get_time() - t_strokes; + } if !skip_effects { for stroke in &visible_strokes { shadows::render_stroke_inner_shadows( @@ -2293,12 +2500,23 @@ impl RenderState { performance::begin_measure!("render"); performance::begin_measure!("start_render_loop"); + let zoom_perf = self.zoom_perf_active; + if zoom_perf { + self.zoom_perf_log("start_render_loop begin"); + } + // Compute and set document-space bounds (1 unit == 1 doc px @ 100% zoom) // to clamp atlas updates. This prevents zoom-out tiles from forcing atlas // growth far beyond real content. let t_bounds = performance::get_time(); let doc_bounds = self.compute_document_bounds(base_object, tree); self.surfaces.atlas.set_doc_bounds(doc_bounds); + if zoom_perf { + self.zoom_perf_log(&format!( + "compute_document_bounds {}ms", + performance::get_time() - t_bounds + )); + } self.cache_cleared_this_render = false; let preserve_target = self.preserve_target_during_render; @@ -2307,6 +2525,12 @@ impl RenderState { if preserve_target && self.options.is_fast_mode() { let t_idx = performance::get_time(); self.rebuild_tile_index(tree); + if zoom_perf { + self.zoom_perf_log(&format!( + "start_render_loop.rebuild_tile_index {}ms", + performance::get_time() - t_idx + )); + } } if self.options.is_interactive_transform() { @@ -2365,6 +2589,16 @@ impl RenderState { let only_visible = self.options.is_interactive_transform(); self.pending_tiles .update(&self.tile_viewbox, &self.surfaces, only_visible); + if zoom_perf { + self.zoom_perf_log(&format!( + "pending_tiles.update {}ms pending={} visible_uncached={} deferred_interest~={}", + performance::get_time() - t_pending, + self.pending_tiles.list.len(), + self.pending_tiles.visible_uncached.len(), + self.pending_tiles.interest_uncached.len() + + self.pending_tiles.interest_cached.len() + )); + } performance::end_measure!("tile_cache"); performance::end_timed_log!("tile_cache_update", _tile_start); @@ -2382,6 +2616,13 @@ impl RenderState { !preserve_target || self.zoom_changed() || self.options.is_interactive_transform(); let t_cont = performance::get_time(); frame_type = self.continue_render_loop(base_object, tree, timestamp, allow_stop)?; + if zoom_perf { + self.zoom_perf_log(&format!( + "start_render_loop.first_continue {}ms -> {:?}", + performance::get_time() - t_cont, + frame_type as u8 + )); + } // This is an option to debug frames. if self.options.capture_frames > 0 { @@ -2445,6 +2686,9 @@ impl RenderState { ) -> Result { performance::begin_measure!("continue_render_loop"); let timestamp = self.render_budget_start(timestamp); + if self.zoom_perf_active { + self.zoom_perf_frame += 1; + } let t0 = performance::get_time(); let pending_before = self.pending_tiles.list.len(); @@ -2452,6 +2696,16 @@ impl RenderState { self.render_shape_tree_partial(base_object, tree, timestamp, allow_stop)?; let t_tree = performance::get_time(); + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "frame#{} render_shape_tree {}ms pending {}->{} type={}", + self.zoom_perf_frame, + t_tree - t0, + pending_before, + self.pending_tiles.list.len(), + frame_type as u8 + )); + } // `draw_atlas` needs a snapshot of the tile atlas. Partial frames are not // presented (only flushed), so defer composition until the viewport is @@ -2468,6 +2722,13 @@ impl RenderState { &self.tile_viewbox, self.background_color, ); + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "frame#{} draw_tile_atlas_to_backbuffer {}ms", + self.zoom_perf_frame, + performance::get_time() - t_c + )); + } } match frame_type { @@ -2480,6 +2741,13 @@ impl RenderState { // Composition stays deferred until ViewportReady/Full. let t_f = performance::get_time(); crate::get_gpu_state().context.flush_and_submit(); + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "frame#{} Partial.flush_and_submit {}ms", + self.zoom_perf_frame, + performance::get_time() - t_f + )); + } } FrameType::ViewportReady => { // Visible tiles are done: present now so the user sees the @@ -2488,11 +2756,26 @@ impl RenderState { if !self.options.is_fast_mode() && !self.options.is_interactive_transform() { let t_crop = performance::get_time(); self.rebuild_backbuffer_crop_cache(tree); + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "frame#{} rebuild_backbuffer_crop_cache {}ms", + self.zoom_perf_frame, + performance::get_time() - t_crop + )); + } } self.present_frame(tree); self.viewport_presented = true; wapi::notify_tiles_render_complete!(); crate::get_gpu_state().context.flush_and_submit(); + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "frame#{} ViewportReady.present+flush {}ms", + self.zoom_perf_frame, + performance::get_time() - t_p + )); + self.zoom_perf_end("ViewportReady (visible tiles done)"); + } } FrameType::Full => { if !self.viewport_presented { @@ -2504,9 +2787,20 @@ impl RenderState { } self.present_frame(tree); wapi::notify_tiles_render_complete!(); + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "frame#{} Full.present {}ms", + self.zoom_perf_frame, + performance::get_time() - t_p + )); + self.zoom_perf_end("Full"); + } } // If we already presented at ViewportReady, interest fill is // done; Target already shows the viewport. + if self.zoom_perf_active { + self.zoom_perf_end("Full (after ViewportReady interest fill)"); + } performance::end_measure!("render"); } } @@ -3612,6 +3906,11 @@ impl RenderState { && element.drop_shadows_visible().next().is_some(); if shadow_before_layer { + let t_shadow = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; if self.render_element_drop_shadows_and_composite( element, tree, @@ -3621,6 +3920,10 @@ impl RenderState { &node_render_state, target_surface, )? { + if self.zoom_perf_active { + self.zoom_perf_shadow_ms += performance::get_time() - t_shadow; + self.zoom_perf_shadow_nodes += 1; + } self.drop_shadows_ops_warmed = true; } } @@ -3628,10 +3931,26 @@ impl RenderState { // Render background blur BEFORE save_layer so it modifies // the backdrop independently of the shape's opacity. if !node_render_state.is_root() && self.focus_mode.is_active() { + let t_blur = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; self.render_background_blur(element, target_surface); + if self.zoom_perf_active { + self.zoom_perf_blur_ms += performance::get_time() - t_blur; + } } + let t_enter = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; self.render_shape_enter(element, mask, clip_bounds.as_ref(), target_surface); + if self.zoom_perf_active { + self.zoom_perf_enter_ms += performance::get_time() - t_enter; + } } if !node_render_state.is_root() && self.focus_mode.is_active() { @@ -3646,6 +3965,11 @@ impl RenderState { && !shadows_already_rendered && !matches!(element.shape_type, Type::Text(_)) { + let t_shadow = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; if self.render_element_drop_shadows_and_composite( element, tree, @@ -3655,6 +3979,10 @@ impl RenderState { &node_render_state, target_surface, )? { + if self.zoom_perf_active { + self.zoom_perf_shadow_ms += performance::get_time() - t_shadow; + self.zoom_perf_shadow_nodes += 1; + } // Real shadow composite already clears DropShadows. self.drop_shadows_ops_warmed = true; } @@ -3665,8 +3993,16 @@ impl RenderState { // composited real shadows yet. Omitting this entirely made // flush_and_submit very slow (ops-task ordering); repeating // it per shape was wasted GPU work. + let t_warm = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; self.surfaces .draw_into(SurfaceId::DropShadows, target_surface, None); + if self.zoom_perf_active { + self.zoom_perf_shadow_warmup_ms += performance::get_time() - t_warm; + } self.drop_shadows_ops_warmed = true; } @@ -3687,6 +4023,11 @@ impl RenderState { }; let is_text = matches!(element_for_inline.shape_type, Type::Text(_)); + let t_shape = if self.zoom_perf_active { + performance::get_time() + } else { + 0 + }; self.render_shape( &element_for_inline, clip_bounds.clone(), @@ -3700,6 +4041,15 @@ impl RenderState { None, target_surface, )?; + if self.zoom_perf_active { + let dt = performance::get_time() - t_shape; + self.zoom_perf_shape_ms += dt; + self.zoom_perf_nodes += 1; + if is_text { + self.zoom_perf_text_ms += dt; + self.zoom_perf_text_nodes += 1; + } + } } else if visited_children { self.draw_shape_surface_stack_into(Some(element), target_surface); } @@ -3891,6 +4241,25 @@ impl RenderState { return Ok(false); } + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "region={} START tiles={} shapes={} roots={} bg_blur={} skip_shadows={} zoom={:.3} scale={:.3} area=({:.1},{:.1},{:.1}x{:.1}) {}", + label, + region_tiles.len(), + shape_ids.len(), + valid_ids.len(), + region_has_bg_blur, + self.should_skip_drop_shadows(), + self.viewbox.zoom, + self.get_scale(), + area.left, + area.top, + area.width(), + area.height(), + self.surfaces.paint_diag_summary() + )); + } + self.pending_nodes .extend(valid_ids.into_iter().map(|id| NodeRenderState { id, @@ -3964,9 +4333,23 @@ impl RenderState { // a previous pass; otherwise pass-1 pixels can leak into pass 2. if self.viewer_masked_pass() || !self.surfaces.has_cached_tile_surface(current_tile) { + let zoom_perf = self.zoom_perf_active; + let t_tile = performance::get_time(); + let shapes_n = self + .tiles + .get_shapes_at(current_tile) + .map(|ids| ids.len()) + .unwrap_or(0); + let nodes_before = self.pending_nodes.len(); + let shadows_before = self.drop_shadows_ops_warmed; + if zoom_perf { + self.zoom_perf_reset_walker(); + } + performance::begin_measure!("render_shape_tree::uncached"); let (is_empty, early_return) = self .render_shape_tree_partial_uncached(tree, timestamp, allow_stop, false)?; + let walker_ms = performance::get_time() - t_tile; #[cfg(target_arch = "wasm32")] if self.options.capture_frames > 0 { @@ -3974,14 +4357,62 @@ impl RenderState { } if early_return { + if zoom_perf { + let breakdown = self.zoom_perf_walker_summary(); + if let Some(ref region) = self.paint_region { + self.zoom_perf_log(&format!( + "region={} YIELD walker={}ms tiles={} nodes {}->{} shadows_warmed={}->{} | {}", + region.label, + walker_ms, + region.tiles.len(), + nodes_before, + self.pending_nodes.len(), + shadows_before, + self.drop_shadows_ops_warmed, + breakdown + )); + } else { + self.zoom_perf_log(&format!( + "tile=({},{}) YIELD walker={}ms shapes={} nodes {}->{} shadows_warmed={}->{} | {}", + current_tile.0, + current_tile.1, + walker_ms, + shapes_n, + nodes_before, + self.pending_nodes.len(), + shadows_before, + self.drop_shadows_ops_warmed, + breakdown + )); + } + } self.viewer_render_root = None; return Ok(FrameType::Partial); } performance::end_measure!("render_shape_tree::uncached"); + let mut apply_ms = 0; if let Some(region) = self.paint_region.take() { if !is_empty || self.current_tile_had_shapes { + let t_apply = performance::get_time(); self.apply_paint_region_to_atlas(®ion)?; + apply_ms = performance::get_time() - t_apply; + } + if zoom_perf { + let breakdown = self.zoom_perf_walker_summary(); + self.zoom_perf_log(&format!( + "region={} DONE walker={}ms crop={}ms total={}ms tiles={} nodes {}->{} shadows_warmed={}->{} | {}", + region.label, + walker_ms, + apply_ms, + performance::get_time() - t_tile, + region.tiles.len(), + nodes_before, + self.pending_nodes.len(), + shadows_before, + self.drop_shadows_ops_warmed, + breakdown + )); } } else { let tile_rect = self.get_current_tile_bounds()?; @@ -3990,6 +4421,7 @@ impl RenderState { // (`current_tile_had_shapes` was set when we populated pending_nodes // for this tile). if !is_empty || self.current_tile_had_shapes { + let t_apply = performance::get_time(); if self.options.is_interactive_transform() { // During drag, avoid snapshot-based caching. Draw Current directly // into Target (and Cache) to reduce stalls. @@ -4001,6 +4433,7 @@ impl RenderState { } else { self.apply_render_to_final_canvas()?; } + apply_ms = performance::get_time() - t_apply; if self.options.is_debug_visible() { debug::render_workspace_current_tile( @@ -4011,6 +4444,23 @@ impl RenderState { ); } } + if zoom_perf { + let breakdown = self.zoom_perf_walker_summary(); + self.zoom_perf_log(&format!( + "tile=({},{}) DONE walker={}ms apply={}ms total={}ms shapes={} nodes {}->{} shadows_warmed={}->{} | {}", + current_tile.0, + current_tile.1, + walker_ms, + apply_ms, + performance::get_time() - t_tile, + shapes_n, + nodes_before, + self.pending_nodes.len(), + shadows_before, + self.drop_shadows_ops_warmed, + breakdown + )); + } } } else if self.tiles.is_empty_at(current_tile) { self.surfaces.remove_cached_tile_surface(current_tile); @@ -4040,7 +4490,9 @@ impl RenderState { let viewer_masked_pass = self.viewer_masked_pass(); - let valid_ids = { + // Scope the `tiles` borrow from `get_shapes_at` so it ends + // before `zoom_perf_log` (needs `&self`). + let (shapes_n, valid_ids, tile_has_bg_blur) = { let Some(ids) = self.tiles.get_shapes_at(next_tile) else { // If the tile is empty we do not need to render it. continue; @@ -4069,7 +4521,8 @@ impl RenderState { // tiles (we clear the tile rect before drawing Current), so we must render // all root shapes that can contribute to this tile; otherwise, unchanged // siblings inside the same tile would disappear. - let mut valid_ids = Vec::with_capacity(ids.len()); + let shapes_n = ids.len(); + let mut valid_ids = Vec::with_capacity(shapes_n); if self.options.is_interactive_transform() || tile_has_bg_blur { valid_ids.extend(root_ids.iter().copied()); } else { @@ -4079,9 +4532,20 @@ impl RenderState { } } } - valid_ids + (shapes_n, valid_ids, tile_has_bg_blur) }; + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "tile=({},{}) START shapes={} roots={} bg_blur={}", + next_tile.0, + next_tile.1, + shapes_n, + valid_ids.len(), + tile_has_bg_blur + )); + } + if !valid_ids.is_empty() { self.current_tile_had_shapes = true; } @@ -4326,6 +4790,14 @@ impl RenderState { } } } + if self.zoom_perf_active { + self.zoom_perf_log(&format!( + "rebuild_tile_index inner {}ms top_level_shapes={} zoom_changed={}", + performance::get_time() - t0, + shapes_visited, + zoom_changed + )); + } performance::end_measure!("rebuild_tile_index"); } diff --git a/render-wasm/src/render/surfaces.rs b/render-wasm/src/render/surfaces.rs index 04fd226637..87e2f07a84 100644 --- a/render-wasm/src/render/surfaces.rs +++ b/render-wasm/src/render/surfaces.rs @@ -471,6 +471,10 @@ pub struct Surfaces { dirty_surfaces: u32, extra_tile_dims: skia::ISize, dpr: f32, + /// When true, accumulate draw_into wall time (ZOOM-PERF diagnosis). + paint_diag: bool, + draw_into_ms: i32, + draw_into_n: u32, } #[allow(dead_code)] @@ -550,6 +554,9 @@ impl Surfaces { dirty_surfaces: 0, extra_tile_dims, dpr: 1.0, + paint_diag: false, + draw_into_ms: 0, + draw_into_n: 0, }) } @@ -849,6 +856,11 @@ impl Surfaces { pub fn draw_into(&mut self, from: SurfaceId, to: SurfaceId, paint: Option<&skia::Paint>) { let sampling_options = self.sampling_options; + let t0 = if self.paint_diag { + performance::get_time() + } else { + 0 + }; self.get_mut(from).clone().draw( self.canvas_and_mark_dirty(to), @@ -856,6 +868,34 @@ impl Surfaces { sampling_options, paint, ); + + if self.paint_diag { + self.draw_into_ms += performance::get_time() - t0; + self.draw_into_n += 1; + } + } + + pub fn set_paint_diag(&mut self, enabled: bool) { + self.paint_diag = enabled; + if enabled { + self.draw_into_ms = 0; + self.draw_into_n = 0; + } + } + + pub fn reset_paint_diag_counters(&mut self) { + self.draw_into_ms = 0; + self.draw_into_n = 0; + } + + pub fn paint_diag_summary(&self) -> String { + format!( + "current={}x{} draw_into={}ms n={}", + self.current.width(), + self.current.height(), + self.draw_into_ms, + self.draw_into_n + ) } pub fn cache_dimensions(&self) -> skia::ISize {