diff --git a/Cargo.lock b/Cargo.lock index 3b43b47d9b..17bd0a8319 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -8116,6 +8116,7 @@ dependencies = [ "gpui_util", "gpui_web", "hdrhistogram", + "heapless", "http_client", "image", "inventory", @@ -23499,6 +23500,7 @@ dependencies = [ "gpui", "gpui_platform", "gpui_tokio", + "hdrhistogram", "http_client", "image", "image_viewer", diff --git a/crates/fs/src/fs_watcher.rs b/crates/fs/src/fs_watcher.rs index 062e543daf..c4138a084d 100644 --- a/crates/fs/src/fs_watcher.rs +++ b/crates/fs/src/fs_watcher.rs @@ -430,6 +430,10 @@ fn push_notify_event( .collect::>(); if event.need_rescan() { + if !watcher_logging_rate_limited() { + log::warn!("filesystem watcher lost sync for {watched_root:?}; scheduling rescan"); + } + path_events.retain(|path_event| path_event.path != watched_root); path_events.push(PathEvent { path: watched_root.to_path_buf(), @@ -440,6 +444,28 @@ fn push_notify_event( enqueue_path_events(tx, pending_path_events, path_events); } +fn watcher_logging_rate_limited() -> bool { + static LAST_WARN: Mutex> = Mutex::new(None); + let Some((ref mut started, ref mut emitted)) = *LAST_WARN.lock() else { + *LAST_WARN.lock() = Some((Instant::now(), 0)); + return false; + }; + + if started.elapsed().as_secs() < 1 { + if *emitted < 20 { + log::warn!("filesystem watcher lost sync for many files, not logging more"); + return true; + } else { + *emitted += 1; + } + } else { + *emitted = 0; + *started = Instant::now() + } + + true +} + fn coalesce_pending_rescans(pending_paths: &mut Vec, path_events: &mut Vec) { if !path_events .iter() diff --git a/crates/gpui/Cargo.toml b/crates/gpui/Cargo.toml index 64b568a22f..960963ea35 100644 --- a/crates/gpui/Cargo.toml +++ b/crates/gpui/Cargo.toml @@ -107,6 +107,7 @@ pollster.workspace = true url.workspace = true uuid.workspace = true web-time.workspace = true +heapless.workspace = true [target.'cfg(target_family = "wasm")'.dependencies] getrandom = { version = "0.3.4", features = ["wasm_js"] } diff --git a/crates/gpui/src/action.rs b/crates/gpui/src/action.rs index a47ebe69f0..b270bd0965 100644 --- a/crates/gpui/src/action.rs +++ b/crates/gpui/src/action.rs @@ -342,6 +342,10 @@ impl ActionRegistry { Ok(self.build_action(name, None)?) } + pub(crate) fn try_resolve_action(&self, type_id: &TypeId) -> Option<&'static str> { + self.names_by_type_id.get(type_id).copied() + } + /// Construct an action based on its name and optional JSON parameters sourced from the keymap. pub fn build_action( &self, diff --git a/crates/gpui/src/app.rs b/crates/gpui/src/app.rs index 71b5b258bd..22a05b450e 100644 --- a/crates/gpui/src/app.rs +++ b/crates/gpui/src/app.rs @@ -72,7 +72,7 @@ mod test_context; mod visual_test_context; /// The duration for which futures returned from [Context::on_app_quit] can run before the application fully quits. -pub const SHUTDOWN_TIMEOUT: Duration = Duration::from_millis(100); +pub const SHUTDOWN_TIMEOUT: Duration = Duration::from_millis(200); /// Temporary(?) wrapper around [`RefCell`] to help us debug any double borrows. /// Strongly consider removing after stabilization. @@ -862,7 +862,7 @@ impl App { } /// Quit the application gracefully. Handlers registered with [`Context::on_app_quit`] - /// will be given 100ms to complete before exiting. + /// will be given `SHUTDOWN_TIMEOUT` to complete before exiting. pub fn shutdown(&mut self) { let mut futures = Vec::new(); diff --git a/crates/gpui/src/elements/div.rs b/crates/gpui/src/elements/div.rs index a95f8ff92d..5287e12bfe 100644 --- a/crates/gpui/src/elements/div.rs +++ b/crates/gpui/src/elements/div.rs @@ -408,6 +408,7 @@ impl Interactivity { /// The imperative API equivalent to [`InteractiveElement::on_action`]. /// /// See [`Context::listener`](crate::Context::listener) to get access to a view's state from this callback. + #[track_caller] pub fn on_action(&mut self, listener: impl Fn(&A, &mut Window, &mut App) + 'static) { self.action_listeners.push(( TypeId::of::(), @@ -975,6 +976,7 @@ pub trait InteractiveElement: Sized { /// The fluent API equivalent to [`Interactivity::on_action`]. /// /// See [`Context::listener`](crate::Context::listener) to get access to a view's state from this callback. + #[track_caller] fn on_action( mut self, listener: impl Fn(&A, &mut Window, &mut App) + 'static, diff --git a/crates/gpui/src/platform.rs b/crates/gpui/src/platform.rs index 321f67b473..2cc32107f1 100644 --- a/crates/gpui/src/platform.rs +++ b/crates/gpui/src/platform.rs @@ -34,7 +34,7 @@ use crate::{ ForegroundExecutor, GlyphId, GpuSpecs, Hsla, ImageSource, Keymap, LineLayout, Pixels, PlatformInput, Point, Priority, RenderGlyphParams, RenderImage, RenderImageParams, RenderSvgParams, Scene, ShapedGlyph, ShapedRun, SharedString, Size, SvgRenderer, - SystemWindowTab, Task, ThreadTaskTimings, Window, WindowControlArea, hash, point, px, size, + SystemWindowTab, Task, Window, WindowControlArea, hash, point, px, size, }; use anyhow::Result; #[cfg(any(target_os = "linux", target_os = "freebsd"))] @@ -757,12 +757,16 @@ pub type RunnableVariant = Runnable; #[doc(hidden)] pub type TimerResolutionGuard = gpui_util::Deferred>; +#[doc(hidden)] +pub enum TasksIncluded { + OnlyCompleted, + CompletedAndRunning, +} + /// This type is public so that our test macro can generate and use it, but it should not /// be considered part of our public API. #[doc(hidden)] pub trait PlatformDispatcher: Send + Sync { - fn get_all_timings(&self) -> Vec; - fn get_current_thread_timings(&self) -> ThreadTaskTimings; fn is_main_thread(&self) -> bool; fn dispatch(&self, runnable: RunnableVariant, priority: Priority); fn dispatch_on_main_thread(&self, runnable: RunnableVariant, priority: Priority); diff --git a/crates/gpui/src/platform/test/dispatcher.rs b/crates/gpui/src/platform/test/dispatcher.rs index ef662c6c48..c48e491347 100644 --- a/crates/gpui/src/platform/test/dispatcher.rs +++ b/crates/gpui/src/platform/test/dispatcher.rs @@ -112,19 +112,6 @@ impl Clone for TestDispatcher { } impl PlatformDispatcher for TestDispatcher { - fn get_all_timings(&self) -> Vec { - Vec::new() - } - - fn get_current_thread_timings(&self) -> crate::ThreadTaskTimings { - crate::ThreadTaskTimings { - thread_name: None, - thread_id: std::thread::current().id(), - timings: Vec::new(), - total_pushed: 0, - } - } - fn is_main_thread(&self) -> bool { self.scheduler.is_main_thread() } diff --git a/crates/gpui/src/platform_scheduler.rs b/crates/gpui/src/platform_scheduler.rs index 6a3929e91b..b7426ba466 100644 --- a/crates/gpui/src/platform_scheduler.rs +++ b/crates/gpui/src/platform_scheduler.rs @@ -129,7 +129,10 @@ impl Scheduler for PlatformScheduler { // Create a runnable that will send the completion signal let location = std::panic::Location::caller(); let (runnable, _task) = async_task::Builder::new() - .metadata(RunnableMeta { location }) + .metadata(RunnableMeta { + location, + spawned: scheduler::SpawnTime(Instant::now()), + }) .spawn( move |_| async move { let _ = tx.send(()); @@ -185,7 +188,7 @@ impl Clock for PlatformClock { #[cfg(all(test, not(target_family = "wasm")))] mod tests { use super::*; - use crate::{RunnableVariant, ThreadTaskTimings}; + use crate::RunnableVariant; use scheduler::BackgroundExecutor; use std::time::Instant as StdInstant; @@ -194,17 +197,6 @@ mod tests { struct SmokeDispatcher; impl PlatformDispatcher for SmokeDispatcher { - fn get_all_timings(&self) -> Vec { - Vec::new() - } - fn get_current_thread_timings(&self) -> ThreadTaskTimings { - ThreadTaskTimings { - thread_name: None, - thread_id: std::thread::current().id(), - timings: Vec::new(), - total_pushed: 0, - } - } fn is_main_thread(&self) -> bool { false } diff --git a/crates/gpui/src/profiler.rs b/crates/gpui/src/profiler.rs index 009afb9099..0aa54fe131 100644 --- a/crates/gpui/src/profiler.rs +++ b/crates/gpui/src/profiler.rs @@ -1,25 +1,96 @@ -use scheduler::Instant; +use itertools::Itertools; +use scheduler::{Instant, SpawnTime}; use std::{ cell::LazyCell, collections::{HashMap, VecDeque}, hash::{DefaultHasher, Hash, Hasher}, + hint::cold_path, sync::{ Arc, atomic::{AtomicBool, Ordering}, }, thread::ThreadId, + time::Duration, }; +mod actions; +pub use actions::{ActionStatistics, ActionTiming, take_action_stats}; +pub(crate) use actions::{save_action_timing, update_running_action}; + use serde::{Deserialize, Serialize}; -use crate::SharedString; +use crate::{SharedString, TasksIncluded}; + +#[doc(hidden)] +pub fn get_all_timings(included: gpui::TasksIncluded) -> Vec { + let global_thread_timings = GLOBAL_THREAD_TIMINGS.lock(); + ThreadTaskTimings::collect(&global_thread_timings, included) +} + +#[doc(hidden)] +pub fn get_current_thread_timings(included: TasksIncluded) -> gpui::ThreadTaskTimings { + gpui::profiler::get_current_thread_task_timings(included) +} + +#[doc(hidden)] +pub fn take_all_stats(included: TasksIncluded) -> Vec { + let global_timings = GLOBAL_THREAD_TIMINGS.lock(); + ThreadTaskStatistics::collect_and_reset(&global_timings, included) +} #[doc(hidden)] #[derive(Debug, Copy, Clone)] +pub struct YieldTime(pub Instant); + +#[doc(hidden)] +#[derive(Copy, Clone)] pub struct TaskTiming { pub location: &'static core::panic::Location<'static>, + pub spawned: SpawnTime, pub start: Instant, - pub end: Option, + pub end: YieldTime, +} + +impl std::fmt::Debug for TaskTiming { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("TaskTiming") + .field("location", &self.location) + .field("since_spawned", &self.spawned.0.elapsed()) + .field("last_poll_duration", &self.poll_duration()) + .field("total_runtime", &self.since_spawn()) + .finish() + } +} + +#[doc(hidden)] +#[derive(Debug, Copy, Clone)] +pub struct ActiveTiming { + pub location: &'static core::panic::Location<'static>, + pub spawned: SpawnTime, + pub start: Instant, +} + +impl TaskTiming { + /// A task timing with a duration of zero. Any task will replace this in history. + pub fn placeholder() -> Self { + let now = Instant::now(); + Self { + location: std::panic::Location::caller(), + spawned: SpawnTime(now), + start: now, + end: YieldTime(now), + } + } + + #[inline(always)] + pub fn poll_duration(&self) -> Duration { + self.end.0 - self.start + } + + #[inline(always)] + fn since_spawn(&self) -> Duration { + self.end.0 - self.spawned.0 + } } #[doc(hidden)] @@ -28,12 +99,13 @@ pub struct ThreadTaskTimings { pub thread_name: Option, pub thread_id: ThreadId, pub timings: Vec, + pub stats: TaskStatistics, pub total_pushed: u64, } impl ThreadTaskTimings { /// Convert global thread timings into their structured format. - pub fn convert(timings: &[GlobalThreadTimings]) -> Vec { + pub fn collect(timings: &[GlobalThreadTimings], included: TasksIncluded) -> Vec { timings .iter() .filter_map(|t| match t.timings.upgrade() { @@ -44,17 +116,28 @@ impl ThreadTaskTimings { let timings = timings.lock(); let thread_name = timings.thread_name.clone(); let total_pushed = timings.total_pushed; - let timings = &timings.timings; + let completed = &timings.timings; - let mut vec = Vec::with_capacity(timings.len()); - let (s1, s2) = timings.as_slices(); + let mut vec = Vec::with_capacity(completed.len() + 1); // +1 for running task + let (s1, s2) = completed.as_slices(); vec.extend_from_slice(s1); vec.extend_from_slice(s2); + if let TasksIncluded::CompletedAndRunning = included + && let Some(running) = timings.running + { + vec.push(TaskTiming { + location: running.location, + spawned: running.spawned, + start: running.start, + end: YieldTime(Instant::now()), + }) + } ThreadTaskTimings { thread_name, thread_id, timings: vec, + stats: timings.stats.clone(), total_pushed, } }) @@ -62,6 +145,58 @@ impl ThreadTaskTimings { } } +#[doc(hidden)] +#[derive(Debug)] +pub struct ThreadTaskStatistics { + pub thread_name: Option, + pub thread_id: ThreadId, + pub stats: TaskStatistics, +} + +impl ThreadTaskStatistics { + pub fn collect_and_reset( + timings: &[GlobalThreadTimings], + include_running: TasksIncluded, + ) -> Vec { + timings + .iter() + .filter_map(|t| match t.timings.upgrade() { + Some(timings) => Some((t.thread_id, timings)), + _ => None, + }) + .map(|(thread_id, timings)| { + let mut timings = timings.lock(); + let thread_name = timings.thread_name.clone(); + + let mut stats = std::mem::take(&mut timings.stats); + if let TasksIncluded::CompletedAndRunning = include_running + && let Some(ActiveTiming { + location, + spawned, + start, + }) = timings.running + { + let end = YieldTime(Instant::now()); + let timing = TaskTiming { + location, + spawned, + start, + end, + }; + stats.add_runtime(timing); + stats.add_yield_timing(timing); + } + + Self { + thread_name, + thread_id, + stats, + } + }) + .collect() + } +} + /// Serializable variant of [`core::panic::Location`] #[derive(Debug, Clone, Serialize, Deserialize)] pub struct SerializedLocation { @@ -105,11 +240,7 @@ impl SerializedTaskTiming { .iter() .map(|timing| { let start = timing.start.duration_since(anchor).as_nanos(); - let duration = timing - .end - .unwrap_or_else(|| Instant::now()) - .duration_since(timing.start) - .as_nanos(); + let duration = timing.end.0.duration_since(timing.start).as_nanos(); SerializedTaskTiming { location: timing.location.into(), start, @@ -120,6 +251,17 @@ impl SerializedTaskTiming { serialized } + + /// `anchor` - [`Instant`] that should be earlier than all timings to use as base anchor + pub fn from(anchor: Instant, timing: TaskTiming) -> SerializedTaskTiming { + let start = timing.start.duration_since(anchor).as_nanos(); + let duration = timing.end.0.duration_since(timing.start).as_nanos(); + SerializedTaskTiming { + location: timing.location.into(), + start, + duration, + } + } } /// Serializable variant of [`ThreadTaskTimings`] @@ -209,18 +351,7 @@ impl ProfilingCollector { &thread.timings[skip.min(thread.timings.len())..] }; - // Don't emit the last entry if it's still in-progress (end: None). - let incomplete_at_end = slice.last().is_some_and(|t| t.end.is_none()); - if incomplete_at_end { - slice = &slice[..slice.len() - 1]; - } - - let cursor_advance = if incomplete_at_end { - thread.total_pushed.saturating_sub(1) - } else { - thread.total_pushed - }; - + let cursor_advance = thread.total_pushed; self.cursors.insert(thread.thread_id, cursor_advance); if slice.is_empty() { @@ -261,6 +392,96 @@ pub struct GlobalThreadTimings { pub timings: std::sync::Weak, } +#[doc(hidden)] +#[derive(Debug, Clone)] +pub struct TaskStatistics { + pub poll_time_to_beat: Duration, + pub runtime_to_beat: Duration, + pub longest_poll_times: [TaskTiming; 5], + pub longest_runtimes: [TaskTiming; 5], +} + +impl std::fmt::Display for TaskStatistics { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str("Tasks that blocked the longest before yielding\n")?; + for timing in self.longest_poll_times { + f.write_fmt(format_args!( + "{:<20} - {}:{}\n", + format!("{:?}", timing.poll_duration()), + timing.location.file(), + timing.location.column() + ))?; + } + f.write_str("Tasks that ran the longest\n")?; + for timing in self.longest_runtimes { + f.write_fmt(format_args!( + "{:<20} - {}:{}\n", + format!("{:?}", timing.since_spawn()), + timing.location.file(), + timing.location.column() + ))?; + } + Ok(()) + } +} + +impl Default for TaskStatistics { + fn default() -> Self { + Self { + // Do not track polls that are not problematic + // this keeps more calls on the fast path + poll_time_to_beat: Duration::from_micros(100), + runtime_to_beat: Duration::from_micros(100), + longest_poll_times: [TaskTiming::placeholder(); 5], + longest_runtimes: [TaskTiming::placeholder(); 5], + } + } +} + +impl TaskStatistics { + #[inline(always)] + fn add_yield_timing(&mut self, task: TaskTiming) { + let yielded_after = task.poll_duration(); + if yielded_after >= self.poll_time_to_beat { + cold_path(); // most tasks are not the worst, optimize for that + let to_replace = self + .longest_poll_times + .iter() + .position_min_by_key(|task| task.since_spawn()) + .expect("guarded by the comparison with nth_longest_yield_time"); + self.longest_poll_times[to_replace] = task; + + self.poll_time_to_beat = self + .longest_poll_times + .iter() + .map(|task| task.since_spawn()) + .min() + .expect("never empty"); + } + } + + #[inline(always)] + fn add_runtime(&mut self, task: TaskTiming) { + let runtime = task.since_spawn(); + if runtime >= self.runtime_to_beat { + cold_path(); // most tasks are not the worst, optimize for that + let to_replace = self + .longest_runtimes + .iter() + .position_min_by_key(|task| task.since_spawn()) + .expect("guarded by the comparison with nth_longest_yield_time"); + self.longest_runtimes[to_replace] = task; + + self.runtime_to_beat = self + .longest_runtimes + .iter() + .map(|task| task.since_spawn()) + .min() + .expect("never empty"); + } + } +} + #[doc(hidden)] pub static GLOBAL_THREAD_TIMINGS: spin::Mutex> = spin::Mutex::new(Vec::new()); @@ -292,6 +513,8 @@ pub struct ThreadTimings { pub thread_name: Option, pub thread_id: ThreadId, pub timings: TaskTimings, + pub running: Option, + pub stats: TaskStatistics, pub total_pushed: u64, } @@ -301,22 +524,47 @@ impl ThreadTimings { thread_name, thread_id, timings: TaskTimings::new(), + stats: TaskStatistics::default(), total_pushed: 0, + running: None, } } - /// If this task is the same as the last task, update the end time of the last task. - /// - /// Otherwise, add the new task timing to the list. - pub fn add_task_timing(&mut self, timing: TaskTiming) { - if let Some(last_timing) = self.timings.back_mut() - && last_timing.location == timing.location - && last_timing.start == timing.start - { - last_timing.end = timing.end; - } else { - while self.timings.len() + 1 > MAX_TASK_TIMINGS { - // This should only ever pop one element because it matches the insertion below. + pub fn update_running_task( + &mut self, + spawned: SpawnTime, + location: &'static std::panic::Location<'_>, + ) { + let start = Instant::now(); + self.running = Some(ActiveTiming { + spawned, + location, + start, + }); + } + + pub fn save_task_timing(&mut self, ended: YieldTime) { + let ActiveTiming { + location, + start, + spawned, + } = self + .running + .take() + .expect("this function is only ever called after register_task_start"); + + let timing = TaskTiming { + location, + spawned, + start, + end: ended, + }; + self.stats.add_yield_timing(timing); + self.stats.add_runtime(timing); + + if trace_enabled() { + cold_path(); // optimize for when the profiling is off + if self.timings.len() >= MAX_TASK_TIMINGS { self.timings.pop_front(); } self.timings.push_back(timing); @@ -324,11 +572,28 @@ impl ThreadTimings { } } - pub fn get_thread_task_timings(&self) -> ThreadTaskTimings { + // Running tasks are included in the reliability trace, which is written + // whenever the foreground executor makes no progress for > n seconds + pub fn get_thread_task_timings(&self, includes: TasksIncluded) -> ThreadTaskTimings { ThreadTaskTimings { thread_name: self.thread_name.clone(), thread_id: self.thread_id, - timings: self.timings.iter().cloned().collect(), + timings: self + .timings + .iter() + .cloned() + .chain( + self.running + .filter(|_| matches!(includes, TasksIncluded::CompletedAndRunning)) + .map(|running| TaskTiming { + spawned: running.spawned, + location: running.location, + start: running.start, + end: YieldTime(Instant::now()), + }), + ) + .collect(), + stats: self.stats.clone(), total_pushed: self.total_pushed, } } @@ -350,28 +615,34 @@ impl Drop for ThreadTimings { } #[doc(hidden)] -pub fn add_task_timing(timing: TaskTiming) { - if !PROFILER_ENABLED.load(Ordering::Acquire) { - return; - } +pub fn update_running_task(spawned: SpawnTime, location: &'static std::panic::Location<'_>) { THREAD_TIMINGS.with(|timings| { - timings.lock().add_task_timing(timing); + timings.lock().update_running_task(spawned, location); }); } #[doc(hidden)] -pub fn get_current_thread_task_timings() -> ThreadTaskTimings { - THREAD_TIMINGS.with(|timings| timings.lock().get_thread_task_timings()) +pub fn save_task_timing() { + let yielded_at = YieldTime(Instant::now()); + THREAD_TIMINGS.with(|timings| { + timings.lock().save_task_timing(yielded_at); + }); +} + +#[doc(hidden)] +pub fn get_current_thread_task_timings(include_running: TasksIncluded) -> ThreadTaskTimings { + THREAD_TIMINGS.with(|timings| timings.lock().get_thread_task_timings(include_running)) } static PROFILER_ENABLED: AtomicBool = AtomicBool::new(false); -/// Enables or disables task timing collection at runtime. +/// Enables or disables task timing trace collection at runtime. /// /// When transitioning from enabled to disabled, `add_task_timing` becomes a -/// no-op and the existing per-thread buffers are cleared so stale data isn't -/// reported after a later re-enable. Calls with the current value are a no-op. -pub fn set_enabled(enabled: bool) -> bool { +/// cheaper since only cheap statistics are gathered. The existing per-thread +/// buffers for traces are cleared so stale data isn't reported after a later +/// re-enable. Calls with the current value are a no-op. +pub fn set_trace_enabled(enabled: bool) -> bool { if PROFILER_ENABLED.swap(enabled, Ordering::AcqRel) == enabled { return false; } @@ -388,3 +659,8 @@ pub fn set_enabled(enabled: bool) -> bool { } true } + +/// Returns whether task timing tracing is enabled. +pub fn trace_enabled() -> bool { + PROFILER_ENABLED.load(Ordering::Relaxed) +} diff --git a/crates/gpui/src/profiler/actions.rs b/crates/gpui/src/profiler/actions.rs new file mode 100644 index 0000000000..a055fc21e3 --- /dev/null +++ b/crates/gpui/src/profiler/actions.rs @@ -0,0 +1,189 @@ +use std::{ + hint::cold_path, + time::{Duration, Instant}, +}; + +use itertools::Itertools; + +use crate::action::Action; + +#[doc(hidden)] +#[derive(Clone)] +pub struct ActionStatistics { + runtime_to_beat: Duration, + + longest_runtimes: heapless::Vec, + running: Option<(&'static str, Instant)>, +} + +impl std::fmt::Debug for ActionStatistics { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("ActionStatistics") + .field("runtime_to_beat", &self.runtime_to_beat) + .field("longest_runtimes", &self.longest_runtimes) + .field( + "running", + &self.running.map(|(id, started)| (id, started.elapsed())), + ) + .finish() + } +} + +impl std::fmt::Display for ActionStatistics { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str("Actions that blocked the longest\n")?; + for action in self + .longest_runtimes(true) + .sorted_by_key(|action| action.runtime()) + .rev() + { + f.write_fmt(format_args!( + "{:<20} - {}", + format!("{:?}", action.runtime()), // impl dbg does not support alignment + action.name + ))?; + writeln!(f)?; + } + Ok(()) + } +} + +impl Default for ActionStatistics { + fn default() -> Self { + Self::new() + } +} + +impl ActionStatistics { + const fn new() -> Self { + Self { + // This keeps more calls on the fast path by only tracking + // problematic polls + runtime_to_beat: Duration::from_micros(100), + longest_runtimes: heapless::Vec::new(), + running: None, + } + } + + pub fn take(&mut self) -> Self { + let taken = std::mem::take(self); + self.running = taken.running; + taken + } + + pub fn is_empty(&self) -> bool { + self.longest_runtimes.is_empty() + } + + pub fn update_running_action(&mut self, action: &'static str, started: Instant) { + self.running = Some((action, started)); + } + + pub fn save_action_timing(&mut self) { + let now = Instant::now(); + let (action, started) = self + .running + .take() + .expect("only called after `update_running_action`"); + + let runtime = now.duration_since(started); + if runtime >= self.runtime_to_beat { + cold_path(); // most actions are not the worst, optimize for that + + if self.longest_runtimes.is_full() + && let Some(to_replace) = self + .longest_runtimes + .iter_mut() + .min_by_key(|action| runtime >= action.runtime()) + { + *to_replace = ActionTiming { + name: action, + start: started, + end: now, + }; + } else { + self.longest_runtimes + .push(ActionTiming { + name: action, + start: started, + end: now, + }) + .expect("just checked it is not full"); + }; + + self.runtime_to_beat = self + .longest_runtimes + .iter() + .map(|action| action.runtime()) + .min() + .expect("never empty"); + } + } + + pub fn longest_runtimes(&self, include_running: bool) -> impl Iterator { + self.longest_runtimes.iter().copied().chain( + self.running + .into_iter() + .filter(move |_| include_running) + .map(|(name, start)| ActionTiming { + name, + start, + end: Instant::now(), + }), + ) + } +} + +#[doc(hidden)] +/// UNSTABLE only for use in the profiler and zed-reliability +#[derive(Copy, Clone)] +pub struct ActionTiming { + pub name: &'static str, + pub start: Instant, + pub end: Instant, +} + +impl core::fmt::Debug for ActionTiming { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("ActionTiming") + .field("name", &self.name) + .field("runtime", &self.runtime()) + .finish() + } +} + +impl ActionTiming { + pub fn duration(&self) -> Duration { + self.end.saturating_duration_since(self.start) + } +} + +impl ActionTiming { + #[doc(hidden)] + pub fn runtime(&self) -> Duration { + self.end - self.start + } +} + +// The profiler is careful to never block when the lock is held, therefore a +// spinlock is optimal. +static ACTION_STATISTICS: spin::Mutex = + const { spin::Mutex::new(ActionStatistics::new()) }; + +#[doc(hidden)] +pub(crate) fn update_running_action(action: &(dyn Action + 'static), cx: &mut crate::App) { + let now = Instant::now(); + let action = action.type_id(); + let action = cx.actions.try_resolve_action(&action).unwrap_or("un-named"); + ACTION_STATISTICS.lock().update_running_action(action, now); +} + +#[doc(hidden)] +pub(crate) fn save_action_timing() { + ACTION_STATISTICS.lock().save_action_timing(); +} + +#[doc(hidden)] +pub fn take_action_stats() -> ActionStatistics { + ACTION_STATISTICS.lock().take() +} diff --git a/crates/gpui/src/window.rs b/crates/gpui/src/window.rs index 161891187a..c3a84c0b72 100644 --- a/crates/gpui/src/window.rs +++ b/crates/gpui/src/window.rs @@ -17,7 +17,7 @@ use crate::{ SystemWindowTabController, TabStopMap, TaffyLayoutEngine, Task, TextRenderingMode, TextStyle, TextStyleRefinement, ThermalState, TransformationMatrix, Underline, UnderlineStyle, WindowAppearance, WindowBackgroundAppearance, WindowBounds, WindowControls, WindowDecorations, - WindowOptions, WindowParams, WindowTextSystem, point, prelude::*, px, rems, size, + WindowOptions, WindowParams, WindowTextSystem, point, prelude::*, profiler, px, rems, size, transparent_black, }; use anyhow::{Context as _, Result, anyhow}; @@ -4969,7 +4969,9 @@ impl Window { .remove(&action.as_any().type_id()) { for listener in &global_listeners { + profiler::update_running_action(action, cx); listener(action.as_any(), DispatchPhase::Capture, cx); + profiler::save_action_timing(); if !cx.propagate_event { break; } @@ -4999,7 +5001,9 @@ impl Window { { let any_action = action.as_any(); if action_type == any_action.type_id() { + profiler::update_running_action(action, cx); listener(any_action, DispatchPhase::Capture, self, cx); + profiler::save_action_timing(); if !cx.propagate_event { return; @@ -5019,7 +5023,9 @@ impl Window { let any_action = action.as_any(); if action_type == any_action.type_id() { cx.propagate_event = false; // Actions stop propagation by default during the bubble phase + profiler::update_running_action(action, cx); listener(any_action, DispatchPhase::Bubble, self, cx); + profiler::save_action_timing(); if !cx.propagate_event { return; @@ -5036,7 +5042,9 @@ impl Window { for listener in global_listeners.iter().rev() { cx.propagate_event = false; // Actions stop propagation by default during the bubble phase + profiler::update_running_action(action, cx); listener(action.as_any(), DispatchPhase::Bubble, cx); + profiler::save_action_timing(); if !cx.propagate_event { break; } diff --git a/crates/gpui_linux/src/linux/dispatcher.rs b/crates/gpui_linux/src/linux/dispatcher.rs index 22df5799dd..06d29d74f8 100644 --- a/crates/gpui_linux/src/linux/dispatcher.rs +++ b/crates/gpui_linux/src/linux/dispatcher.rs @@ -5,15 +5,11 @@ use calloop::{ }; use util::ResultExt; -use std::{ - mem::MaybeUninit, - thread, - time::{Duration, Instant}, -}; +use std::{mem::MaybeUninit, thread, time::Duration}; use gpui::{ - GLOBAL_THREAD_TIMINGS, PlatformDispatcher, Priority, PriorityQueueReceiver, - PriorityQueueSender, RunnableVariant, TaskTiming, ThreadTaskTimings, profiler, + PlatformDispatcher, Priority, PriorityQueueReceiver, PriorityQueueSender, RunnableVariant, + profiler, }; struct TimerAfter { @@ -44,27 +40,11 @@ impl LinuxDispatcher { .name(format!("Worker-{i}")) .spawn(move || { for runnable in receiver.iter() { - let start = Instant::now(); - let location = runnable.metadata().location; - let mut timing = TaskTiming { - location, - start, - end: None, - }; - profiler::add_task_timing(timing); - + let spawned = runnable.metadata().spawned; + profiler::update_running_task(spawned, location); runnable.run(); - - let end = Instant::now(); - timing.end = Some(end); - profiler::add_task_timing(timing); - - log::trace!( - "background thread {}: ran runnable. took: {:?}", - i, - start.elapsed() - ); + profiler::save_task_timing(); } }) .unwrap() @@ -89,20 +69,11 @@ impl LinuxDispatcher { calloop::timer::Timer::from_duration(timer.duration), move |_, _, _| { if let Some(runnable) = runnable.take() { - let start = Instant::now(); let location = runnable.metadata().location; - let mut timing = TaskTiming { - location, - start, - end: None, - }; - profiler::add_task_timing(timing); - + let spawned = runnable.metadata().spawned; + profiler::update_running_task(spawned, location); runnable.run(); - let end = Instant::now(); - - timing.end = Some(end); - profiler::add_task_timing(timing); + profiler::save_task_timing(); } TimeoutAction::Drop }, @@ -129,15 +100,6 @@ impl LinuxDispatcher { } impl PlatformDispatcher for LinuxDispatcher { - fn get_all_timings(&self) -> Vec { - let global_timings = GLOBAL_THREAD_TIMINGS.lock(); - ThreadTaskTimings::convert(&global_timings) - } - - fn get_current_thread_timings(&self) -> gpui::ThreadTaskTimings { - gpui::profiler::get_current_thread_task_timings() - } - fn is_main_thread(&self) -> bool { thread::current().id() == self.main_thread_id } @@ -398,20 +360,3 @@ mod tests { assert!(data.got_closed); } } - -// running 1 test -// test linux::dispatcher::tests::tomato ... FAILED - -// failures: - -// ---- linux::dispatcher::tests::tomato stdout ---- -// [crates/gpui/src/platform/linux/dispatcher.rs:262:9] -// returning 1 tasks to process -// [crates/gpui/src/platform/linux/dispatcher.rs:480:75] evt = Msg( -// (), -// ) -// returning 0 tasks to process - -// thread 'linux::dispatcher::tests::tomato' (478301) panicked at crates/gpui/src/platform/linux/dispatcher.rs:515:9: -// assertion failed: data.got_closed -// note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace diff --git a/crates/gpui_linux/src/linux/wayland/client.rs b/crates/gpui_linux/src/linux/wayland/client.rs index 6a7c4c76e4..fc3697a8bb 100644 --- a/crates/gpui_linux/src/linux/wayland/client.rs +++ b/crates/gpui_linux/src/linux/wayland/client.rs @@ -96,7 +96,7 @@ use gpui::{ ForegroundExecutor, KeyDownEvent, KeyUpEvent, Keystroke, Modifiers, ModifiersChangedEvent, MouseButton, MouseDownEvent, MouseExitEvent, MouseMoveEvent, MouseUpEvent, NavigationDirection, Pixels, PlatformDisplay, PlatformInput, PlatformKeyboardLayout, PlatformWindow, Point, - ScrollDelta, ScrollWheelEvent, SharedString, Size, TaskTiming, TouchPhase, WindowButtonLayout, + ScrollDelta, ScrollWheelEvent, SharedString, Size, TouchPhase, WindowButtonLayout, WindowParams, point, profiler, px, size, }; use gpui_wgpu::{CompositorGpuHint, GpuContext}; @@ -576,20 +576,11 @@ impl WaylandClient { move |event, _, _: &mut WaylandClientStatePtr| { if let calloop::channel::Event::Msg(runnable) = event { handle.insert_idle(|_| { - let start = Instant::now(); let location = runnable.metadata().location; - let mut timing = TaskTiming { - location, - start, - end: None, - }; - profiler::add_task_timing(timing); - + let spawned = runnable.metadata().spawned; + profiler::update_running_task(spawned, location); runnable.run(); - - let end = Instant::now(); - timing.end = Some(end); - profiler::add_task_timing(timing); + profiler::save_task_timing(); }); } } diff --git a/crates/gpui_linux/src/linux/x11/client.rs b/crates/gpui_linux/src/linux/x11/client.rs index 1e573a54bf..b923fde438 100644 --- a/crates/gpui_linux/src/linux/x11/client.rs +++ b/crates/gpui_linux/src/linux/x11/client.rs @@ -6,7 +6,7 @@ use calloop::{ }; use collections::HashMap; use core::str; -use gpui::{Capslock, TaskTiming, profiler}; +use gpui::{Capslock, profiler}; use http_client::Url; use log::Level; use smallvec::SmallVec; @@ -322,20 +322,11 @@ impl X11Client { // events have higher priority and runnables are only worked off after the event // callbacks. handle.insert_idle(|_| { - let start = Instant::now(); let location = runnable.metadata().location; - let mut timing = TaskTiming { - location, - start, - end: None, - }; - profiler::add_task_timing(timing); - + let spawned = runnable.metadata().spawned; + profiler::update_running_task(spawned, location); runnable.run(); - - let end = Instant::now(); - timing.end = Some(end); - profiler::add_task_timing(timing); + profiler::save_task_timing(); }); } } diff --git a/crates/gpui_macos/src/dispatcher.rs b/crates/gpui_macos/src/dispatcher.rs index f4b80ec7cb..5699fdae1d 100644 --- a/crates/gpui_macos/src/dispatcher.rs +++ b/crates/gpui_macos/src/dispatcher.rs @@ -1,8 +1,5 @@ use dispatch2::{DispatchQueue, DispatchQueueGlobalPriority, DispatchTime, GlobalQueueIdentifier}; -use gpui::{ - GLOBAL_THREAD_TIMINGS, PlatformDispatcher, Priority, RunnableMeta, RunnableVariant, TaskTiming, - ThreadTaskTimings, add_task_timing, -}; +use gpui::{PlatformDispatcher, Priority, RunnableMeta, RunnableVariant}; use mach2::{ kern_return::KERN_SUCCESS, mach_time::mach_timebase_info_data_t, @@ -21,11 +18,7 @@ use objc::{ runtime::{BOOL, YES}, sel, sel_impl, }; -use std::{ - ffi::c_void, - ptr::NonNull, - time::{Duration, Instant}, -}; +use std::{ffi::c_void, ptr::NonNull, time::Duration}; pub(crate) struct MacDispatcher; @@ -36,15 +29,6 @@ impl MacDispatcher { } impl PlatformDispatcher for MacDispatcher { - fn get_all_timings(&self) -> Vec { - let global_timings = GLOBAL_THREAD_TIMINGS.lock(); - ThreadTaskTimings::convert(&global_timings) - } - - fn get_current_thread_timings(&self) -> ThreadTaskTimings { - gpui::profiler::get_current_thread_task_timings() - } - fn is_main_thread(&self) -> bool { let is_main_thread: BOOL = unsafe { msg_send![class!(NSThread), isMainThread] }; is_main_thread == YES @@ -184,18 +168,8 @@ extern "C" fn trampoline(context: *mut c_void) { unsafe { Runnable::::from_raw(NonNull::new_unchecked(context as *mut ())) }; let location = runnable.metadata().location; - - let start = Instant::now(); - let mut timing = TaskTiming { - location, - start, - end: None, - }; - - add_task_timing(timing); - + let spawned = runnable.metadata().spawned; + gpui::profiler::update_running_task(spawned, location); runnable.run(); - - timing.end = Some(Instant::now()); - add_task_timing(timing); + gpui::profiler::save_task_timing(); } diff --git a/crates/gpui_web/src/dispatcher.rs b/crates/gpui_web/src/dispatcher.rs index 9c45de1b0e..9bcacbdecb 100644 --- a/crates/gpui_web/src/dispatcher.rs +++ b/crates/gpui_web/src/dispatcher.rs @@ -1,6 +1,5 @@ use gpui::{ PlatformDispatcher, Priority, PriorityQueueReceiver, PriorityQueueSender, RunnableVariant, - ThreadTaskTimings, }; use std::sync::Arc; use std::sync::atomic::AtomicI32; @@ -211,20 +210,6 @@ impl WebDispatcher { } impl PlatformDispatcher for WebDispatcher { - fn get_all_timings(&self) -> Vec { - // TODO-Wasm: should we panic here? - Vec::new() - } - - fn get_current_thread_timings(&self) -> ThreadTaskTimings { - ThreadTaskTimings { - thread_name: None, - thread_id: std::thread::current().id(), - timings: Vec::new(), - total_pushed: 0, - } - } - fn is_main_thread(&self) -> bool { self.on_main_thread() } diff --git a/crates/gpui_windows/src/dispatcher.rs b/crates/gpui_windows/src/dispatcher.rs index 2b2bf402d2..1f74aa8ad0 100644 --- a/crates/gpui_windows/src/dispatcher.rs +++ b/crates/gpui_windows/src/dispatcher.rs @@ -1,7 +1,7 @@ use std::{ sync::atomic::{AtomicBool, Ordering}, thread::{ThreadId, current}, - time::{Duration, Instant}, + time::Duration, }; use anyhow::Context; @@ -20,8 +20,7 @@ use windows::{ use crate::{HWND, SafeHwnd, WM_GPUI_TASK_DISPATCHED_ON_MAIN_THREAD}; use gpui::{ - GLOBAL_THREAD_TIMINGS, PlatformDispatcher, Priority, PriorityQueueSender, RunnableVariant, - TaskTiming, ThreadTaskTimings, TimerResolutionGuard, + PlatformDispatcher, Priority, PriorityQueueSender, RunnableVariant, TimerResolutionGuard, }; pub(crate) struct WindowsDispatcher { @@ -77,35 +76,15 @@ impl WindowsDispatcher { #[inline(always)] pub(crate) fn execute_runnable(runnable: RunnableVariant) { - let start = Instant::now(); - let location = runnable.metadata().location; - let mut timing = TaskTiming { - location, - start, - end: None, - }; - gpui::profiler::add_task_timing(timing); - + let spawned = runnable.metadata().spawned; + gpui::profiler::update_running_task(spawned, location); runnable.run(); - - let end = Instant::now(); - timing.end = Some(end); - - gpui::profiler::add_task_timing(timing); + gpui::profiler::save_task_timing(); } } impl PlatformDispatcher for WindowsDispatcher { - fn get_all_timings(&self) -> Vec { - let global_thread_timings = GLOBAL_THREAD_TIMINGS.lock(); - ThreadTaskTimings::convert(&global_thread_timings) - } - - fn get_current_thread_timings(&self) -> gpui::ThreadTaskTimings { - gpui::profiler::get_current_thread_task_timings() - } - fn is_main_thread(&self) -> bool { current().id() == self.main_thread_id } diff --git a/crates/miniprofiler_ui/src/miniprofiler_ui.rs b/crates/miniprofiler_ui/src/miniprofiler_ui.rs index 82c7a1e688..8cab39b975 100644 --- a/crates/miniprofiler_ui/src/miniprofiler_ui.rs +++ b/crates/miniprofiler_ui/src/miniprofiler_ui.rs @@ -10,8 +10,9 @@ use gpui::{ App, AppContext, ClipboardItem, Context, Div, Entity, Hsla, InteractiveElement, ParentElement as _, ProfilingCollector, Render, SerializedLocation, SerializedTaskTiming, SerializedThreadTaskTimings, SharedString, StatefulInteractiveElement, Styled, Task, - ThreadTimingsDelta, TitlebarOptions, UniformListScrollHandle, WeakEntity, WindowBounds, - WindowOptions, div, prelude::FluentBuilder, profiler, px, relative, size, uniform_list, + TasksIncluded, ThreadTimingsDelta, TitlebarOptions, UniformListScrollHandle, WeakEntity, + WindowBounds, WindowOptions, div, prelude::FluentBuilder, profiler, px, relative, size, + uniform_list, }; use rpc::{AnyProtoClient, proto}; use settings::{RegisterSetting, Settings, SettingsContent, SettingsStore}; @@ -81,7 +82,7 @@ impl Settings for PerformanceProfilerSettings { pub fn init(startup_time: Instant, cx: &mut App) { let initial_enabled = PerformanceProfilerSettings::get_global(cx).enabled; - profiler::set_enabled(initial_enabled); + profiler::set_trace_enabled(initial_enabled); update_command_palette_filter(initial_enabled, cx); cx.observe_global::(|cx| { @@ -89,7 +90,7 @@ pub fn init(startup_time: Instant, cx: &mut App) { // `set_enabled` reports whether the value actually changed, so skip the // filter update and window cleanup on the common no-op path — the // settings observer fires for every settings change. - if !profiler::set_enabled(enabled) { + if !profiler::set_trace_enabled(enabled) { return; } update_command_palette_filter(enabled, cx); @@ -225,14 +226,13 @@ impl ProfilerWindow { self.has_remote = self.remote_proto_client(cx).is_some(); match self.source { ProfileSource::Foreground => { - let dispatcher = cx.foreground_executor().dispatcher(); - let current_thread = dispatcher.get_current_thread_timings(); + let current_thread = + gpui::profiler::get_current_thread_timings(TasksIncluded::OnlyCompleted); let deltas = self.collector.collect_unseen(vec![current_thread]); self.apply_deltas(deltas); } ProfileSource::AllThreads => { - let dispatcher = cx.foreground_executor().dispatcher(); - let all_timings = dispatcher.get_all_timings(); + let all_timings = gpui::profiler::get_all_timings(TasksIncluded::OnlyCompleted); let deltas = self.collector.collect_unseen(all_timings); self.apply_deltas(deltas); } diff --git a/crates/remote_server/src/headless_project.rs b/crates/remote_server/src/headless_project.rs index 82ba504963..c4897cd4d0 100644 --- a/crates/remote_server/src/headless_project.rs +++ b/crates/remote_server/src/headless_project.rs @@ -2,6 +2,7 @@ use anyhow::{Context as _, Result, anyhow}; use client::ProjectId; use collections::HashMap; use collections::HashSet; +use gpui::TasksIncluded; use language::File; use lsp::LanguageServerId; @@ -1269,11 +1270,12 @@ impl HeadlessProject { let foreground_only = envelope.payload.foreground_only; let (deltas, now_nanos) = cx.update(|cx| { - let dispatcher = cx.foreground_executor().dispatcher(); let timings = if foreground_only { - vec![dispatcher.get_current_thread_timings()] + vec![gpui::profiler::get_current_thread_timings( + TasksIncluded::OnlyCompleted, + )] } else { - dispatcher.get_all_timings() + gpui::profiler::get_all_timings(TasksIncluded::OnlyCompleted) }; this.update(cx, |this, _cx| { let deltas = this.profiling_collector.collect_unseen(timings); diff --git a/crates/repl/src/repl.rs b/crates/repl/src/repl.rs index 8c3d15a2ad..299641c47d 100644 --- a/crates/repl/src/repl.rs +++ b/crates/repl/src/repl.rs @@ -46,9 +46,8 @@ fn zed_dispatcher(cx: &mut App) -> impl Dispatcher { impl Dispatcher for ZedDispatcher { #[track_caller] fn dispatch(&self, runnable: Runnable) { - let location = core::panic::Location::caller(); let (wrapper, task) = async_task::Builder::new() - .metadata(RunnableMeta { location }) + .metadata(RunnableMeta::new_with_callers_location()) .spawn(|_| async move { runnable.run() }, { let dispatcher = self.dispatcher.clone(); move |r| dispatcher.dispatch(r, Priority::default()) @@ -59,9 +58,8 @@ fn zed_dispatcher(cx: &mut App) -> impl Dispatcher { #[track_caller] fn dispatch_after(&self, duration: Duration, runnable: Runnable) { - let location = core::panic::Location::caller(); let (wrapper, task) = async_task::Builder::new() - .metadata(RunnableMeta { location }) + .metadata(RunnableMeta::new_with_callers_location()) .spawn(|_| async move { runnable.run() }, { let dispatcher = self.dispatcher.clone(); move |r| dispatcher.dispatch_after(duration, r) diff --git a/crates/scheduler/src/executor.rs b/crates/scheduler/src/executor.rs index e5474a4cf0..959c2e3207 100644 --- a/crates/scheduler/src/executor.rs +++ b/crates/scheduler/src/executor.rs @@ -70,7 +70,10 @@ impl LocalExecutor { let (runnable, task) = spawn_local_with_source_location( future, move |runnable| dispatch(runnable), - RunnableMeta { location }, + RunnableMeta { + location, + spawned: crate::SpawnTime(Instant::now()), + }, ); runnable.schedule(); Task(TaskState::Spawned(task)) @@ -200,7 +203,10 @@ impl BackgroundExecutor { let scheduler = Arc::downgrade(&self.scheduler); let location = Location::caller(); let (runnable, task) = async_task::Builder::new() - .metadata(RunnableMeta { location }) + .metadata(RunnableMeta { + location, + spawned: crate::SpawnTime(Instant::now()), + }) .spawn( move |_| future, move |runnable| { @@ -230,7 +236,10 @@ impl BackgroundExecutor { })); let (runnable, task) = async_task::Builder::new() - .metadata(RunnableMeta { location }) + .metadata(RunnableMeta { + location, + spawned: crate::SpawnTime(Instant::now()), + }) .spawn( move |_| future, move |runnable| { diff --git a/crates/scheduler/src/scheduler.rs b/crates/scheduler/src/scheduler.rs index 9212545623..957af02b88 100644 --- a/crates/scheduler/src/scheduler.rs +++ b/crates/scheduler/src/scheduler.rs @@ -56,18 +56,25 @@ impl Priority { } } +#[derive(Clone, Copy, Debug)] +pub struct SpawnTime(pub Instant); + /// Metadata attached to runnables for debugging and profiling. -#[derive(Clone)] +#[derive(Clone, Debug)] pub struct RunnableMeta { /// The source location where the task was spawned. pub location: &'static Location<'static>, + /// The moment the task was spawned. + pub spawned: SpawnTime, } -impl std::fmt::Debug for RunnableMeta { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - f.debug_struct("RunnableMeta") - .field("location", &self.location) - .finish() +impl RunnableMeta { + #[track_caller] + pub fn new_with_callers_location() -> Self { + Self { + location: core::panic::Location::caller(), + spawned: SpawnTime(Instant::now()), + } } } diff --git a/crates/zed/Cargo.toml b/crates/zed/Cargo.toml index 6bd33833b5..14f5140926 100644 --- a/crates/zed/Cargo.toml +++ b/crates/zed/Cargo.toml @@ -120,7 +120,9 @@ go_to_line.workspace = true system_specs.workspace = true gpui = { workspace = true, features = ["input-latency-histogram"] } gpui_platform = {workspace = true, features=["screen-capture", "font-kit", "wayland", "x11"]} +hdrhistogram.workspace = true image = { workspace = true, optional = true } +itertools.workspace = true semver.workspace = true tempfile = { workspace = true, optional = true } clock = { workspace = true, optional = true } diff --git a/crates/zed/src/reliability.rs b/crates/zed/src/reliability.rs index fd602d4ab5..4e654aefa8 100644 --- a/crates/zed/src/reliability.rs +++ b/crates/zed/src/reliability.rs @@ -2,9 +2,8 @@ use anyhow::{Context as _, Result}; use client::{Client, telemetry::MINIDUMP_ENDPOINT}; use feature_flags::FeatureFlagAppExt; use futures::{AsyncReadExt, TryStreamExt}; -use gpui::{App, AppContext as _, SerializedThreadTaskTimings, TaskExt}; -use http_client::{self, AsyncBody, HttpClient, Request}; -use log::info; +use gpui::{App, AppContext, TaskExt}; +use http_client::{AsyncBody, HttpClient, Request}; use project::Project; use proto::{CrashReport, GetCrashFilesResponse}; use reqwest::{ @@ -13,20 +12,14 @@ use reqwest::{ }; use serde::Deserialize; use smol::stream::StreamExt; -use std::{ffi::OsStr, fs, sync::Arc, thread::ThreadId, time::Duration}; +use std::{ffi::OsStr, fs, sync::Arc}; use sysinfo::{MemoryRefreshKind, RefreshKind, System}; use util::ResultExt; -use crate::STARTUP_TIME; - -const MAX_HANG_TRACES: usize = 3; +mod hang_detection; pub fn init(client: Arc, cx: &mut App) { - if cfg!(debug_assertions) { - log::info!("Debug assertions enabled, skipping hang monitoring"); - } else { - monitor_hangs(cx); - } + hang_detection::start(client.clone(), cx); cx.on_flags_ready({ let client = client.clone(); @@ -89,136 +82,6 @@ pub fn init(client: Arc, cx: &mut App) { .detach(); } -fn monitor_hangs(cx: &App) { - let main_thread_id = std::thread::current().id(); - - let foreground_executor = cx.foreground_executor(); - let background_executor = cx.background_executor(); - - // 3 seconds hang - let (mut tx, mut rx) = futures::channel::mpsc::channel(3); - foreground_executor - .spawn(async move { while (rx.next().await).is_some() {} }) - .detach(); - - background_executor - .spawn({ - let background_executor = background_executor.clone(); - async move { - cleanup_old_hang_traces(); - - let mut hang_time = None; - - let mut hanging = false; - loop { - background_executor.timer(Duration::from_secs(1)).await; - match tx.try_send(()) { - Ok(_) => { - hang_time = None; - hanging = false; - continue; - } - Err(e) => { - let is_full = e.into_send_error().is_full(); - if is_full && !hanging { - hanging = true; - hang_time = Some(chrono::Local::now()); - } - - if is_full { - save_hang_trace( - main_thread_id, - &background_executor, - hang_time.unwrap(), - ); - } - } - } - } - } - }) - .detach(); -} - -fn cleanup_old_hang_traces() { - if let Ok(entries) = std::fs::read_dir(paths::hang_traces_dir()) { - let mut files: Vec<_> = entries - .filter_map(|entry| entry.ok()) - .filter(|entry| { - entry - .path() - .extension() - .is_some_and(|ext| ext == "json" || ext == "miniprof") - }) - .collect(); - - if files.len() > MAX_HANG_TRACES { - files.sort_by_key(|entry| entry.file_name()); - for entry in files.iter().take(files.len() - MAX_HANG_TRACES) { - std::fs::remove_file(entry.path()).log_err(); - } - } - } -} - -fn save_hang_trace( - main_thread_id: ThreadId, - background_executor: &gpui::BackgroundExecutor, - hang_time: chrono::DateTime, -) { - let thread_timings = background_executor.dispatcher().get_all_timings(); - let thread_timings = thread_timings - .into_iter() - .map(|mut timings| { - if timings.thread_id == main_thread_id { - timings.thread_name = Some("main".to_string()); - } - - SerializedThreadTaskTimings::convert(*STARTUP_TIME.get().unwrap(), timings) - }) - .collect::>(); - - let trace_path = paths::hang_traces_dir().join(&format!( - "hang-{}.miniprof.json", - hang_time.format("%Y-%m-%d_%H-%M-%S") - )); - - let Some(timings) = serde_json::to_string(&thread_timings) - .context("hang timings serialization") - .log_err() - else { - return; - }; - - if let Ok(entries) = std::fs::read_dir(paths::hang_traces_dir()) { - let mut files: Vec<_> = entries - .filter_map(|entry| entry.ok()) - .filter(|entry| { - entry - .path() - .extension() - .is_some_and(|ext| ext == "json" || ext == "miniprof") - }) - .collect(); - - if files.len() >= MAX_HANG_TRACES { - files.sort_by_key(|entry| entry.file_name()); - for entry in files.iter().take(files.len() - (MAX_HANG_TRACES - 1)) { - std::fs::remove_file(entry.path()).log_err(); - } - } - } - - std::fs::write(&trace_path, timings) - .context("hang trace file writing") - .log_err(); - - info!( - "hang detected, trace file saved at: {}", - trace_path.display() - ); -} - pub async fn upload_previous_minidumps(client: Arc) -> anyhow::Result<()> { let Some(minidump_endpoint) = MINIDUMP_ENDPOINT.as_ref() else { log::warn!("Minidump endpoint not set"); diff --git a/crates/zed/src/reliability/hang_detection.rs b/crates/zed/src/reliability/hang_detection.rs new file mode 100644 index 0000000000..82f8f2b85a --- /dev/null +++ b/crates/zed/src/reliability/hang_detection.rs @@ -0,0 +1,123 @@ +use std::sync::Arc; +use std::thread; +use std::time::Duration; + +use client::Client; +use gpui::{AppContext, TasksIncluded, profiler}; +use parking_lot::Mutex; +use ui::App; + +mod logging; +mod task_traces; +mod telemetry; + +gpui::actions!( + dev, + [ + /// Causes a performance hang to test performance monitoring + HangAction, + /// Causes a performance hang to test performance monitoring + HangBackground, + /// Causes a performance hang to test performance monitoring + HangForeground, + ] +); + +pub(crate) fn start(client: Arc, cx: &mut App) { + let hang_time = if cfg!(debug_assertions) { + if cfg!(windows) { + // yes windows debug builds are horribly slow + Duration::from_secs(30) + } else { + Duration::from_secs(5) + } + } else { + // will be lowered over time or turned into a setting + Duration::from_millis(100) + }; + + if cfg!(debug_assertions) { + log::warn!("debug build, only reporting hangs longer then {hang_time:?}"); + } + + start_hang_detection(hang_time, client, cx); + + cx.on_action(move |_: &HangAction, _| { + log::warn!( + "Hanging the foreground for {hang_time:?} by blocking in an action. \ + Zed will be unresponsive for that time. This should trigger a report in the log", + ); + thread::sleep(hang_time + Duration::from_micros(1)); + log::warn!("Hang ended"); + }); + cx.on_action(move |_: &HangBackground, cx| { + cx.background_spawn(async move { + log::warn!( + "Hanging one background executor for {hang_time:?}. \ + This should trigger a report in the log", + ); + thread::sleep(hang_time + Duration::from_micros(1)); + log::warn!("Hang ended"); + }) + .detach(); + }); + cx.on_action(move |_: &HangForeground, cx| { + cx.spawn(async move |_| { + log::warn!( + "Hanging the foreground executor for {hang_time:?} seconds to test \ + performance monitoring! Zed will be unresponsive for that time. \ + This should trigger a report in the log" + ); + thread::sleep(hang_time + Duration::from_micros(1)); + log::warn!("Hang ended"); + }) + .detach(); + }); +} + +fn start_hang_detection(report_longer_then: Duration, client: Arc, cx: &App) { + let foreground_thread = thread::current().id(); + let monitor_interval = Duration::from_secs(1); + let telemetry = Arc::new(Mutex::new(telemetry::Reporter::new(foreground_thread))); + let mut log = logging::Reporter::new(monitor_interval, report_longer_then, foreground_thread); + + let telemetry2 = Arc::clone(&telemetry); + cx.on_app_quit({ + move |_| { + telemetry2.lock().send(); + client.telemetry().flush_events() + } + }) + .detach(); + + // an OS thread to insulate detection and reporting from hangs on the fore + // or background. + thread::Builder::new() + .name("HangDetection".to_string()) + .spawn(move || { + // allow "bad" tasks during startup. Not because we should but since here + // they are not observed by the user and to lower on clutter from the reporter + thread::sleep(Duration::from_millis(200)); + loop { + thread::sleep(monitor_interval); + // TODO(yara) the telemetry should not include still running tasks while the + // reports being logged should. + let task_stats = profiler::take_all_stats(TasksIncluded::CompletedAndRunning); + let action_stats = profiler::take_action_stats(); + + { + let mut telemetry = telemetry.lock(); + telemetry.update(&task_stats, &action_stats); + telemetry.send_periodically(); + } + + let should_write_trace = log.check_and_report(&task_stats, &action_stats); + if should_write_trace { + if let Some(path) = task_traces::save_any(foreground_thread) { + log::info!("Task trace has been saved to: {}", path.display()); + } + } + } + }) + .expect("App can always spawn threads"); +} diff --git a/crates/zed/src/reliability/hang_detection/logging.rs b/crates/zed/src/reliability/hang_detection/logging.rs new file mode 100644 index 0000000000..c518d03ba1 --- /dev/null +++ b/crates/zed/src/reliability/hang_detection/logging.rs @@ -0,0 +1,190 @@ +use std::fmt::Display; +use std::panic::Location; +use std::thread::ThreadId; +use std::time::{Duration, Instant}; + +use collections::HashMap; +use itertools::Itertools; +use log::info; + +#[derive(Debug, Hash, Eq, PartialEq)] +enum PerfIssue { + Foreground(&'static Location<'static>), + Background(&'static Location<'static>), + Action(&'static str), +} + +pub struct Reporter { + monitor_interval: Duration, + forget_after: Duration, + history: HashMap, + report_longer_then: Duration, + foreground_thread: ThreadId, +} + +type ReportMade = bool; +impl Reporter { + pub fn new( + monitor_interval: Duration, + report_longer_then: Duration, + foreground_thread: ThreadId, + ) -> Self { + Self { + monitor_interval, + forget_after: Duration::from_mins(5), + history: HashMap::default(), + report_longer_then, + foreground_thread, + } + } + pub fn check_and_report( + &mut self, + task_stats: &[gpui::ThreadTaskStatistics], + action_stats: &gpui::ActionStatistics, + ) -> ReportMade { + let mut reported_task_hangs = false; + reported_task_hangs |= self.report_hanging_foreground(&task_stats); + reported_task_hangs |= self.report_hanging_background(&task_stats); + + self.report_hanging_actions(action_stats); + reported_task_hangs + } + + fn hold_report(&self, issue: PerfIssue) -> bool { + self.history + .get(&issue) + .map(Instant::elapsed) + .is_some_and(|since_report| since_report > self.monitor_interval) + } + fn update_reported(&mut self, new: impl Iterator) { + let now = Instant::now(); + for issue in new { + if self + .history + .get(&issue) + .is_none_or(|s| s.elapsed() > self.forget_after) + { + self.history.insert(issue, now); + } + } + } +} + +impl Reporter { + fn report_hanging_foreground( + &mut self, + task_stats: &[gpui::ThreadTaskStatistics], + ) -> ReportMade { + let foreground = self.foreground_thread; + let foreground = task_stats + .iter() + .find(|t| t.thread_id == foreground) + .expect("main thread should be in all statistics"); + + let hangs: Vec<_> = foreground + .stats + .longest_poll_times + .into_iter() + .filter(|task| task.poll_duration() > self.report_longer_then) + .filter(|task| !self.hold_report(PerfIssue::Foreground(task.location))) + .collect(); + self.update_reported( + hangs + .iter() + .map(|task| PerfIssue::Foreground(task.location)), + ); + if !hangs.is_empty() { + info!("New foreground hang detected:\n{}", DisplayTasks(&hangs)); + } + + !hangs.is_empty() + } + + fn report_hanging_background( + &mut self, + task_stats: &[gpui::ThreadTaskStatistics], + ) -> ReportMade { + let foreground = self.foreground_thread; + let background = task_stats.iter().filter(move |t| t.thread_id != foreground); + + let mut report_made = false; + for worker in background { + let hangs: Vec<_> = worker + .stats + .longest_poll_times + .into_iter() + .filter(|stat| stat.poll_duration() > self.report_longer_then) + .filter(|task| !self.hold_report(PerfIssue::Background(task.location))) + .collect(); + + if hangs.is_empty() { + continue; + } + + self.update_reported( + hangs + .iter() + .map(|task| PerfIssue::Background(task.location)), + ); + + info!( + "Background hang detected on {}:\n{}", + worker.thread_name.as_deref().unwrap_or_else(|| "Unknown"), + DisplayTasks(&hangs) + ); + report_made = true; + } + report_made + } + + fn report_hanging_actions(&mut self, action_stats: &gpui::ActionStatistics) { + let hangs: Vec<_> = action_stats + .longest_runtimes(true) + .filter(|action| action.runtime() > self.report_longer_then) + .filter(|action| !self.hold_report(PerfIssue::Action(action.name))) + .collect(); + + self.update_reported(hangs.iter().map(|action| PerfIssue::Action(action.name))); + if !hangs.is_empty() { + info!("Action hang detected:\n{}", DisplayActions(hangs)); + } + } +} + +struct DisplayActions(Vec); +struct DisplayTasks<'a>(&'a [gpui::TaskTiming]); + +impl Display for DisplayActions { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str("Actions(s) that ran too long\n")?; + for action in self.0.iter().sorted_by_key(|action| action.runtime()).rev() { + f.write_fmt(format_args!( + "{:<20} - {}", + format!("{:?}", action.runtime()), // impl debug does not support alignment + action.name + ))?; + writeln!(f)?; + } + Ok(()) + } +} + +impl<'a> Display for DisplayTasks<'a> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str("Tasks(s) that ran too long\n")?; + for task in self + .0 + .iter() + .sorted_by_key(|task| task.poll_duration()) + .rev() + { + f.write_fmt(format_args!( + "{:<20} - {}", + format!("{:?}", task.poll_duration()), // impl debug does not support alignment + task.location + ))?; + writeln!(f)?; + } + Ok(()) + } +} diff --git a/crates/zed/src/reliability/hang_detection/task_traces.rs b/crates/zed/src/reliability/hang_detection/task_traces.rs new file mode 100644 index 0000000000..ab4fe4683d --- /dev/null +++ b/crates/zed/src/reliability/hang_detection/task_traces.rs @@ -0,0 +1,67 @@ +use std::path::PathBuf; +use std::thread::ThreadId; + +use anyhow::Context; +use gpui::{SerializedThreadTaskTimings, TasksIncluded, profiler}; +use util::ResultExt; + +use crate::STARTUP_TIME; + +pub fn save_any(main_thread_id: ThreadId) -> Option { + cleanup_old_hang_traces(); + let thread_timings = gpui::profiler::get_all_timings(TasksIncluded::CompletedAndRunning); + + let thread_timings = thread_timings + .into_iter() + .map(|mut timings| { + if timings.thread_id == main_thread_id { + timings.thread_name = Some("main".to_string()); + } + + SerializedThreadTaskTimings::convert(*STARTUP_TIME.get().unwrap(), timings) + }) + .collect::>(); + + let Some(timings) = serde_json::to_string(&thread_timings) + .context("hang timings serialization") + .log_err() + else { + return None; + }; + + if profiler::trace_enabled() { + None + } else { + cleanup_old_hang_traces(); + let trace_path = paths::hang_traces_dir().join(&format!( + "hang-{}.miniprof.json", + chrono::Local::now().format("%Y-%m-%d_%H-%M-%S") + )); + std::fs::write(&trace_path, timings) + .context("hang trace file writing") + .log_err(); + Some(trace_path) + } +} + +pub fn cleanup_old_hang_traces() { + if let Ok(entries) = std::fs::read_dir(paths::hang_traces_dir()) { + let mut files: Vec<_> = entries + .filter_map(|entry| entry.ok()) + .filter(|entry| { + entry + .path() + .extension() + .is_some_and(|ext| ext == "json" || ext == "miniprof") + }) + .collect(); + + const MAX_HANG_TRACES: usize = 3; + if files.len() > MAX_HANG_TRACES { + files.sort_by_key(|entry| entry.file_name()); + for entry in files.iter().take(files.len() - MAX_HANG_TRACES) { + std::fs::remove_file(entry.path()).log_err(); + } + } + } +} diff --git a/crates/zed/src/reliability/hang_detection/telemetry.rs b/crates/zed/src/reliability/hang_detection/telemetry.rs new file mode 100644 index 0000000000..4717cebe5a --- /dev/null +++ b/crates/zed/src/reliability/hang_detection/telemetry.rs @@ -0,0 +1,301 @@ +use std::thread::ThreadId; +use std::time::{Duration, Instant}; + +use collections::HashMap; +use hdrhistogram::Histogram; +use itertools::Itertools; + +use crate::STARTUP_TIME; + +/// Microseconds since app start +type MicroSeconds = u64; + +// TODO(yara) some crazy ideas: +// - track most recent action? +// - Action that this task was spawned from? +// - flag that enables tracking more for a specific task +// - task backtrace? (who spawned who etc) + +#[derive(Debug, Clone, serde::Serialize)] +struct HangReport { + location: String, + hang_density: f64, + mean_hang_duration: MicroSeconds, + + /// since app start + slowest_start: MicroSeconds, + /// since app start + slowest_end: MicroSeconds, + + /// 50% of bad polls where faster then this value + /// This also approximate the median + p50: MicroSeconds, + /// 75% of bad polls where faster then this value + p75: MicroSeconds, + /// 95% of bad polls where faster then this value + p95: MicroSeconds, +} + +#[derive(Debug, Clone, serde::Serialize)] +struct TelemetryReport { + foreground: Vec, + background: Vec, + actions: Vec, +} + +struct Item { + total_hanged: Duration, + slowest_poll: T, + /// saturates if more then 256 measurements end up in the same bin + histogram: Histogram, +} + +impl Item { + fn hang_density(&self, period: Duration) -> f64 { + self.total_hanged.div_duration_f64(period) + } + fn into_report(&self, location: &T::Descriptor, period: Duration) -> HangReport { + let now = Instant::now(); + let startup = STARTUP_TIME.get().unwrap_or(&now); + HangReport { + location: T::format_location(location), + hang_density: self.hang_density(period), + mean_hang_duration: self.histogram.mean() as u64, + slowest_start: self + .slowest_poll + .start() + .duration_since(*startup) + .as_micros() as u64, + slowest_end: self.slowest_poll.end().duration_since(*startup).as_micros() as u64, + p50: self.histogram.value_at_quantile(0.5), + p75: self.histogram.value_at_quantile(0.75), + p95: self.histogram.value_at_quantile(0.95), + } + } +} + +struct Hangs { + last_reset: Instant, + hangs: HashMap>, +} + +trait Hang: Clone { + type Descriptor: std::hash::Hash + PartialEq + Eq; + fn poll_duration(&self) -> Duration; + fn descriptor(&self) -> Self::Descriptor; + fn format_location(location: &Self::Descriptor) -> String; + fn start(&self) -> Instant; + fn end(&self) -> Instant; +} + +impl Hang for gpui::TaskTiming { + type Descriptor = std::panic::Location<'static>; + + fn poll_duration(&self) -> Duration { + gpui::TaskTiming::poll_duration(self) + } + fn descriptor(&self) -> Self::Descriptor { + *self.location + } + fn format_location(location: &Self::Descriptor) -> String { + format!( + "{}:{}:{}", + location.file(), + location.line(), + location.column() + ) + } + fn start(&self) -> Instant { + self.start + } + fn end(&self) -> Instant { + self.end.0 + } +} + +impl Hang for gpui::ActionTiming { + type Descriptor = &'static str; + + fn poll_duration(&self) -> Duration { + self.duration() + } + fn descriptor(&self) -> Self::Descriptor { + self.name + } + fn format_location(location: &Self::Descriptor) -> String { + location.to_string() + } + fn start(&self) -> Instant { + self.start + } + fn end(&self) -> Instant { + self.end + } +} + +impl Hangs { + fn new() -> Self { + Self { + last_reset: Instant::now(), + hangs: HashMap::default(), + } + } + fn add(&mut self, new: T, min_recorded_us: u64) { + const MICROSECONDS_MINUTE: u64 = 60 * 1000 * 1000; + + if self.hangs.len() > 1000 { + log::warn!("Too many hanging tasks to track, can not add new"); + return; + } + + self.hangs + .entry(new.descriptor()) + .and_modify(|item| { + item.total_hanged += new.poll_duration(); + item.histogram + .saturating_record(new.poll_duration().as_micros() as u64); + if new.poll_duration() > item.slowest_poll.poll_duration() { + item.slowest_poll = new.clone(); + } + }) + .or_insert({ + Item { + total_hanged: new.poll_duration(), + slowest_poll: new, + histogram: Histogram::new_with_bounds(min_recorded_us, MICROSECONDS_MINUTE, 3) + .expect("function parameters are constants and correct"), + } + }); + } + + fn report_and_reset(&mut self) -> Vec { + let period = self.last_reset.elapsed(); + self.last_reset = Instant::now(); + + let lowest_density_to_report = self + .hangs + .values() + .map(|item| item.total_hanged.div_duration_f64(period)) + .k_largest_relaxed_by(5, f64::total_cmp) + .nth(5) + .unwrap_or(0.0); + + let report = self + .hangs + .drain() + .filter(|(_, item)| item.hang_density(period) >= lowest_density_to_report) + .map(|(location, item)| item.into_report(&location, period)) + .collect(); + + report + } + + fn is_empty(&self) -> bool { + self.hangs.is_empty() + } +} + +pub struct Reporter { + record_slower_then: Duration, + foreground_thread: ThreadId, + last_send: Instant, + + foreground: Hangs, + background: Hangs, + actions: Hangs, +} + +impl Reporter { + pub fn new(foreground_thread: ThreadId) -> Self { + Self { + record_slower_then: Duration::from_millis(1), + foreground_thread, + last_send: Instant::now(), + foreground: Hangs::new(), + background: Hangs::new(), + actions: Hangs::new(), + } + } + + pub fn update( + &mut self, + task_stats: &[gpui::ThreadTaskStatistics], + action_stats: &gpui::ActionStatistics, + ) { + self.process_foreground(task_stats); + self.process_background(task_stats); + self.process_actions(action_stats); + } + + pub fn send_periodically(&mut self) { + // this should be a long period otherwise things like + // hang density get + if self.last_send.elapsed() > Duration::from_mins(30) { + self.send() + } + } + + pub fn send(&mut self) { + self.last_send = Instant::now(); + if self.nothing_to_report() { + return; + } + let report = TelemetryReport { + foreground: self.foreground.report_and_reset(), + background: self.background.report_and_reset(), + actions: self.actions.report_and_reset(), + }; + + telemetry::event!("Hang Report", report); + } + + fn process_foreground(&mut self, task_stats: &[gpui::ThreadTaskStatistics]) { + let foreground_thread = self.foreground_thread; + let foreground = task_stats + .iter() + .find(|t| t.thread_id == foreground_thread) + .expect("main thread should be in all statistics"); + + for hang in foreground + .stats + .longest_poll_times + .into_iter() + .filter(|task| task.poll_duration() > self.record_slower_then) + { + self.foreground + .add(hang, self.record_slower_then.as_micros() as u64); + } + } + fn process_background(&mut self, task_stats: &[gpui::ThreadTaskStatistics]) { + let foreground_thread = self.foreground_thread; + let background = task_stats + .iter() + .filter(|t| t.thread_id != foreground_thread); + + for worker in background { + for hang in worker + .stats + .longest_poll_times + .into_iter() + .filter(|task| task.poll_duration() > self.record_slower_then) + { + self.background + .add(hang, self.record_slower_then.as_micros() as u64); + } + } + } + + fn process_actions(&mut self, action_stats: &gpui::ActionStatistics) { + for hang in action_stats + .longest_runtimes(false) + .filter(|action| action.runtime() > self.record_slower_then) + { + self.actions + .add(hang, self.record_slower_then.as_micros() as u64); + } + } + + fn nothing_to_report(&self) -> bool { + self.actions.is_empty() && self.foreground.is_empty() && self.background.is_empty() + } +}