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
This commit is contained in:
Yara 🏳️‍⚧️ authored and GitHub committed 2026-06-02 12:03:05 +00:00
1 parent 1a9468df12
commit a0d71a483a
29 files changed
+1327 -409

No files matched your search

Generated
+2
View File
@@ -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",
+26
View File
@@ -430,6 +430,10 @@ fn push_notify_event(
.collect::<Vec<_>>();
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<Option<(Instant, usize)>> = 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<PathEvent>, path_events: &mut Vec<PathEvent>) {
if !path_events
.iter()
+1
View File
@@ -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"] }
+4
View File
@@ -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,
+2 -2
View File
@@ -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<App>`] 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();
+2
View File
@@ -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<A: Action>(&mut self, listener: impl Fn(&A, &mut Window, &mut App) + 'static) {
self.action_listeners.push((
TypeId::of::<A>(),
@@ -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<A: Action>(
mut self,
listener: impl Fn(&A, &mut Window, &mut App) + 'static,
+7 -3
View File
@@ -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<RunnableMeta>;
#[doc(hidden)]
pub type TimerResolutionGuard = gpui_util::Deferred<Box<dyn FnOnce() + Send>>;
#[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<ThreadTaskTimings>;
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);
@@ -112,19 +112,6 @@ impl Clone for TestDispatcher {
}
impl PlatformDispatcher for TestDispatcher {
fn get_all_timings(&self) -> Vec<crate::ThreadTaskTimings> {
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()
}
+5 -13
View File
@@ -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<ThreadTaskTimings> {
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
}
+325 -49
View File
@@ -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<gpui::ThreadTaskTimings> {
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<gpui::ThreadTaskStatistics> {
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<Instant>,
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<String>,
pub thread_id: ThreadId,
pub timings: Vec<TaskTiming>,
pub stats: TaskStatistics,
pub total_pushed: u64,
}
impl ThreadTaskTimings {
/// Convert global thread timings into their structured format.
pub fn convert(timings: &[GlobalThreadTimings]) -> Vec<Self> {
pub fn collect(timings: &[GlobalThreadTimings], included: TasksIncluded) -> Vec<Self> {
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<String>,
pub thread_id: ThreadId,
pub stats: TaskStatistics,
}
impl ThreadTaskStatistics {
pub fn collect_and_reset(
timings: &[GlobalThreadTimings],
include_running: TasksIncluded,
) -> Vec<Self> {
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<GuardedTaskTimings>,
}
#[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<Vec<GlobalThreadTimings>> =
spin::Mutex::new(Vec::new());
@@ -292,6 +513,8 @@ pub struct ThreadTimings {
pub thread_name: Option<String>,
pub thread_id: ThreadId,
pub timings: TaskTimings,
pub running: Option<ActiveTiming>,
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)
}
+189
View File
@@ -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<ActionTiming, 5>,
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<Item = ActionTiming> {
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<ActionStatistics> =
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()
}
+9 -1
View File
@@ -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;
}
+9 -64
View File
@@ -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<gpui::ThreadTaskTimings> {
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
+4 -13
View File
@@ -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();
});
}
}
+4 -13
View File
@@ -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();
});
}
}
+5 -31
View File
@@ -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<ThreadTaskTimings> {
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::<RunnableMeta>::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();
}
-15
View File
@@ -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<ThreadTaskTimings> {
// 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()
}
+5 -26
View File
@@ -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<ThreadTaskTimings> {
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
}
@@ -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::<SettingsStore>(|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);
}
+5 -3
View File
@@ -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);
+2 -4
View File
@@ -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)
+12 -3
View File
@@ -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| {
+13 -6
View File
@@ -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()),
}
}
}
+2
View File
@@ -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 }
+5 -142
View File
@@ -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<Client>, 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<Client>, 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<chrono::Local>,
) {
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::<Vec<_>>();
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<Client>) -> anyhow::Result<()> {
let Some(minidump_endpoint) = MINIDUMP_ENDPOINT.as_ref() else {
log::warn!("Minidump endpoint not set");
@@ -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<Client>, 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<Client>, 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");
}
@@ -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<PerfIssue, Instant>,
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<Item = PerfIssue>) {
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<gpui::profiler::ActionTiming>);
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(())
}
}
@@ -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<PathBuf> {
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::<Vec<_>>();
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();
}
}
}
}
@@ -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<HangReport>,
background: Vec<HangReport>,
actions: Vec<HangReport>,
}
struct Item<T: Hang> {
total_hanged: Duration,
slowest_poll: T,
/// saturates if more then 256 measurements end up in the same bin
histogram: Histogram<u8>,
}
impl<T: Hang> Item<T> {
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<T: Hang> {
last_reset: Instant,
hangs: HashMap<T::Descriptor, Item<T>>,
}
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<T: Hang> Hangs<T> {
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<HangReport> {
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<gpui::TaskTiming>,
background: Hangs<gpui::TaskTiming>,
actions: Hangs<gpui::ActionTiming>,
}
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()
}
}