perf: instrument the file-open load path behind PERF

The 52 s silent stretch in a large-DWG open could not be attributed:
OpenTimings covered parse / purge / xref / caches, but the FINALIZING
phase -- prepare_open_geometry, which does the first full Model
tessellation and builds the interaction index -- was unmeasured and
reports only two progress ticks, so it was indistinguishable from parse
time.

Add finalize_ms to OpenTimings and a per-stage PERF breakdown:

  open-phases     parse / purge / xref / caches / finalize
  open-finalize   tessellation vs interaction index
  open-index      index build vs prepare_screen
  wires-build     sort cache, visible filter, block cache, classify,
                  memo hits, parallel tessellate, materialize, sort
  resident-post   scene markers, refedit fade, resident layout
  wire-upload     build_wire_buffers, which runs on the render thread

The wires-build line separates the parallel tessellate from the serial
materialize loop that deep-clones every WireModel while the memo retains
a second copy -- the leading hypothesis for both the stall and the
6.45 GB RSS.

No behaviour change. Every timer is gated on crate::perf::enabled(), so
nothing runs without PERF=1 or the in-app PERF panel. The localized
open-summary format string is left alone; changing it would rekey the
string across every locale, so the full breakdown goes to PERF instead.

Co-Authored-By: Claude Opus 5 <[email protected]>

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))
                 })()
             }));

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());

src/scene/mod.rs

@@ -605,6 +605,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`.
@@ -908,15 +912,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,
@@ -5063,14 +5088,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());
@@ -8606,6 +8646,12 @@ impl Scene {
     ) -> Vec<WireModel> {
         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.
@@ -8647,6 +8693,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
@@ -8697,6 +8746,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;
@@ -8729,7 +8781,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:
@@ -8758,6 +8812,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<WireModel> = if memo_active {
             // Guard hash of everything tessellate_entity output depends on
             // besides the entity itself. A mismatch (zoom/tol, view, anno,
@@ -8796,6 +8859,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<Arc<Vec<WireModel>>> = Vec::new();
             let mut misses: Vec<&EntityType> = Vec::new();
             {
@@ -8808,11 +8872,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<WireModel> = 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<Vec<WireModel>>)> = misses
                 .par_iter()
                 .map(|e| {
@@ -8833,6 +8903,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();
@@ -8841,9 +8917,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<WireModel> = visible
                 .into_par_iter()
                 .flat_map(|e| {
                     tessellate_entity(
@@ -8860,14 +8938,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())
@@ -8881,6 +8966,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
     }
 

src/scene/view/render.rs

@@ -917,8 +917,19 @@ impl shader::Primitive for Primitive {
                     let built = match cached {
                         Some(entry) => entry,
                         None => {
+                            // Runs on the main/render thread inside `prepare`,
+                            // so its cost is UI stall, not background load.
+                            let t_upload = iced::time::Instant::now();
                             let entry =
                                 inner.build_wire_buffers(device, &vp_wires[..], &draw_depths);
+                            if crate::perf::enabled() {
+                                crate::perf_record!(
+                                    "[perf] wire-upload {:.1}ms wires={} content_id={}",
+                                    t_upload.elapsed().as_secs_f64() * 1000.0,
+                                    vp_wires.len(),
+                                    vp.wire_content_id,
+                                );
+                            }
                             pipeline
                                 .wire_buffer_cache
                                 .insert(vp.wire_content_id, entry.clone());