diff --git a/Cargo.lock b/Cargo.lock index d28325ea22..e138b408e7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -22938,6 +22938,7 @@ dependencies = [ "gpui", "gpui_platform", "gpui_tokio", + "hdrhistogram", "http_client", "image", "image_viewer", diff --git a/corgi.toml b/corgi.toml index b9e1edfb47..ed25f62776 100644 --- a/corgi.toml +++ b/corgi.toml @@ -64,7 +64,12 @@ profiles = ["release"] proto = ["proto/**"] livekit_api = ["vendored/protocol/**"] media = ["src/bindings.h"] -gpui = ["README.md"] +gpui = [ + "README.md", + "examples/image/exif-orientation-rotate-180.jpg", + "../../assets/fonts/ibm-plex-sans/IBMPlexSans-Regular.ttf", + "../../assets/fonts/lilex/Lilex-Regular.ttf", +] git = ["src/checkpoint.gitignore"] git_ui = ["src/commit_message_prompt.txt"] editor = ["../grammars/src/**"] diff --git a/crates/gpui/src/app.rs b/crates/gpui/src/app.rs index 2888824c96..27562e5e53 100644 --- a/crates/gpui/src/app.rs +++ b/crates/gpui/src/app.rs @@ -942,6 +942,8 @@ impl App { init_app_menus(platform.as_ref(), &app.borrow()); SystemWindowTabController::init(&mut app.borrow_mut()); + #[cfg(feature = "profiler")] + crate::profiler::journal::observe_power(&app.borrow()); platform.on_keyboard_layout_change(Box::new({ let app = Rc::downgrade(&app); diff --git a/crates/gpui/src/profiler.rs b/crates/gpui/src/profiler.rs index 340f054b9c..e8108c106b 100644 --- a/crates/gpui/src/profiler.rs +++ b/crates/gpui/src/profiler.rs @@ -961,17 +961,26 @@ impl WindowProfiler { return; }; - journal::record_input(journal::InputTiming { - kind, - start: started_at, - end: Instant::now(), - caused_invalidation, - }); + if !journal::power_interrupted_since(started_at) { + journal::record_input(journal::InputTiming { + kind, + start: started_at, + end: Instant::now(), + caused_invalidation, + }); + } journal::end_foreground_turn(); - if !caused_invalidation { + if !caused_invalidation || !journal::frame_sample_is_valid(self.window_id, started_at) { return; } + if self + .first_input_at + .is_some_and(|at| !journal::frame_sample_is_valid(self.window_id, at)) + { + self.first_input_at = None; + self.pending_input_count = 0; + } let arrived_during_draw = self .active_activities @@ -1003,11 +1012,13 @@ impl WindowProfiler { journal::end_foreground_turn(); return; }; - journal::record_action(ActionTiming { - name, - start, - end: Instant::now(), - }); + if !journal::power_interrupted_since(start) { + journal::record_action(ActionTiming { + name, + start, + end: Instant::now(), + }); + } journal::end_foreground_turn(); } @@ -1034,13 +1045,15 @@ impl WindowProfiler { let draw_end = Instant::now(); let frame_timing = FrameTiming { window_id: self.window_id, - dirty_at, + dirty_at: dirty_at.filter(|at| journal::frame_sample_is_valid(self.window_id, *at)), invalidations, draw_start, draw_end, }; let draw_duration = frame_timing.draw_duration(); - self.record_draw_timing(frame_timing); + if !journal::power_interrupted_since(draw_start) { + self.record_draw_timing(frame_timing); + } journal::end_foreground_turn(); draw_duration } @@ -1089,21 +1102,33 @@ impl WindowProfiler { window_active: bool, next_frame_scheduled: bool, ) { - if let Some(first_input_at) = self.first_input_at.take() { + if let Some(first_input_at) = self.first_input_at.take() + && journal::frame_sample_is_valid(self.window_id, first_input_at) + { let latency_nanos = present_end.duration_since(first_input_at).as_nanos() as u64; self.input_latency_histogram.record(latency_nanos).ok(); + if self.pending_input_count > 0 { + self.events_per_frame_histogram + .record(self.pending_input_count) + .ok(); + } } - if self.pending_input_count > 0 { - self.events_per_frame_histogram - .record(self.pending_input_count) - .ok(); - self.pending_input_count = 0; - } + self.pending_input_count = 0; - let frame = self.pending_frame.take(); + let frame = self + .pending_frame + .take() + .filter(|frame| journal::frame_sample_is_valid(self.window_id, frame.draw_start)) + .map(|mut frame| { + frame.dirty_at = frame + .dirty_at + .filter(|at| journal::frame_sample_is_valid(self.window_id, *at)); + frame + }); let animation_interval = if frame.is_some() && self.animating_at_last_present && window_active { self.last_present_at + .filter(|at| journal::frame_sample_is_valid(self.window_id, *at)) .map(|last_present_at| present_end.duration_since(last_present_at)) } else { None @@ -1241,6 +1266,43 @@ mod tests { use super::*; use std::sync::{Mutex, MutexGuard}; + #[test] + fn interruptions_drop_latency_samples_but_hiding_keeps_draw_work() { + for sleep in [false, true] { + let (_journal, _guard) = journal::install_test_foreground_journal(64, 4); + let id = WindowId::from(1); + let mut profiler = WindowProfiler::new(id).expect("valid histograms"); + let old = Instant::now() - Duration::from_secs(1); + record_test_draw(&mut profiler, old); + profiler.record_present_at(old, old, true, true); + profiler.first_input_at = Some(old); + profiler.pending_input_count = 1; + profiler.begin_draw(); + if sleep { + journal::record_power_transition(journal::PowerState::Suspended); + journal::record_power_transition(journal::PowerState::Awake); + } else { + journal::record_window_visibility(id, crate::WindowVisibility::Hidden); + journal::record_window_visibility(id, crate::WindowVisibility::Visible); + } + profiler.end_draw(Some(old), 1); + let now = Instant::now(); + profiler.record_present_at(now, now, true, true); + assert_eq!( + profiler.draw_duration_histogram.len(), + if sleep { 1 } else { 2 } + ); + assert_eq!(profiler.input_latency_histogram.len(), 0); + assert_eq!(profiler.dirty_to_present_histogram.len(), 1); + assert_eq!(profiler.present_interval_histogram.len(), 0); + profiler.begin_draw(); + profiler.end_draw(Some(Instant::now()), 1); + let now = Instant::now(); + profiler.record_present_at(now, now, true, true); + assert_eq!(profiler.dirty_to_present_histogram.len(), 2); + } + } + #[test] fn records_draw_events_only_while_tracing() { let _trace_test_guard = TraceTestGuard::new(); diff --git a/crates/gpui/src/profiler/hang.rs b/crates/gpui/src/profiler/hang.rs index 7aea645b81..23d63aa658 100644 --- a/crates/gpui/src/profiler/hang.rs +++ b/crates/gpui/src/profiler/hang.rs @@ -15,6 +15,9 @@ use std::time::Duration; use scheduler::Instant; use serde::Serialize; +/// Version of the power/visibility-aware measurement rules. +pub const MEASUREMENT_VERSION: u32 = 2; + use super::SerializedLocation; use super::journal::{ ForegroundEvent, ForegroundJournal, ForegroundJournalCollector, ForegroundJournalEntry, @@ -111,6 +114,8 @@ impl HangDetector { /// locations as plain data, contributor count capped by the converter. #[derive(Debug, Clone, Serialize)] pub struct SerializedHangIncident { + /// Identifies the rules used to exclude interrupted measurements. + pub measurement_version: u32, /// `"startup"` when the active window began before the first observed /// newly drawn frame finished platform submission (see /// [`HangDetector::first_present_at`]), otherwise `"steady"`. @@ -133,7 +138,7 @@ pub struct SerializedHangIncident { /// For presentation-sealed incidents, how long the submitted frame had /// been dirty, in milliseconds. pub dirty_to_present_ms: Option, - /// What closed the incident: `"present"` or `"idle"`. This labels the + /// What closed the incident: `"present"`, `"idle"`, or `"power_transition"`. This labels the /// boundary, not the hang's cause — the cause is the first contributor. pub sealed_by: &'static str, /// Fraction of the active window the foreground spent working, @@ -269,6 +274,7 @@ impl SerializedHangIncident { Some(first_present_at) if active_start >= first_present_at => "steady", _ => "startup", }, + measurement_version: MEASUREMENT_VERSION, trigger: incident.trigger, start_ms: since_startup(active_start), active_ms: as_millis(active), @@ -281,11 +287,12 @@ impl SerializedHangIncident { IntervalBoundary::Presented(presented) => { presented.dirty_to_present_duration().map(as_millis) } - IntervalBoundary::Idle { .. } => None, + IntervalBoundary::Idle { .. } | IntervalBoundary::PowerTransition { .. } => None, }, sealed_by: match snapshot.boundary { IntervalBoundary::Presented(_) => "present", IntervalBoundary::Idle { .. } => "idle", + IntervalBoundary::PowerTransition { .. } => "power_transition", }, busy_fraction: (busy_fraction * 1000.0).round() / 1000.0, event_count: snapshot.events.len(), diff --git a/crates/gpui/src/profiler/journal.rs b/crates/gpui/src/profiler/journal.rs index 761181a0ad..ed6ac6c588 100644 --- a/crates/gpui/src/profiler/journal.rs +++ b/crates/gpui/src/profiler/journal.rs @@ -21,10 +21,17 @@ use std::sync::{ }; use std::time::Duration; +use gpui_util::ResultExt; use scheduler::Instant; use super::{ActionTiming, FrameTiming, PresentTiming, TaskTiming}; -use crate::WindowId; +use crate::{App, WindowId, WindowVisibility}; + +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub(crate) enum PowerState { + Awake, + Suspended, +} /// Task polls shorter than this are folded into a [`PollSummary`] instead of /// being recorded individually. This keeps the stream bounded by the number @@ -182,6 +189,11 @@ pub enum IntervalBoundary { /// When the foreground went idle. ended_at: Instant, }, + /// A power notification interrupted the measurement interval. + PowerTransition { + /// When the foreground received the notification. + ended_at: Instant, + }, } impl IntervalBoundary { @@ -189,7 +201,7 @@ impl IntervalBoundary { pub fn end_time(&self) -> Instant { match self { Self::Presented(presented) => presented.presentation.present_end, - Self::Idle { ended_at } => *ended_at, + Self::Idle { ended_at } | Self::PowerTransition { ended_at } => *ended_at, } } @@ -197,7 +209,7 @@ impl IntervalBoundary { pub fn dirty_at(&self) -> Option { match self { Self::Presented(presented) => presented.frame.dirty_at, - Self::Idle { .. } => None, + Self::Idle { .. } | Self::PowerTransition { .. } => None, } } } @@ -379,11 +391,31 @@ impl ForegroundRunnableCounter { } } +// Visibility and power changes clear `dirty_at`; `Window::refresh_visibility` +// re-records the frame from the window's actual dirty state afterwards. +struct WindowFrameState { + visibility: WindowVisibility, + dirty_at: Option, + visibility_changed_at: Option, +} + +impl WindowFrameState { + fn new(visibility: WindowVisibility) -> Self { + Self { + visibility, + dirty_at: None, + visibility_changed_at: None, + } + } +} + struct ForegroundJournalWriter { foreground_runnables: ForegroundRunnableCounter, publisher: JournalPublisher, turn_depth: usize, - pending_frames: HashMap, + windows: HashMap, + power: PowerState, + power_changed_at: Option, retained_since_boundary: bool, small_polls: Option, } @@ -394,7 +426,9 @@ impl ForegroundJournalWriter { foreground_runnables, publisher, turn_depth: 0, - pending_frames: HashMap::new(), + windows: HashMap::new(), + power: PowerState::Awake, + power_changed_at: None, retained_since_boundary: false, small_polls: None, } @@ -434,12 +468,51 @@ impl ForegroundJournalWriter { } fn has_unexpired_pending_frame(&mut self, now: Instant) -> bool { - if self.pending_frames.is_empty() { - return false; + for window in self.windows.values_mut() { + if window + .dirty_at + .is_some_and(|at| now.saturating_duration_since(at) >= FRAME_DEADLINE) + { + window.dirty_at = None; + } + } + self.power == PowerState::Awake + && self + .windows + .values() + .any(|window| window.dirty_at.is_some()) + } + + fn power_transition(&mut self, power: PowerState, at: Instant) { + if self.power == power { + return; + } + self.record_entry(ForegroundJournalEntry::Boundary( + IntervalBoundary::PowerTransition { ended_at: at }, + )); + self.power = power; + self.power_changed_at = Some(at); + for window in self.windows.values_mut() { + window.dirty_at = None; + } + } + + /// Whether work that started at `start` spans a sleep or a wake, and so + /// must not be measured as uninterrupted foreground work. + fn power_interrupted_since(&self, start: Instant) -> bool { + self.power == PowerState::Suspended || self.power_changed_at.is_some_and(|at| start <= at) + } + + fn set_visibility(&mut self, id: WindowId, visibility: WindowVisibility, at: Instant) { + let window = self + .windows + .entry(id) + .or_insert_with(|| WindowFrameState::new(visibility)); + if window.visibility != visibility { + window.visibility = visibility; + window.visibility_changed_at = Some(at); + window.dirty_at = None; } - self.pending_frames - .retain(|_, dirty_at| now.saturating_duration_since(*dirty_at) < FRAME_DEADLINE); - !self.pending_frames.is_empty() } fn fold_small_poll(&mut self, timing: TaskTiming) { @@ -480,17 +553,20 @@ impl ForegroundJournalWriter { } fn record_frame_pending(&mut self, window_id: WindowId, dirty_at: Instant) { - let should_record = match self.pending_frames.get(&window_id) { - Some(previous_dirty_at) => { - dirty_at.saturating_duration_since(*previous_dirty_at) >= FRAME_DEADLINE - } - None => true, - }; - if !should_record { + let window = self + .windows + .entry(window_id) + .or_insert_with(|| WindowFrameState::new(WindowVisibility::Visible)); + if self.power == PowerState::Suspended + || !window.visibility.is_visible() + || window + .dirty_at + .is_some_and(|at| dirty_at.saturating_duration_since(at) < FRAME_DEADLINE) + { return; } - self.pending_frames.insert(window_id, dirty_at); + window.dirty_at = Some(dirty_at); self.record_frame_state(FrameStateChange::Pending { window_id, dirty_at, @@ -498,14 +574,19 @@ impl ForegroundJournalWriter { } fn record_window_closed(&mut self, window_id: WindowId, at: Instant) { - self.pending_frames.remove(&window_id); + self.windows.remove(&window_id); self.record_frame_state(FrameStateChange::Closed { window_id, at }); } fn record_present(&mut self, timing: PresentTiming, frame: Option) { + if let Some(window) = self.windows.get_mut(&timing.window_id) { + window.dirty_at = None; + } + if self.power_interrupted_since(timing.present_start) { + return; + } match frame { Some(frame) => { - self.pending_frames.remove(&frame.window_id); self.record_entry(ForegroundJournalEntry::Boundary( IntervalBoundary::Presented(PresentedFrame { frame, @@ -514,7 +595,6 @@ impl ForegroundJournalWriter { )); } None => { - self.pending_frames.remove(&timing.window_id); self.record_event(ForegroundEvent::Present(timing)); } } @@ -605,6 +685,58 @@ fn with_journal(f: impl FnOnce(&mut ForegroundJournalWriter)) { }); } +pub(crate) fn observe_power(cx: &App) { + cx.on_system_sleep(|_| { + record_power_transition(PowerState::Suspended); + }) + .detach(); + // Visibility notifications delivered during sleep may have been missed. + cx.on_system_wake(|cx| { + record_power_transition(PowerState::Awake); + cx.spawn(async |cx| { + cx.update(|cx| { + for handle in cx.windows() { + handle + .update(cx, |_, window, cx| window.refresh_visibility(cx)) + .log_err(); + } + }); + }) + .detach(); + }) + .detach(); +} + +pub(crate) fn record_power_transition(state: PowerState) { + with_journal(|journal| journal.power_transition(state, Instant::now())); +} + +/// Whether work that started at `start` spans a sleep or a wake. Such work +/// is dropped rather than measured. +pub(crate) fn power_interrupted_since(start: Instant) -> bool { + let mut interrupted = false; + with_journal(|journal| interrupted = journal.power_interrupted_since(start)); + interrupted +} + +pub(crate) fn record_window_visibility(id: WindowId, visibility: WindowVisibility) { + with_journal(|journal| journal.set_visibility(id, visibility, Instant::now())); +} + +/// Whether a frame sample that started at `start` was measured while the +/// window stayed visible and the system stayed awake. +pub(crate) fn frame_sample_is_valid(id: WindowId, start: Instant) -> bool { + let mut valid = true; + with_journal(|journal| { + valid = !journal.power_interrupted_since(start) + && journal.windows.get(&id).is_none_or(|window| { + window.visibility.is_visible() + && window.visibility_changed_at.is_none_or(|at| start > at) + }); + }); + valid +} + // TODO(gpui-profiler): the turn brackets in the dispatchers and // WindowProfiler are bare begin/end call pairs rather than uses of this // guard. A caught unwind between a pair leaves `turn_depth` (and potentially @@ -636,6 +768,10 @@ pub(crate) fn end_foreground_turn() { pub(crate) fn record_task_poll(timing: TaskTiming) { FOREGROUND_RUNNABLES.with(ForegroundRunnableCounter::finished); with_journal(|journal| { + if journal.power_interrupted_since(timing.start) { + journal.end_turn(timing.end.0); + return; + } if timing.poll_duration() >= TASK_POLL_FLOOR { journal.record_event(ForegroundEvent::TaskPoll(timing)); } else { @@ -1100,6 +1236,96 @@ mod tests { use super::*; use crate::{WindowId, profiler::YieldTime}; + #[gpui::test] + fn wake_rechecks_native_visibility(cx: &mut crate::TestAppContext) { + use crate::PlatformWindow as _; + let handle = cx.add_window(|_, _| crate::Empty); + let platform = cx.test_window(handle.into()); + platform.on_visibility_change(Box::new(|_| {})); + platform.simulate_visibility_change(WindowVisibility::Hidden); + handle + .update(cx, |_, window, _| assert!(window.is_visible())) + .expect("window"); + cx.update(|cx| { + cx.system_wake_observers + .clone() + .retain(&(), |callback| callback(cx)) + }); + cx.run_until_parked(); + handle + .update(cx, |_, window, _| assert!(!window.is_visible())) + .expect("window"); + } + + #[test] + fn power_interruption_drops_the_poll_before_small_poll_folding() { + let (journal, _guard) = install_test_foreground_journal(32, 4); + let mut collector = journal.collector(); + let start = Instant::now(); + begin_foreground_turn(); + record_power_transition(PowerState::Suspended); + record_power_transition(PowerState::Awake); + assert!(power_interrupted_since(start)); + record_task_poll(task_timing(start, start + Duration::from_micros(10))); + assert!( + collector + .collect_unseen() + .entries + .iter() + .all(|entry| matches!( + entry, + ForegroundJournalEntry::Boundary(IntervalBoundary::PowerTransition { .. }) + )) + ); + with_journal(|writer| assert!(writer.small_polls.is_none())); + begin_foreground_turn(); + let start = Instant::now(); + assert!(!power_interrupted_since(start)); + record_task_poll(task_timing(start, start + TASK_POLL_FLOOR)); + assert!( + collector + .collect_unseen() + .entries + .iter() + .any(|entry| matches!( + entry, + ForegroundJournalEntry::Event(ForegroundEvent::TaskPoll(_)) + )) + ); + } + + #[test] + fn visibility_and_power_changes_clear_pending_frames() { + let (mut writer, _) = test_journal(ForegroundRunnableCounter::new()); + let start = Instant::now(); + let first = WindowId::from(1); + let second = WindowId::from(2); + writer.set_visibility(first, WindowVisibility::Hidden, start); + writer.record_frame_pending(first, start); + assert!(!writer.has_unexpired_pending_frame(start)); + writer.record_frame_pending(second, start); + assert!(writer.has_unexpired_pending_frame(start)); + writer.set_visibility(second, WindowVisibility::Hidden, start); + assert!(!writer.has_unexpired_pending_frame(start)); + writer.set_visibility(first, WindowVisibility::Visible, start); + writer.record_frame_pending(first, start); + assert!(writer.has_unexpired_pending_frame(start)); + writer.power_transition(PowerState::Suspended, start); + assert_eq!(writer.windows[&first].dirty_at, None); + writer.record_frame_pending(first, start); + assert!(!writer.has_unexpired_pending_frame(start)); + // A repeated notification is not a transition. + writer.power_transition(PowerState::Suspended, start + FRAME_DEADLINE); + assert_eq!(writer.power_changed_at, Some(start)); + writer.power_transition(PowerState::Awake, start); + writer.record_frame_pending(first, start); + assert!(writer.has_unexpired_pending_frame(start)); + writer.record_present(presentation_timing(first, start + FRAME_DEADLINE), None); + assert_eq!(writer.windows[&first].dirty_at, None); + writer.record_window_closed(first, start); + assert!(!writer.windows.contains_key(&first)); + } + #[test] fn draw_waits_for_its_presentation_boundary() { let start = Instant::now(); @@ -1152,7 +1378,7 @@ mod tests { IntervalBoundary::Presented(presented) => { presented.dirty_to_present_duration() } - IntervalBoundary::Idle { .. } => None, + IntervalBoundary::Idle { .. } | IntervalBoundary::PowerTransition { .. } => None, }, Some(Duration::from_millis(5)) ); @@ -1978,6 +2204,7 @@ mod tests { boundary_kind: match snapshot.boundary { IntervalBoundary::Idle { .. } => 0, IntervalBoundary::Presented(_) => 1, + IntervalBoundary::PowerTransition { .. } => 2, }, interval_end: snapshot.interval_end().duration_since(origin).as_micros() as u64, events: snapshot @@ -2076,6 +2303,7 @@ mod tests { boundary_kind: match boundary { IntervalBoundary::Idle { .. } => 0, IntervalBoundary::Presented(_) => 1, + IntervalBoundary::PowerTransition { .. } => 2, }, interval_end, events: std::mem::take(&mut events), @@ -2687,7 +2915,14 @@ mod tests { ); prop_assert_eq!(writer.turn_depth, model.turn_depth); prop_assert_eq!(writer.retained_since_boundary, model.retained_since_boundary); - prop_assert_eq!(writer.pending_frames.len(), model.pending_frames.len()); + prop_assert_eq!( + writer + .windows + .values() + .filter(|window| window.dirty_at.is_some()) + .count(), + model.pending_frames.len() + ); } } } diff --git a/crates/gpui/src/window.rs b/crates/gpui/src/window.rs index c39e577cec..62d1d5d7ee 100644 --- a/crates/gpui/src/window.rs +++ b/crates/gpui/src/window.rs @@ -1572,6 +1572,8 @@ impl Window { let invalidator = WindowInvalidator::new(handle.window_id()); let active = Rc::new(Cell::new(platform_window.is_active())); let visibility = platform_window.visibility(); + #[cfg(feature = "profiler")] + profiler::journal::record_window_visibility(handle.window_id(), visibility); let hovered = Rc::new(Cell::new(platform_window.is_hovered())); let needs_present = Rc::new(Cell::new(false)); let next_frame_callbacks: Rc>> = Default::default(); @@ -1901,17 +1903,10 @@ impl Window { })); platform_window.on_visibility_change(Box::new({ let mut cx = cx.to_async(); - move |visibility| { + move |_| { handle .update(&mut cx, |_, window, cx| { - if window.visibility == visibility { - return; - } - window.visibility = visibility; - window - .visibility_observers - .clone() - .retain(&(), |callback| callback(visibility, window, cx)); + window.refresh_visibility(cx); }) .log_err(); } @@ -2151,6 +2146,22 @@ impl Window { } } + pub(crate) fn refresh_visibility(&mut self, cx: &mut App) { + let visibility = self.platform_window.visibility(); + if self.visibility != visibility { + self.visibility = visibility; + #[cfg(feature = "profiler")] + profiler::journal::record_window_visibility(self.handle.window_id(), visibility); + self.visibility_observers + .clone() + .retain(&(), |callback| callback(visibility, self, cx)); + } + #[cfg(feature = "profiler")] + if self.invalidator.is_dirty() || self.needs_present.get() { + profiler::journal::record_frame_pending(self.handle.window_id(), Instant::now()); + } + } + /// Whether the platform is presenting this window's frames (see /// [`WindowVisibility`]). pub fn visibility(&self) -> WindowVisibility { diff --git a/crates/input_latency_ui/src/input_latency_ui.rs b/crates/input_latency_ui/src/input_latency_ui.rs index a1961a2254..dced138039 100644 --- a/crates/input_latency_ui/src/input_latency_ui.rs +++ b/crates/input_latency_ui/src/input_latency_ui.rs @@ -164,6 +164,7 @@ pub fn report_input_latency_telemetry(window: &Window, cx: &mut App) { frames_with_2_events = frames_with_2_events, frames_with_3_events = frames_with_3_events, report_window_seconds = report_window_seconds, + measurement_version = gpui::profiler::hang::MEASUREMENT_VERSION, ); } @@ -264,6 +265,7 @@ pub fn report_frame_duration_telemetry(window: &Window, cx: &mut App) { let intervals_18to36 = count_frames_in_range(&delta_intervals, MS18_NS, MS36_NS); let intervals_36to100 = count_frames_in_range(&delta_intervals, MS36_NS, MS100_NS); // intervals > 100ms are implicitly total_intervals - (the buckets above) + let average_present_interval_ms = delta_intervals.mean() / 1_000_000.0; let average_dirty_to_present_ms = delta_dirty_to_present.mean() / 1_000_000.0; telemetry::event!( @@ -278,9 +280,17 @@ pub fn report_frame_duration_telemetry(window: &Window, cx: &mut App) { intervals_18to36 = intervals_18to36, intervals_36to100 = intervals_36to100, total_intervals = total_intervals, + average_present_interval_ms = average_present_interval_ms, average_dirty_to_present_ms = average_dirty_to_present_ms, + dirty_to_present_samples = delta_dirty_to_present.len(), + dirty_to_present_p50_ms = + delta_dirty_to_present.value_at_quantile(0.5) as f64 / 1_000_000.0, + dirty_to_present_p95_ms = + delta_dirty_to_present.value_at_quantile(0.95) as f64 / 1_000_000.0, + dirty_to_present_max_ms = delta_dirty_to_present.max() as f64 / 1_000_000.0, root_entity_type_name = window_handle.root_entity_type_name(), report_window_seconds = report_window_seconds, + measurement_version = gpui::profiler::hang::MEASUREMENT_VERSION, ); } diff --git a/crates/zed/Cargo.toml b/crates/zed/Cargo.toml index f6dce662c3..3a450781d8 100644 --- a/crates/zed/Cargo.toml +++ b/crates/zed/Cargo.toml @@ -128,6 +128,7 @@ gpui_platform = { workspace = true, features = [ "x11", ] } gpui_tokio.workspace = true +hdrhistogram.workspace = true image = { workspace = true, optional = true } spin = "0.10.0" itertools.workspace = true diff --git a/crates/zed/src/reliability/hang_detection/telemetry.rs b/crates/zed/src/reliability/hang_detection/telemetry.rs index c1bf9e4d5e..32f2e08af4 100644 --- a/crates/zed/src/reliability/hang_detection/telemetry.rs +++ b/crates/zed/src/reliability/hang_detection/telemetry.rs @@ -1,6 +1,7 @@ use std::time::{Duration, Instant}; use gpui::profiler::hang::{HangTrigger, SerializedHangIncident}; +use hdrhistogram::Histogram; /// Cap on incidents per telemetry event. When more accrue between sends, the /// ones with the largest stalls are kept and the incident counts still cover @@ -16,6 +17,8 @@ pub struct Reporter { pending: Vec, threshold_incidents: u64, budget_incidents: u64, + // Every incident's stall, in milliseconds; `pending` keeps only the largest. + stalls: Histogram, } impl Reporter { @@ -25,6 +28,7 @@ impl Reporter { pending: Vec::new(), threshold_incidents: 0, budget_incidents: 0, + stalls: Histogram::new(3).expect("3 significant figures is a valid histogram"), } } @@ -33,6 +37,7 @@ impl Reporter { HangTrigger::Threshold => self.threshold_incidents += 1, HangTrigger::Budget => self.budget_incidents += 1, } + self.stalls.record(incident.stall_ms as u64).ok(); self.pending.push(incident); if self.pending.len() > MAX_REPORTED_INCIDENTS { self.pending @@ -47,11 +52,12 @@ impl Reporter { } } + // Sends even without incidents so summing `report_window_seconds` gives the + // observed time when computing incident rates. pub fn send(&mut self) { - self.last_send = Instant::now(); - if self.pending.is_empty() { - return; - } + let now = Instant::now(); + let report_window_seconds = now.duration_since(self.last_send).as_secs(); + self.last_send = now; let mut incidents = std::mem::take(&mut self.pending); incidents.sort_by(|a, b| b.stall_ms.total_cmp(&a.stall_ms)); let threshold_incidents = std::mem::take(&mut self.threshold_incidents); @@ -64,7 +70,13 @@ impl Reporter { incidents, total_incidents, threshold_incidents, - budget_incidents + budget_incidents, + stall_p50_ms = self.stalls.value_at_quantile(0.5), + stall_p95_ms = self.stalls.value_at_quantile(0.95), + stall_max_ms = self.stalls.max(), + report_window_seconds, + measurement_version = gpui::profiler::hang::MEASUREMENT_VERSION ); + self.stalls.reset(); } }