feat(io): open-time breakdown log

Phase 5.2. Time each open phase — parse, purge, derived-cache build on
the loader thread, plus xref resolve on the UI thread — and emit a
breakdown line on open completion:

  parse 1240ms · purge 80ms · caches 340ms · xref 60ms · total 1820ms

Makes open-time regressions (and the wins from 1.1 / 2.4) visible at a
glance. Timings ride back on DerivedCaches; total is wall time from the
Open click to post-xref.

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

ROADMAP.md

@@ -241,7 +241,7 @@ Don't start any of the above **without measuring first**.
 
 Gate behind `debug_assertions` or a `--features profile` flag.
 
-### 5.2 Open-time breakdown log
+### 5.2 Open-time breakdown log ✅ DONE
 
 When open completes, push to the command line:
 

src/app/update.rs

@@ -131,7 +131,8 @@ impl OpenCADStudio {
                 if self.opening.is_none() {
                     return Task::none();
                 }
-                self.opening = None;
+                let open_started = self.opening.take().map(|p| p.started);
+                let timings = caches.timings;
                 let entity_count = doc.entities().count();
                 self.command_line
                     .push_output(&format!("Opened \"{name}\" — {entity_count} entities"));
@@ -171,14 +172,17 @@ impl OpenCADStudio {
                     if cannoscale_value > 1e-9 { (1.0 / cannoscale_value) as f32 } else { 1.0 };
 
                 // Auto-resolve XREFs relative to the opened file's directory.
+                let mut xref_ms = 0u32;
                 if let Some(base_dir) = path.parent() {
                     // xref content arrives un-purged: parser-garbage entities
                     // inside the referenced file can trigger infinite loops in
                     // tessellation. `resolve_xrefs` runs the corrupt-entity
                     // guard inline as it merges each xref, so no second
                     // full-document walk is needed here.
+                    let t_xref = Instant::now();
                     let (xrefs, extra_dropped) =
                         crate::io::xref::resolve_xrefs(&mut self.tabs[i].scene.document, base_dir);
+                    xref_ms = t_xref.elapsed().as_millis() as u32;
                     if extra_dropped > 0 {
                         self.command_line.push_error(&format!(
                             "Warning: {extra_dropped} corrupt xref entities dropped"
@@ -206,6 +210,18 @@ impl OpenCADStudio {
                     }
                 }
 
+                // Open-time breakdown so regressions are visible immediately.
+                // `total` is wall time from the Open click to here (post-xref,
+                // pre-first-frame); the phase figures are the background-thread
+                // parse/purge/cache spans plus the UI-thread xref resolve.
+                let total_ms = open_started
+                    .map(|s| s.elapsed().as_millis() as u32)
+                    .unwrap_or(0);
+                self.command_line.push_info(&format!(
+                    "  parse {}ms · purge {}ms · caches {}ms · xref {}ms · total {}ms",
+                    timings.parse_ms, timings.purge_ms, timings.caches_ms, xref_ms, total_ms
+                ));
+
                 // Caches were built on the background thread inside open_path().
                 self.tabs[i].scene.world_offset = caches.world_offset;
                 self.tabs[i].scene.local_extent_max = caches.local_extent_max;

src/io/mod.rs

@@ -60,11 +60,22 @@ pub async fn open_path_with_phase(
     let path2 = path.clone();
     let phase2 = phase.clone();
     let (doc, caches) = std::thread::spawn(move || -> Result<_, String> {
+        use std::time::Instant;
         phase2.store(PHASE_PARSING, Ordering::Relaxed);
+        let t_parse = Instant::now();
         let mut doc = load_file(&path2)?;
+        let parse_ms = t_parse.elapsed().as_millis() as u32;
+        let t_purge = Instant::now();
         let dropped = purge_corrupt_entities(&mut doc);
+        let purge_ms = t_purge.elapsed().as_millis() as u32;
         phase2.store(PHASE_CACHING, Ordering::Relaxed);
+        let t_caches = Instant::now();
         let mut caches = crate::scene::build_derived_caches(&doc);
+        caches.timings = crate::scene::OpenTimings {
+            parse_ms,
+            purge_ms,
+            caches_ms: t_caches.elapsed().as_millis() as u32,
+        };
         caches.corrupt_dropped = dropped;
         phase2.store(PHASE_FINALIZING, Ordering::Relaxed);
         Ok((doc, caches))

src/scene/mod.rs

@@ -104,6 +104,18 @@ pub struct DerivedCaches {
     /// Reported back to the UI so the user knows when a file had parser-junk
     /// entities silently dropped.
     pub corrupt_dropped: usize,
+    /// Background-thread open-phase timings in milliseconds (parse, purge,
+    /// derived-cache build). Filled in by `open_path_with_phase`; surfaced in
+    /// the open-complete breakdown log so open-time regressions are visible.
+    pub timings: OpenTimings,
+}
+
+/// Wall-clock breakdown of the file-open phases, in milliseconds.
+#[derive(Debug, Clone, Copy, Default)]
+pub struct OpenTimings {
+    pub parse_ms: u32,
+    pub purge_ms: u32,
+    pub caches_ms: u32,
 }
 
 /// Build hatch / image / mesh caches from a document without needing `&mut Scene`.
@@ -237,6 +249,7 @@ pub fn build_derived_caches(doc: &CadDocument) -> DerivedCaches {
         images,
         meshes,
         corrupt_dropped: 0,
+        timings: OpenTimings::default(),
     }
 }