diff --git a/src/app/update/mod.rs b/src/app/update/mod.rs index b80f9ee7c..fe8519aa1 100644 --- a/src/app/update/mod.rs +++ b/src/app/update/mod.rs @@ -265,6 +265,13 @@ impl OpenCADStudio { self.control_observe_user_message(&msg); let perf_started = crate::perf::enabled().then(Instant::now); let perf_label = perf_message_label(&msg); + // Geometry epoch before dispatch. When it moves, this message drew or + // changed something, and the latency the user feels runs from here to + // the frame that shows it — not to the end of this handler. Stamping + // the nav-perf sample makes `nav-prepare` / `nav-render` report that + // span, the same way they already do for pan and zoom. + let perf_epoch_before = perf_started + .map(|_| self.tabs[self.active_tab].scene.geometry_epoch); // A modal dialog must capture the keyboard the same way it already // captures the mouse. Otherwise keystrokes from the global key // subscription leak past the modal into the command line and fire as @@ -324,6 +331,16 @@ impl OpenCADStudio { self.otrack_active = None; self.otrack_kind = None; } + if let (Some(started), Some(before)) = (perf_started, perf_epoch_before) { + let tab = &self.tabs[self.active_tab]; + if tab.scene.geometry_epoch != before { + tab.scene.record_nav_perf_caused( + crate::scene::NavPerfOp::Edit, + perf_label, + started, + ); + } + } if let Some(started) = perf_started { let elapsed_ms = started.elapsed().as_secs_f64() * 1000.0; if elapsed_ms >= 5.0 { diff --git a/src/scene/mod.rs b/src/scene/mod.rs index 07d219156..e19534afa 100644 --- a/src/scene/mod.rs +++ b/src/scene/mod.rs @@ -1432,6 +1432,10 @@ pub(crate) enum NavPerfOp { Pan, Zoom, Rotate, + /// A message that changed geometry. Reported through the same line as + /// navigation because the question is the same one: how long from the + /// input to the frame that answers it. + Edit, } impl NavPerfOp { @@ -1440,6 +1444,7 @@ impl NavPerfOp { Self::Pan => "pan", Self::Zoom => "zoom", Self::Rotate => "rotate", + Self::Edit => "edit", } } } @@ -1447,6 +1452,10 @@ impl NavPerfOp { #[derive(Clone, Copy, Debug)] pub(in crate::scene) struct NavPerfSample { pub(in crate::scene) op: NavPerfOp, + /// Which message caused it. An edit whose handler runs in under a + /// millisecond never reaches the `update` line's threshold, so without this + /// the log shows the latency but not what asked for it. + pub(in crate::scene) cause: &'static str, pub(in crate::scene) space: &'static str, pub(in crate::scene) mode: &'static str, pub(in crate::scene) started: iced::time::Instant, @@ -2875,6 +2884,15 @@ impl Scene { } pub(crate) fn record_nav_perf(&self, op: NavPerfOp, started: iced::time::Instant) { + self.record_nav_perf_caused(op, "-", started); + } + + pub(crate) fn record_nav_perf_caused( + &self, + op: NavPerfOp, + cause: &'static str, + started: iced::time::Instant, + ) { if !crate::perf::enabled() { return; } @@ -2887,6 +2905,7 @@ impl Scene { }; self.nav_perf_pending.set(Some(NavPerfSample { op, + cause, space, mode, started, diff --git a/src/scene/view/render.rs b/src/scene/view/render.rs index b25fb4810..93c8047de 100644 --- a/src/scene/view/render.rs +++ b/src/scene/view/render.rs @@ -1216,8 +1216,9 @@ impl shader::Primitive for Primitive { let prepare_ms = nav_prepare_started.elapsed().as_secs_f64() * 1000.0; if let Some(sample) = self.nav_perf { crate::perf::record(format_args!( - "[perf] nav-prepare op={} space={} mode={} input={:.2}ms build={:.2}ms prepare={:.2}ms elapsed={:.2}ms viewports={}", + "[perf] nav-prepare op={} cause={} space={} mode={} input={:.2}ms build={:.2}ms prepare={:.2}ms elapsed={:.2}ms viewports={}", sample.op.label(), + sample.cause, sample.space, sample.mode, sample.input_ms,