From a0d71a483aeabdd7321d11be4351b8091bafd881 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Yara=20=F0=9F=8F=B3=EF=B8=8F=E2=80=8D=E2=9A=A7=EF=B8=8F?= Date: Tue, 2 Jun 2026 14:03:05 +0200 Subject: [PATCH] Log worst hanging tasks and actions (#57835) We have a lot of long blocking tasks on both the foreground and background, this is a start of getting some insight into those. We will now log tasks running longer then 100ms on the foreground or background. Hanging actions will also be logged including their name. We simultaneously collect statistics on task and action performance and send those to telemetry. This includes quantiles and averages for each hanging task. Finally this adds tree dev actions: - hang action - hang foreground - hang background These cause a hang to check if hang reporting is working and in the future telemetry. Self-Review Checklist: - [x] I've reviewed my own diff for quality, security, and reliability - [x] Unsafe blocks (if any) have justifying comments - [x] The content is consistent with the [UI/UX checklist](https://github.com/zed-industries/zed/blob/main/CONTRIBUTING.md#uiux-checklist) - [x] Tests cover the new/changed behavior - [x] Performance impact has been considered and is acceptable Closes #ISSUE Release Notes: - Added logging and telemetry of tasks and actions with performance issues --- Cargo.lock | 2 + crates/fs/src/fs_watcher.rs | 26 ++ crates/gpui/Cargo.toml | 1 + crates/gpui/src/action.rs | 4 + crates/gpui/src/app.rs | 4 +- crates/gpui/src/elements/div.rs | 2 + crates/gpui/src/platform.rs | 10 +- crates/gpui/src/platform/test/dispatcher.rs | 13 - crates/gpui/src/platform_scheduler.rs | 18 +- crates/gpui/src/profiler.rs | 374 +++++++++++++++--- crates/gpui/src/profiler/actions.rs | 189 +++++++++ crates/gpui/src/window.rs | 10 +- crates/gpui_linux/src/linux/dispatcher.rs | 73 +--- crates/gpui_linux/src/linux/wayland/client.rs | 17 +- crates/gpui_linux/src/linux/x11/client.rs | 17 +- crates/gpui_macos/src/dispatcher.rs | 36 +- crates/gpui_web/src/dispatcher.rs | 15 - crates/gpui_windows/src/dispatcher.rs | 31 +- crates/miniprofiler_ui/src/miniprofiler_ui.rs | 16 +- crates/remote_server/src/headless_project.rs | 8 +- crates/repl/src/repl.rs | 6 +- crates/scheduler/src/executor.rs | 15 +- crates/scheduler/src/scheduler.rs | 19 +- crates/zed/Cargo.toml | 2 + crates/zed/src/reliability.rs | 147 +------ crates/zed/src/reliability/hang_detection.rs | 123 ++++++ .../src/reliability/hang_detection/logging.rs | 190 +++++++++ .../reliability/hang_detection/task_traces.rs | 67 ++++ .../reliability/hang_detection/telemetry.rs | 301 ++++++++++++++ 29 files changed, 1327 insertions(+), 409 deletions(-) create mode 100644 crates/gpui/src/profiler/actions.rs create mode 100644 crates/zed/src/reliability/hang_detection.rs create mode 100644 crates/zed/src/reliability/hang_detection/logging.rs create mode 100644 crates/zed/src/reliability/hang_detection/task_traces.rs create mode 100644 crates/zed/src/reliability/hang_detection/telemetry.rs 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() + } +}