From b4ae4cad4e3a21d5f79e27c81d7b2d03740ec30a Mon Sep 17 00:00:00 2001 From: Panos <25664832+mechpanos@users.noreply.github.com> Date: Tue, 8 Sep 2026 11:25:10 +0300 Subject: [PATCH 1/2] perf: measure an edit from the input to the frame that answers it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Drawing a point in a large drawing feels slow, and nothing currently measures the thing the user actually waits for. `update` times the message handler, `wires-build` and friends time the rebuild, but the span between them — press to the frame that shows the new geometry — has no number. Navigation already has exactly that plumbing: `record_nav_perf` stamps an instant when the input arrives, `prepare` and `encode` pick it up, and `nav-prepare` / `nav-render` report `input`, `build`, `prepare` and `elapsed` from the original event. `NavPerfOp::Edit` reuses it. `update` snapshots `geometry_epoch` before dispatch and stamps the sample when it moved, so any message that changed geometry — a drawn point, a grip commit, an undo — reports its full latency rather than only the handler's share. Diagnostic only: `record_nav_perf` sets a pending sample and nothing else, so no LOD or settle behaviour changes. Nothing is optimised here on purpose. Four call sites feed the snapper along different branches, and picking one to instrument before knowing which dominates is how the earlier rounds of this work were wasted. Co-Authored-By: Claude Opus 5 --- src/app/update/mod.rs | 14 ++++++++++++++ src/scene/mod.rs | 5 +++++ 2 files changed, 19 insertions(+) diff --git a/src/app/update/mod.rs b/src/app/update/mod.rs index b80f9ee7c..c612c61d0 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,13 @@ 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(crate::scene::NavPerfOp::Edit, 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..4d20b37a3 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", } } } From d267083a298ad13b67b67d0c4204f40393626a8a Mon Sep 17 00:00:00 2001 From: Panos <25664832+mechpanos@users.noreply.github.com> Date: Tue, 8 Sep 2026 11:34:12 +0300 Subject: [PATCH 2/2] perf: say which message caused an edit's latency MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The first measurement showed four consecutive edits at ~192 ms each with a handler cost of 0.55 ms. That is below the `update` line's 5 ms threshold, so the log reports the latency but not what asked for it — and whether a live command preview is bumping the geometry epoch on every mouse move is exactly the question the numbers raise. `nav-prepare` now carries the message label alongside the op. Co-Authored-By: Claude Opus 5 --- src/app/update/mod.rs | 7 +++++-- src/scene/mod.rs | 14 ++++++++++++++ src/scene/view/render.rs | 3 ++- 3 files changed, 21 insertions(+), 3 deletions(-) diff --git a/src/app/update/mod.rs b/src/app/update/mod.rs index c612c61d0..fe8519aa1 100644 --- a/src/app/update/mod.rs +++ b/src/app/update/mod.rs @@ -334,8 +334,11 @@ impl OpenCADStudio { 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(crate::scene::NavPerfOp::Edit, started); + tab.scene.record_nav_perf_caused( + crate::scene::NavPerfOp::Edit, + perf_label, + started, + ); } } if let Some(started) = perf_started { diff --git a/src/scene/mod.rs b/src/scene/mod.rs index 4d20b37a3..e19534afa 100644 --- a/src/scene/mod.rs +++ b/src/scene/mod.rs @@ -1452,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, @@ -2880,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; } @@ -2892,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,