diff --git a/src/app/view/mod.rs b/src/app/view/mod.rs index ec566dc3a..e10cda835 100644 --- a/src/app/view/mod.rs +++ b/src/app/view/mod.rs @@ -177,7 +177,20 @@ impl OpenCADStudio { // All dialogs are in-canvas modals now (Plan B); view_main stacks the // active one. `window_id` is unused — there is only the main window. let _ = window_id; - self.view_main() + // Pan latency on a large drawing is ~120 ms while `update`, `prepare` + // and `encode` together account for ~1 ms of it, the GPU sits at 0-8%, + // and encoding no scene at all changes nothing. Widget-tree + // construction is the largest span between the input handler returning + // and `prepare` running, and it was never measured. + let started = crate::perf::enabled().then(iced::time::Instant::now); + let element = self.view_main(); + if let Some(started) = started { + let elapsed_ms = started.elapsed().as_secs_f64() * 1000.0; + if elapsed_ms >= 1.0 { + crate::perf_record!("[perf] view {:>7.1}ms", elapsed_ms); + } + } + element } /// The primary window: viewport, ribbon, tab bar, status bar. Split out of diff --git a/src/io/mod.rs b/src/io/mod.rs index a839bd2a5..b278576e5 100644 --- a/src/io/mod.rs +++ b/src/io/mod.rs @@ -383,6 +383,8 @@ async fn open_path_with_phase_attempt( purge_ms, caches_ms: t_caches.elapsed().as_millis() as u32, xref_ms, + // Filled in after `prepare_open_geometry` below. + finalize_ms: 0, }; caches.corrupt_dropped = dropped; caches.read_stats = Some(read_stats); @@ -395,11 +397,24 @@ async fn open_path_with_phase_attempt( ); } progress2.set(crate::app::OPEN_PHASE_FINALIZING, 9600, 0, 1); + let t_finalize = Instant::now(); let (prepared_doc, prepared_geometry) = crate::scene::prepare_open_geometry(doc, &caches, model_bg); + caches.timings.finalize_ms = t_finalize.elapsed().as_millis() as u32; doc = prepared_doc; caches.prepared_geometry = Some(prepared_geometry); progress2.set(crate::app::OPEN_PHASE_FINALIZING, 9950, 1, 1); + // The localized command-line summary predates `finalize_ms` and + // is keyed on its format string, so the full breakdown goes out + // here instead of changing that key across every locale. + crate::perf_record!( + "[perf] open-phases parse={}ms purge={}ms xref={}ms caches={}ms finalize={}ms", + caches.timings.parse_ms, + caches.timings.purge_ms, + caches.timings.xref_ms, + caches.timings.caches_ms, + caches.timings.finalize_ms, + ); Ok((doc, caches)) })() })); diff --git a/src/io/recovery.rs b/src/io/recovery.rs index d8a779b5e..c99f5a55a 100644 --- a/src/io/recovery.rs +++ b/src/io/recovery.rs @@ -373,6 +373,7 @@ impl RecoveryReport { lines.push(format!("Validation: {} ms", self.timings.purge_ms)); lines.push(format!("References: {} ms", self.timings.xref_ms)); lines.push(format!("Scene caches: {} ms", self.timings.caches_ms)); + lines.push(format!("Geometry prep: {} ms", self.timings.finalize_ms)); lines.push(format!("Total: {} ms", self.total_ms)); if !self.diagnostics.is_empty() { lines.push(String::new()); diff --git a/src/scene/mod.rs b/src/scene/mod.rs index abbacd6ca..107eaefdd 100644 --- a/src/scene/mod.rs +++ b/src/scene/mod.rs @@ -679,6 +679,10 @@ pub struct OpenTimings { pub purge_ms: u32, pub caches_ms: u32, pub xref_ms: u32, + /// The FINALIZING phase: `prepare_open_geometry` — first full Model + /// tessellation plus interaction index. Previously unmeasured, which made + /// it indistinguishable from parse time in an open that appeared to stall. + pub finalize_ms: u32, } /// Build hatch / image / mesh caches from a document without needing `&mut Scene`. @@ -982,15 +986,36 @@ pub fn prepare_open_geometry( }; scene.current_layout = "Model".to_string(); let camera = scene.camera.borrow().clone(); + let perf = crate::perf::enabled(); + let t_wires = iced::time::Instant::now(); let wires = scene.model_tile_wires_arc(0, &camera, 1.0, 1.0); + let wires_ms = t_wires.elapsed().as_secs_f64() * 1000.0; + let t_index = iced::time::Instant::now(); let interaction_index = if scene.interaction_index_worthwhile(&wires) { let index = Arc::new(crate::scene::pick::interaction_index::InteractionIndex::build(&wires)); + let build_ms = t_index.elapsed().as_secs_f64() * 1000.0; + let t_screen = iced::time::Instant::now(); index.prepare_screen(); + if perf { + crate::perf_record!( + "[perf] open-index build={:.1}ms prepare_screen={:.1}ms", + build_ms, + t_screen.elapsed().as_secs_f64() * 1000.0, + ); + } Some(index) } else { None }; + if perf { + crate::perf_record!( + "[perf] open-finalize wires={:.1}ms index={:.1}ms wire_models={}", + wires_ms, + t_index.elapsed().as_secs_f64() * 1000.0, + wires.len(), + ); + } let doc = std::mem::replace(&mut scene.document, CadDocument::new()); ( doc, @@ -5181,14 +5206,29 @@ impl Scene { all_visible, style_viewport, ); + let perf = crate::perf::enabled(); + let t_post = iced::time::Instant::now(); // Synthesized nonprint markers (geo-location daisy) live in model space // only and are derived from document objects, not entities — append them // to the freshly built resident set (incremental patches preserve them). if block == self.model_space_block_handle() { self.append_scene_markers(&mut wires, bg); } + let markers_ms = t_post.elapsed().as_secs_f64() * 1000.0; + let t_fade = iced::time::Instant::now(); self.apply_refedit_fade(&mut wires, bg); + let fade_ms = t_fade.elapsed().as_secs_f64() * 1000.0; + let t_layout = iced::time::Instant::now(); let layout = Self::resident_wire_layout(&wires); + if perf { + crate::perf_record!( + "[perf] resident-post markers={:.1}ms fade={:.1}ms layout={:.1}ms wires={}", + markers_ms, + fade_ms, + t_layout.elapsed().as_secs_f64() * 1000.0, + wires.len(), + ); + } self.last_tess_ms .set(t_tess.elapsed().as_secs_f32() * 1000.0); self.last_tess_wires.set(wires.len()); @@ -8724,6 +8764,12 @@ impl Scene { ) -> Vec { use acadrust::objects::ObjectType; + // Stage timings for the load-path investigation. This function also + // runs per frame on the cull path, so the reporting stays behind the + // PERF gate. `t_fn` doubles as the start of the sort-cache stage. + let perf = crate::perf::enabled(); + let t_fn = iced::time::Instant::now(); + // ── Ensure sort-order index is current ──────────────────────────── // Replaces the old O(objects) find_map with one rebuild per epoch, // after which every wires_for_block call is an O(1) HashMap lookup. @@ -8765,6 +8811,9 @@ impl Scene { ) }; + let sort_cache_ms = t_fn.elapsed().as_secs_f64() * 1000.0; + let t_visible = iced::time::Instant::now(); + // Phase 2.1 — quadtree-driven candidate selection. When a view // AABB exists (Model layout with a settled camera), only iterate // entities whose stored WCS bbox intersects the view; unindexable @@ -8815,6 +8864,9 @@ impl Scene { .collect() }; + let visible_ms = t_visible.elapsed().as_secs_f64() * 1000.0; + let visible_count = visible.len(); + // Tessellate in parallel across all available CPU cores. use crate::par::prelude::*; let doc = &self.document; @@ -8847,7 +8899,9 @@ impl Scene { // Content shown inside a paper-space viewport carries a scale override; // only there does PSLTSCALE resize linetypes by the viewport scale. let paper = anno_scale_override.is_some(); + let t_blk = iced::time::Instant::now(); let blk_cache = self.block_cache_arc_for(annotation_scale_handle, all_visible, style_viewport); + let blk_ms = t_blk.elapsed().as_secs_f64() * 1000.0; let blk_ref: &cache::block_cache::BlockCache = &blk_cache; // Per-entity tessellation memo. Same classify/tessellate logic, two // SEPARATE stores so they can't thrash each other: @@ -8876,6 +8930,15 @@ impl Scene { } let resident = base_ok && view_aabb.is_none() && wpp.is_none() && resident_memo_enabled(); let memo_active = base_ok && (view_aabb.is_some() || resident); + // Reported in one line below. `tess_ms` / `memo_misses` are assigned by + // both branches; the rest exist only on the memo path and stay zero. + let mut classify_ms = 0.0f64; + let mut hits_ms = 0.0f64; + let tess_ms; + let mut materialize_ms = 0.0f64; + let mut memo_hits = 0usize; + let memo_misses; + let t_build = iced::time::Instant::now(); let mut wires: Vec = if memo_active { // Guard hash of everything tessellate_entity output depends on // besides the entity itself. A mismatch (zoom/tol, view, anno, @@ -8914,6 +8977,7 @@ impl Scene { guard_cell.set(guard); } // Classify (serial, cheap): reuse memoized Arcs, collect misses. + let t_classify = iced::time::Instant::now(); let mut hit_arcs: Vec>> = Vec::new(); let mut misses: Vec<&EntityType> = Vec::new(); { @@ -8926,11 +8990,17 @@ impl Scene { } } } + classify_ms = t_classify.elapsed().as_secs_f64() * 1000.0; + memo_hits = hit_arcs.len(); + memo_misses = misses.len(); // Materialize hits + tessellate misses, both in parallel. + let t_hits = iced::time::Instant::now(); let hit_wires: Vec = hit_arcs .par_iter() .flat_map_iter(|a| a.iter().cloned()) .collect(); + hits_ms = t_hits.elapsed().as_secs_f64() * 1000.0; + let t_tess_miss = iced::time::Instant::now(); let miss_pairs: Vec<(Handle, Arc>)> = misses .par_iter() .map(|e| { @@ -8951,6 +9021,12 @@ impl Scene { (e.common().handle, Arc::new(w)) }) .collect(); + tess_ms = t_tess_miss.elapsed().as_secs_f64() * 1000.0; + // Serial deep-clone of every freshly tessellated wire, while the + // memo retains a second copy of the same geometry. Suspected + // dominant cost of a cold open; measuring it is the point of this + // whole breakdown. + let t_materialize = iced::time::Instant::now(); let mut out = hit_wires; { let mut memo = memo_cell.borrow_mut(); @@ -8959,9 +9035,11 @@ impl Scene { memo.insert(*h, Arc::clone(a)); } } + materialize_ms = t_materialize.elapsed().as_secs_f64() * 1000.0; out } else { - visible + let t_tess_all = iced::time::Instant::now(); + let out: Vec = visible .into_par_iter() .flat_map(|e| { tessellate_entity( @@ -8978,14 +9056,21 @@ impl Scene { paper, ) }) - .collect() + .collect(); + tess_ms = t_tess_all.elapsed().as_secs_f64() * 1000.0; + memo_misses = visible_count; + out }; + let build_ms = t_build.elapsed().as_secs_f64() * 1000.0; // Apply draw order via the cached index (O(1) block lookup). + let t_sort = iced::time::Instant::now(); + let mut sorted = false; { let cache = self.sort_cache.borrow(); if let Some((_, ref idx)) = *cache { if let Some(sort_map) = idx.get(&block_handle) { + sorted = true; wires.sort_by_key(|w| { let key = Self::handle_from_wire_name(&w.name) .map(|h| h.value()) @@ -8999,6 +9084,29 @@ impl Scene { } } } + if perf { + crate::perf_record!( + "[perf] wires-build total={:.1}ms sort_cache={:.1} visible={:.1} blk_cache={:.1} \ +build={:.1} [classify={:.1} hits={:.1} tess={:.1} materialize={:.1}] sort={:.1}({}) \ +entities={} memo_hit={} memo_miss={} wires={} memo={}", + t_fn.elapsed().as_secs_f64() * 1000.0, + sort_cache_ms, + visible_ms, + blk_ms, + build_ms, + classify_ms, + hits_ms, + tess_ms, + materialize_ms, + t_sort.elapsed().as_secs_f64() * 1000.0, + if sorted { "applied" } else { "skipped" }, + visible_count, + memo_hits, + memo_misses, + wires.len(), + if memo_active { "on" } else { "off" }, + ); + } wires } diff --git a/src/scene/view/render.rs b/src/scene/view/render.rs index 3326543f4..bc0568231 100644 --- a/src/scene/view/render.rs +++ b/src/scene/view/render.rs @@ -921,23 +921,10 @@ impl shader::Primitive for Primitive { let built = match cached { Some(entry) => entry, None => { - // Free the superseded content BEFORE allocating its - // replacement. Every geometry edit mints a new content - // id, so a miss here means this slot's current buffers - // are already dead weight — and on a large drawing one - // set is most of the card (measured: 1.3 GB of a 2 GB - // GT 1030). Holding the old set while the new one is - // allocated is what exhausts VRAM after the first edit. - // - // Dropping this slot's handles first is what makes the - // retain below able to see the old entry as garbage; a - // pane still drawing that content keeps its own clone, - // so shared geometry is never pulled out from under it. + // Release superseded buffers before allocating replacements. + // Other panes retain their own references to shared geometry. inner.gpu_wires = std::sync::Arc::new(Vec::new()); inner.gpu_block_wires = std::sync::Arc::new(Vec::new()); - // Entries no slot still holds: only the cache references - // them. An entry drawn by any pane keeps a strong count - // ≥ 2, so this never drops live geometry. let held_before = pipeline.wire_buffer_cache.len(); pipeline.wire_buffer_cache.retain(|_, (w, b, _)| { std::sync::Arc::strong_count(w) > 1 @@ -950,8 +937,18 @@ impl shader::Primitive for Primitive { pipeline.wire_buffer_cache.len(), ); } + let t_upload = _perf.then(iced::time::Instant::now); let entry = inner.build_wire_buffers(device, queue, &vp_wires[..], &draw_depths); + if let Some(start) = t_upload { + crate::perf_record!( + "[perf] wire-upload {:.1}ms wires={} content_id={}", + start.elapsed().as_secs_f64() * 1000.0, + vp_wires.len(), + vp.wire_content_id, + ); + } + pipeline .wire_buffer_cache .insert(vp.wire_content_id, entry.clone());