From a9e7b7767207ccf40bcba04a4c5cad96d6916f13 Mon Sep 17 00:00:00 2001 From: Eric Holk Date: Thu, 16 Apr 2026 10:38:58 -0700 Subject: [PATCH] gpui: Record input-to-frame latency histogram (#53822) Adds instrumentation to track input-to-frame latency in GPUI windows, helping diagnose input responsiveness issues. ## What this does - Records the time between when an input event is dispatched and when the resulting frame is presented, capturing worst-case latency when multiple events are coalesced into a single frame. - Tracks how many input events get coalesced per rendered frame. - Both metrics are stored in [HdrHistogram](https://docs.rs/hdrhistogram) instances with 3 significant digits of precision. - Latency is only recorded when the input event actually causes a redraw (i.e. marks the window dirty), so idle mouse moves and other no-op events don't skew the data. - Adds a `Dump Input Latency Histogram` command that opens a buffer with a formatted report including percentile breakdowns and visual distribution bars. ## Example output The report shows percentile latencies, a bucketed distribution with bar charts, and a per-frame event coalescing breakdown. Release Notes: - N/A --------- Co-authored-by: Claude Sonnet 4.6 Co-authored-by: Cole Miller --- Cargo.lock | 25 ++ Cargo.toml | 3 + crates/gpui/Cargo.toml | 2 + crates/gpui/src/window.rs | 122 +++++++++- crates/input_latency_ui/Cargo.toml | 17 ++ crates/input_latency_ui/LICENSE-GPL | 1 + .../input_latency_ui/src/input_latency_ui.rs | 216 ++++++++++++++++++ crates/zed/Cargo.toml | 7 +- crates/zed/src/zed.rs | 16 ++ 9 files changed, 404 insertions(+), 5 deletions(-) create mode 100644 crates/input_latency_ui/Cargo.toml create mode 120000 crates/input_latency_ui/LICENSE-GPL create mode 100644 crates/input_latency_ui/src/input_latency_ui.rs diff --git a/Cargo.lock b/Cargo.lock index 69269aaf82cea606270192885a9fca0df3b0747d..d90c6f8921577e4e388b4e78c91bdf42a95ca2fc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7584,6 +7584,7 @@ dependencies = [ "gpui_shared_string", "gpui_util", "gpui_web", + "hdrhistogram", "http_client", "image", "inventory", @@ -8065,6 +8066,20 @@ dependencies = [ "hashbrown 0.15.5", ] +[[package]] +name = "hdrhistogram" +version = "7.5.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "765c9198f173dd59ce26ff9f95ef0aafd0a0fe01fb9d72841bc5066a4c06511d" +dependencies = [ + "base64 0.21.7", + "byteorder", + "crossbeam-channel", + "flate2", + "nom 7.1.3", + "num-traits", +] + [[package]] name = "headers" version = "0.3.9" @@ -8815,6 +8830,15 @@ dependencies = [ "generic-array", ] +[[package]] +name = "input_latency_ui" +version = "0.1.0" +dependencies = [ + "chrono", + "gpui", + "hdrhistogram", +] + [[package]] name = "inspector_ui" version = "0.1.0" @@ -22241,6 +22265,7 @@ dependencies = [ "http_client", "image", "image_viewer", + "input_latency_ui", "inspector_ui", "install_cli", "itertools 0.14.0", diff --git a/Cargo.toml b/Cargo.toml index 7c3d79c223a6c0e0b9000de533237465356a6936..dfab0c339c9d995672669a1d3e309c03d8694442 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -103,6 +103,7 @@ members = [ "crates/http_client_tls", "crates/icons", "crates/image_viewer", + "crates/input_latency_ui", "crates/inspector_ui", "crates/install_cli", "crates/journal", @@ -357,6 +358,7 @@ image_viewer = { path = "crates/image_viewer" } edit_prediction_types = { path = "crates/edit_prediction_types" } edit_prediction_ui = { path = "crates/edit_prediction_ui" } edit_prediction_context = { path = "crates/edit_prediction_context" } +input_latency_ui = { path = "crates/input_latency_ui" } inspector_ui = { path = "crates/inspector_ui" } install_cli = { path = "crates/install_cli" } journal = { path = "crates/journal" } @@ -584,6 +586,7 @@ globset = "0.4" heapless = "0.9.2" handlebars = "4.3" heck = "0.5" +hdrhistogram = "7" heed = { version = "0.21.0", features = ["read-txn-no-tls"] } hex = "0.4.3" human_bytes = "0.4.1" diff --git a/crates/gpui/Cargo.toml b/crates/gpui/Cargo.toml index 4bbff0c4bfc7c6c64acbed5bf65c343d66269f64..9dd5a55dd072d9aaedd21dd3904e8c2119c443ca 100644 --- a/crates/gpui/Cargo.toml +++ b/crates/gpui/Cargo.toml @@ -38,6 +38,7 @@ screen-capture = [ "scap", ] windows-manifest = ["dep:embed-resource"] +input-latency-histogram = ["dep:hdrhistogram"] [lib] path = "src/gpui.rs" @@ -96,6 +97,7 @@ sum_tree.workspace = true taffy = "=0.9.0" thiserror.workspace = true gpui_util.workspace = true +hdrhistogram = { workspace = true, optional = true } waker-fn = "1.2.0" lyon = "1.0" pin-project = "1.1.10" diff --git a/crates/gpui/src/window.rs b/crates/gpui/src/window.rs index 86e48def36e73f592d5e9c019c4d89d2fd8fae42..dadc5a6247dc69d1b12fab08b253e1cb1564bd84 100644 --- a/crates/gpui/src/window.rs +++ b/crates/gpui/src/window.rs @@ -28,6 +28,8 @@ use futures::FutureExt; use futures::channel::oneshot; use gpui_util::post_inc; use gpui_util::{ResultExt, measure}; +#[cfg(feature = "input-latency-histogram")] +use hdrhistogram::Histogram; use itertools::FoldWhile::{Continue, Done}; use itertools::Itertools; use parking_lot::RwLock; @@ -105,6 +107,7 @@ struct WindowInvalidatorInner { pub dirty: bool, pub draw_phase: DrawPhase, pub dirty_views: FxHashSet, + pub update_count: usize, } #[derive(Clone)] @@ -119,12 +122,14 @@ impl WindowInvalidator { dirty: true, draw_phase: DrawPhase::None, dirty_views: FxHashSet::default(), + update_count: 0, })), } } pub fn invalidate_view(&self, entity: EntityId, cx: &mut App) -> bool { let mut inner = self.inner.borrow_mut(); + inner.update_count += 1; inner.dirty_views.insert(entity); if inner.draw_phase == DrawPhase::None { inner.dirty = true; @@ -140,13 +145,21 @@ impl WindowInvalidator { } pub fn set_dirty(&self, dirty: bool) { - self.inner.borrow_mut().dirty = dirty + let mut inner = self.inner.borrow_mut(); + inner.dirty = dirty; + if dirty { + inner.update_count += 1; + } } pub fn set_phase(&self, phase: DrawPhase) { self.inner.borrow_mut().draw_phase = phase } + pub fn update_count(&self) -> usize { + self.inner.borrow().update_count + } + pub fn take_views(&self) -> FxHashSet { mem::take(&mut self.inner.borrow_mut().dirty_views) } @@ -958,6 +971,8 @@ pub struct Window { /// Tracks recent input event timestamps to determine if input is arriving at a high rate. /// Used to selectively enable VRR optimization only when input rate exceeds 60fps. pub(crate) input_rate_tracker: Rc>, + #[cfg(feature = "input-latency-histogram")] + input_latency_tracker: InputLatencyTracker, last_input_modality: InputModality, pub(crate) refreshing: bool, pub(crate) activation_observers: SubscriberSet<(), AnyObserver>, @@ -1026,6 +1041,88 @@ impl InputRateTracker { } } +/// A point-in-time snapshot of the input-latency histograms for a window, +/// suitable for external formatting. +#[cfg(feature = "input-latency-histogram")] +pub struct InputLatencySnapshot { + /// Histogram of input-to-frame latency samples, in nanoseconds. + pub latency_histogram: Histogram, + /// Histogram of input events coalesced per rendered frame. + pub events_per_frame_histogram: Histogram, + /// Count of input events that arrived mid-draw and were excluded from + /// latency recording. + pub mid_draw_events_dropped: u64, +} + +/// Records the time between when the first input event in a frame is dispatched +/// and when the resulting frame is presented, capturing worst-case latency when +/// multiple events are coalesced into a single frame. +#[cfg(feature = "input-latency-histogram")] +struct InputLatencyTracker { + /// Timestamp of the first unrendered input event in the current frame; + /// cleared when a frame is presented. + first_input_at: Option, + /// Count of input events received since the last frame was presented. + pending_input_count: u64, + /// Histogram of input-to-frame latency samples, in nanoseconds. + latency_histogram: Histogram, + /// Histogram of input events coalesced per rendered frame. + events_per_frame_histogram: Histogram, + /// Count of input events that arrived mid-draw and were excluded from + /// latency recording because their effects won't appear until the next frame. + mid_draw_events_dropped: u64, +} + +#[cfg(feature = "input-latency-histogram")] +impl InputLatencyTracker { + fn new() -> Result { + Ok(Self { + first_input_at: None, + pending_input_count: 0, + latency_histogram: Histogram::new(3) + .map_err(|e| anyhow!("Failed to create input latency histogram: {e}"))?, + events_per_frame_histogram: Histogram::new(3) + .map_err(|e| anyhow!("Failed to create events per frame histogram: {e}"))?, + mid_draw_events_dropped: 0, + }) + } + + /// Record that an input event was dispatched at the given time. + /// Only the first event's timestamp per frame is retained (worst-case latency). + fn record_input(&mut self, dispatch_time: Instant) { + self.first_input_at.get_or_insert(dispatch_time); + self.pending_input_count += 1; + } + + /// Record that an input event arrived during a draw phase and was excluded + /// from latency tracking. + fn record_mid_draw_input(&mut self) { + self.mid_draw_events_dropped += 1; + } + + /// Record that a frame was presented, flushing pending latency and coalescing samples. + fn record_frame_presented(&mut self) { + if let Some(first_input_at) = self.first_input_at.take() { + let latency_nanos = first_input_at.elapsed().as_nanos() as u64; + self.latency_histogram.record(latency_nanos).ok(); + } + if self.pending_input_count > 0 { + self.events_per_frame_histogram + .record(self.pending_input_count) + .ok(); + self.pending_input_count = 0; + } + } + + fn snapshot(&self) -> InputLatencySnapshot { + InputLatencySnapshot { + latency_histogram: self.latency_histogram.clone(), + events_per_frame_histogram: self.events_per_frame_histogram.clone(), + mid_draw_events_dropped: self.mid_draw_events_dropped, + } + } +} + #[derive(Clone, Copy, Debug, Eq, PartialEq)] pub(crate) enum DrawPhase { None, @@ -1482,6 +1579,8 @@ impl Window { hovered, needs_present, input_rate_tracker, + #[cfg(feature = "input-latency-histogram")] + input_latency_tracker: InputLatencyTracker::new()?, last_input_modality: InputModality::Mouse, refreshing: false, activation_observers: SubscriberSet::new(), @@ -2367,12 +2466,20 @@ impl Window { } #[profiling::function] - fn present(&self) { + fn present(&mut self) { self.platform_window.draw(&self.rendered_frame.scene); + #[cfg(feature = "input-latency-histogram")] + self.input_latency_tracker.record_frame_presented(); self.needs_present.set(false); profiling::finish_frame!(); } + /// Returns a snapshot of the current input-latency histograms. + #[cfg(feature = "input-latency-histogram")] + pub fn input_latency_snapshot(&self) -> InputLatencySnapshot { + self.input_latency_tracker.snapshot() + } + fn draw_roots(&mut self, cx: &mut App) { self.invalidator.set_phase(DrawPhase::Prepaint); self.tooltip_bounds.take(); @@ -4119,6 +4226,9 @@ impl Window { /// Dispatch a mouse or keyboard event on the window. #[profiling::function] pub fn dispatch_event(&mut self, event: PlatformInput, cx: &mut App) -> DispatchEventResult { + #[cfg(feature = "input-latency-histogram")] + let dispatch_time = Instant::now(); + let update_count_before = self.invalidator.update_count(); // Track input modality for focus-visible styling and hover suppression. // Hover is suppressed during keyboard modality so that keyboard navigation // doesn't show hover highlights on the item under the mouse cursor. @@ -4228,8 +4338,14 @@ impl Window { self.dispatch_key_event(any_key_event, cx); } - if self.invalidator.is_dirty() { + if self.invalidator.update_count() > update_count_before { self.input_rate_tracker.borrow_mut().record_input(); + #[cfg(feature = "input-latency-histogram")] + if self.invalidator.not_drawing() { + self.input_latency_tracker.record_input(dispatch_time); + } else { + self.input_latency_tracker.record_mid_draw_input(); + } } DispatchEventResult { diff --git a/crates/input_latency_ui/Cargo.toml b/crates/input_latency_ui/Cargo.toml new file mode 100644 index 0000000000000000000000000000000000000000..94c48bb7e9c08ab291b7362b8d0dbe03ea580699 --- /dev/null +++ b/crates/input_latency_ui/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "input_latency_ui" +version = "0.1.0" +edition.workspace = true +publish.workspace = true +license = "GPL-3.0-or-later" + +[lints] +workspace = true + +[lib] +path = "src/input_latency_ui.rs" + +[dependencies] +chrono.workspace = true +gpui = { workspace = true, features = ["input-latency-histogram"] } +hdrhistogram.workspace = true diff --git a/crates/input_latency_ui/LICENSE-GPL b/crates/input_latency_ui/LICENSE-GPL new file mode 120000 index 0000000000000000000000000000000000000000..89e542f750cd3860a0598eff0dc34b56d7336dc4 --- /dev/null +++ b/crates/input_latency_ui/LICENSE-GPL @@ -0,0 +1 @@ +../../LICENSE-GPL \ No newline at end of file diff --git a/crates/input_latency_ui/src/input_latency_ui.rs b/crates/input_latency_ui/src/input_latency_ui.rs new file mode 100644 index 0000000000000000000000000000000000000000..3fcdaab7eb6c7aca103bea0a2991c55efb0e950e --- /dev/null +++ b/crates/input_latency_ui/src/input_latency_ui.rs @@ -0,0 +1,216 @@ +use gpui::{App, Global, InputLatencySnapshot, Window, actions}; +use hdrhistogram::Histogram; + +actions!( + dev, + [ + /// Opens a buffer showing the input-to-frame latency histogram for the current window. + DumpInputLatencyHistogram, + ] +); + +/// Generates a formatted text report of the input-to-frame latency histogram +/// for the given window. If a previous report was generated (tracked via a +/// global on the `App`), includes a delta section showing changes since that +/// report. +pub fn format_input_latency_report(window: &Window, cx: &mut App) -> String { + let snapshot = window.input_latency_snapshot(); + let state = cx.default_global::(); + let report = format_report(&snapshot, state); + + state.previous_snapshot = Some(snapshot); + state.previous_timestamp = Some(chrono::Local::now()); + + report +} + +#[derive(Default)] +struct ReporterState { + previous_snapshot: Option, + previous_timestamp: Option>, +} + +impl Global for ReporterState {} + +fn format_report(snapshot: &InputLatencySnapshot, previous: &ReporterState) -> String { + let histogram = &snapshot.latency_histogram; + let total = histogram.len(); + + if total == 0 { + return "No input latency samples recorded yet.\n\nTry typing or clicking in a buffer first.".to_string(); + } + + let percentiles: &[(&str, f64)] = &[ + ("min ", 0.0), + ("p50 ", 0.50), + ("p75 ", 0.75), + ("p90 ", 0.90), + ("p95 ", 0.95), + ("p99 ", 0.99), + ("p99.9", 0.999), + ("max ", 1.0), + ]; + + let now = chrono::Local::now(); + + let mut report = String::new(); + report.push_str("Input Latency Histogram\n"); + report.push_str("=======================\n"); + + let timestamp = now.format("%Y-%m-%d %H:%M:%S %Z"); + report.push_str(&format!("Timestamp: {timestamp}\n")); + report.push_str(&format!("Samples: {total}\n")); + if snapshot.mid_draw_events_dropped > 0 { + report.push_str(&format!( + "Mid-draw events excluded: {}\n", + snapshot.mid_draw_events_dropped + )); + } + + write_latency_percentiles(&mut report, "Percentiles", histogram, percentiles); + write_latency_distribution(&mut report, "Distribution", histogram); + + let coalesce = &snapshot.events_per_frame_histogram; + let coalesce_total = coalesce.len(); + if coalesce_total > 0 { + report.push('\n'); + report.push_str("Events coalesced per frame:\n"); + for (label, quantile) in percentiles { + let value = if *quantile == 0.0 { + coalesce.min() + } else if *quantile == 1.0 { + coalesce.max() + } else { + coalesce.value_at_quantile(*quantile) + }; + report.push_str(&format!(" {label}: {value:>6} events\n")); + } + + report.push('\n'); + report.push_str("Distribution:\n"); + let bar_width = 30usize; + let max_count = coalesce.max(); + for n in 1..=max_count { + let count = coalesce + .iter_recorded() + .filter(|value| value.value_iterated_to() == n) + .map(|value| value.count_at_value()) + .sum::(); + if count == 0 { + continue; + } + let fraction = count as f64 / coalesce_total as f64; + let bar_len = (fraction * bar_width as f64) as usize; + let bar = "\u{2588}".repeat(bar_len); + report.push_str(&format!( + " {n:>6} events: {count:>6} ({:>5.1}%) {bar}\n", + fraction * 100.0, + )); + } + } + + // Delta section: compare against the previous report's snapshot. + if let (Some(prev_snapshot), Some(prev_timestamp)) = + (&previous.previous_snapshot, &previous.previous_timestamp) + { + let prev_latency = &prev_snapshot.latency_histogram; + let prev_total = prev_latency.len(); + let delta_total = total - prev_total; + + report.push('\n'); + report.push_str("Delta Since Last Report\n"); + report.push_str("-----------------------\n"); + let prev_ts = prev_timestamp.format("%Y-%m-%d %H:%M:%S %Z"); + let elapsed_secs = (now - *prev_timestamp).num_seconds().max(0); + report.push_str(&format!( + "Previous report: {prev_ts} ({elapsed_secs}s ago)\n" + )); + report.push_str(&format!("New samples: {delta_total}\n")); + + if delta_total > 0 { + let mut delta_histogram = histogram.clone(); + delta_histogram.subtract(prev_latency).ok(); + + write_latency_percentiles( + &mut report, + "Percentiles (new samples only)", + &delta_histogram, + percentiles, + ); + write_latency_distribution( + &mut report, + "Distribution (new samples only)", + &delta_histogram, + ); + } + } + + report +} + +fn write_latency_percentiles( + report: &mut String, + heading: &str, + histogram: &Histogram, + percentiles: &[(&str, f64)], +) { + let ns_to_ms = |ns: u64| ns as f64 / 1_000_000.0; + + report.push('\n'); + report.push_str(heading); + report.push_str(":\n"); + for (label, quantile) in percentiles { + let value_ns = if *quantile == 0.0 { + histogram.min() + } else if *quantile == 1.0 { + histogram.max() + } else { + histogram.value_at_quantile(*quantile) + }; + let hz = if value_ns > 0 { + 1_000_000_000.0 / value_ns as f64 + } else { + f64::INFINITY + }; + report.push_str(&format!( + " {label}: {:>8.2}ms ({:>7.1} Hz)\n", + ns_to_ms(value_ns), + hz + )); + } +} + +fn write_latency_distribution(report: &mut String, heading: &str, histogram: &Histogram) { + const BUCKETS: &[(u64, u64, &str, &str)] = &[ + (0, 4_000_000, "0\u{2013}4ms", "(excellent)"), + (4_000_000, 8_000_000, "4\u{2013}8ms", "(120fps)"), + (8_000_000, 16_000_000, "8\u{2013}16ms", "(60fps)"), + (16_000_000, 33_000_000, "16\u{2013}33ms", "(30fps)"), + (33_000_000, 100_000_000, "33\u{2013}100ms", ""), + (100_000_000, u64::MAX, "100ms+", "(sluggish)"), + ]; + let bar_width = 30usize; + let total = histogram.len() as f64; + + report.push('\n'); + report.push_str(heading); + report.push_str(":\n"); + for (low, high, range, note) in BUCKETS { + let count: u64 = histogram + .iter_recorded() + .filter(|value| value.value_iterated_to() >= *low && value.value_iterated_to() < *high) + .map(|value| value.count_at_value()) + .sum(); + let fraction = if total > 0.0 { + count as f64 / total + } else { + 0.0 + }; + let bar_len = (fraction * bar_width as f64) as usize; + let bar = "\u{2588}".repeat(bar_len); + report.push_str(&format!( + " {range:>8} {note:<11}: {count:>6} ({:>5.1}%) {bar}\n", + fraction * 100.0, + )); + } +} diff --git a/crates/zed/Cargo.toml b/crates/zed/Cargo.toml index 35832b574094237485eb66ac217a215d1adea3fb..d853ee4f4dc88326d08203721c9e2236151fa7c5 100644 --- a/crates/zed/Cargo.toml +++ b/crates/zed/Cargo.toml @@ -117,7 +117,7 @@ git_hosting_providers.workspace = true git_ui.workspace = true go_to_line.workspace = true system_specs.workspace = true -gpui.workspace = true +gpui = { workspace = true, features = ["input-latency-histogram"] } gpui_platform = {workspace = true, features=["screen-capture", "font-kit", "wayland", "x11"]} image = { workspace = true, optional = true } semver.workspace = true @@ -133,6 +133,7 @@ edit_prediction.workspace = true edit_prediction_ui.workspace = true http_client.workspace = true image_viewer.workspace = true +input_latency_ui.workspace = true inspector_ui.workspace = true install_cli.workspace = true journal.workspace = true @@ -228,6 +229,7 @@ zlog_settings.workspace = true etw_tracing.workspace = true windows.workspace = true gpui = { workspace = true, features = [ + "input-latency-histogram", "windows-manifest", ] } @@ -236,6 +238,7 @@ winresource = "0.1" [target.'cfg(any(target_os = "linux", target_os = "freebsd"))'.dependencies] gpui = { workspace = true, features = [ + "input-latency-histogram", "wayland", "x11", ] } @@ -252,7 +255,7 @@ pkg-config = "0.3.22" [dev-dependencies] call = { workspace = true, features = ["test-support"] } editor = { workspace = true, features = ["test-support"] } -gpui = { workspace = true, features = ["test-support"] } +gpui = { workspace = true, features = ["input-latency-histogram", "test-support"] } image_viewer = { workspace = true, features = ["test-support"] } itertools.workspace = true language = { workspace = true, features = ["test-support"] } diff --git a/crates/zed/src/zed.rs b/crates/zed/src/zed.rs index c3c02b83cbc4bbdd6d10b59af4c3fac652a9599c..71f7ab51f255aa109341b5ca17508da74237e3aa 100644 --- a/crates/zed/src/zed.rs +++ b/crates/zed/src/zed.rs @@ -782,6 +782,22 @@ fn register_actions( ) { workspace .register_action(|_, _: &OpenDocs, _, cx| cx.open_url(DOCS_URL)) + .register_action( + |workspace: &mut Workspace, + _: &input_latency_ui::DumpInputLatencyHistogram, + window: &mut Window, + cx: &mut Context| { + let report = + input_latency_ui::format_input_latency_report(window, cx); + let project = workspace.project().clone(); + let buffer = project.update(cx, |project, cx| { + project.create_local_buffer(&report, None, true, cx) + }); + let editor = + cx.new(|cx| Editor::for_buffer(buffer, Some(project), window, cx)); + workspace.add_item_to_active_pane(Box::new(editor), None, true, window, cx); + }, + ) .register_action(|_, _: &Minimize, window, _| { window.minimize_window(); })