diff --git a/ROADMAP.md b/ROADMAP.md index 4e444631a..7e075718d 100644 --- a/ROADMAP.md +++ b/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: diff --git a/src/app/update.rs b/src/app/update.rs index d60a031b4..ff99976cc 100644 --- a/src/app/update.rs +++ b/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; diff --git a/src/io/mod.rs b/src/io/mod.rs index ffdafab22..402b61f21 100644 --- a/src/io/mod.rs +++ b/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)) diff --git a/src/scene/mod.rs b/src/scene/mod.rs index b62bb47bb..b4e3b1a40 100644 --- a/src/scene/mod.rs +++ b/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(), } }