#[cfg(feature = "profiler")]
use hdrhistogram::Histogram;
use itertools::Itertools;
use scheduler::{Instant, SpawnTime};
#[cfg(feature = "profiler")]
use smallvec::SmallVec;
use std::{
cell::LazyCell,
collections::{HashMap, VecDeque},
hash::{DefaultHasher, Hash, Hasher},
sync::{
Arc,
atomic::{AtomicU64, Ordering},
},
thread::ThreadId,
time::Duration,
};
mod actions;
#[cfg(feature = "profiler")]
pub mod hang;
#[cfg(feature = "profiler")]
pub mod journal;
pub use actions::{ActionStatistics, ActionTiming, take_action_stats};
use serde::{Deserialize, Serialize};
#[cfg(feature = "profiler")]
use crate::{Action, App, WindowId};
use crate::{SharedString, TasksIncluded};
#[cfg(feature = "profiler")]
#[doc(hidden)]
pub fn get_all_timings(included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
ThreadTaskTimings::collect(upgraded_thread_timings(), included)
}
#[cfg(feature = "profiler")]
#[doc(hidden)]
pub fn get_current_thread_timings(included: TasksIncluded) -> gpui::ThreadTaskTimings {
gpui::profiler::get_current_thread_task_timings(included)
}
#[cfg(feature = "profiler")]
#[doc(hidden)]
pub fn take_all_stats(included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
ThreadTaskStatistics::collect_and_reset(upgraded_thread_timings(), included)
}
#[cfg(not(feature = "profiler"))]
#[doc(hidden)]
pub fn get_all_timings(_included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
Vec::new()
}
#[cfg(not(feature = "profiler"))]
#[doc(hidden)]
pub fn get_current_thread_timings(_included: TasksIncluded) -> gpui::ThreadTaskTimings {
gpui::ThreadTaskTimings {
thread_name: None,
thread_id: std::thread::current().id(),
timings: Vec::new(),
stats: TaskStatistics::default(),
total_pushed: 0,
}
}
#[cfg(not(feature = "profiler"))]
#[doc(hidden)]
pub fn take_all_stats(_included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
Vec::new()
}
#[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: 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 {
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)]
#[derive(Debug, Clone)]
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 {
pub fn collect(
timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
included: TasksIncluded,
) -> Vec<Self> {
timings
.into_iter()
.map(|(thread_id, timings)| {
let timings = timings.lock();
let thread_name = timings.thread_name.clone();
let total_pushed = timings.total_pushed;
let completed = &timings.timings;
let mut vec = Vec::with_capacity(completed.len() + 1); 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,
}
})
.collect()
}
}
#[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: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
include_running: TasksIncluded,
) -> Vec<Self> {
timings
.into_iter()
.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()
}
}
#[derive(Debug, Clone, Serialize, Deserialize)]
pub struct SerializedLocation {
pub file: SharedString,
pub line: u32,
pub column: u32,
}
impl From<&core::panic::Location<'static>> for SerializedLocation {
fn from(value: &core::panic::Location<'static>) -> Self {
SerializedLocation {
file: value.file().into(),
line: value.line(),
column: value.column(),
}
}
}
#[derive(Debug, Clone, Serialize, Deserialize)]
pub struct SerializedTaskTiming {
pub location: SerializedLocation,
pub start: u128,
pub duration: u128,
}
impl SerializedTaskTiming {
pub fn convert(anchor: Instant, timings: &[TaskTiming]) -> Vec<SerializedTaskTiming> {
let serialized = timings
.iter()
.map(|timing| {
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,
}
})
.collect::<Vec<_>>();
serialized
}
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,
}
}
}
#[derive(Debug, Clone, Serialize, Deserialize)]
pub struct SerializedThreadTaskTimings {
pub thread_name: Option<String>,
pub thread_id: u64,
pub timings: Vec<SerializedTaskTiming>,
}
impl SerializedThreadTaskTimings {
pub fn convert(anchor: Instant, timings: ThreadTaskTimings) -> SerializedThreadTaskTimings {
let serialized_timings = SerializedTaskTiming::convert(anchor, &timings.timings);
let mut hasher = DefaultHasher::new();
timings.thread_id.hash(&mut hasher);
let thread_id = hasher.finish();
SerializedThreadTaskTimings {
thread_name: timings.thread_name,
thread_id,
timings: serialized_timings,
}
}
}
#[doc(hidden)]
#[derive(Debug, Clone)]
pub struct ThreadTimingsDelta {
pub thread_id: u64,
pub thread_name: Option<String>,
pub new_timings: Vec<SerializedTaskTiming>,
}
#[doc(hidden)]
pub struct ProfilingCollector {
startup_time: Instant,
cursors: HashMap<ThreadId, u64>,
}
impl ProfilingCollector {
pub fn new(startup_time: Instant) -> Self {
Self {
startup_time,
cursors: HashMap::default(),
}
}
pub fn startup_time(&self) -> Instant {
self.startup_time
}
pub fn collect_unseen(
&mut self,
all_timings: Vec<ThreadTaskTimings>,
) -> Vec<ThreadTimingsDelta> {
let mut deltas = Vec::with_capacity(all_timings.len());
for thread in all_timings {
let mut hasher = DefaultHasher::new();
thread.thread_id.hash(&mut hasher);
let hashed_id = hasher.finish();
let prev_cursor = self.cursors.get(&thread.thread_id).copied().unwrap_or(0);
let buffer_len = thread.timings.len() as u64;
let buffer_start = thread.total_pushed.saturating_sub(buffer_len);
let mut slice = if prev_cursor < buffer_start {
thread.timings.as_slice()
} else {
let skip = (prev_cursor - buffer_start) as usize;
&thread.timings[skip.min(thread.timings.len())..]
};
let cursor_advance = thread.total_pushed;
self.cursors.insert(thread.thread_id, cursor_advance);
if slice.is_empty() {
continue;
}
let new_timings = SerializedTaskTiming::convert(self.startup_time, slice);
deltas.push(ThreadTimingsDelta {
thread_id: hashed_id,
thread_name: thread.thread_name,
new_timings,
});
}
deltas
}
pub fn reset(&mut self) {
self.cursors.clear();
}
}
#[cfg(feature = "profiler")]
const MAX_TASK_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<TaskTiming>();
#[doc(hidden)]
pub(crate) type TaskTimings = VecDeque<TaskTiming>;
#[doc(hidden)]
pub type GuardedTaskTimings = spin::Mutex<ThreadTimings>;
#[doc(hidden)]
pub struct GlobalThreadTimings {
pub thread_id: ThreadId,
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 {
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 {
std::hint::cold_path(); 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 {
std::hint::cold_path(); 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());
fn upgraded_thread_timings() -> Vec<(ThreadId, Arc<GuardedTaskTimings>)> {
let global_thread_timings = GLOBAL_THREAD_TIMINGS.lock();
global_thread_timings
.iter()
.filter_map(|t| Some((t.thread_id, t.timings.upgrade()?)))
.collect()
}
thread_local! {
#[doc(hidden)]
pub static THREAD_TIMINGS: LazyCell<Arc<GuardedTaskTimings>> = LazyCell::new(|| {
let current_thread = std::thread::current();
let thread_name = current_thread.name();
let thread_id = current_thread.id();
let timings = ThreadTimings::new(thread_name.map(|e| e.to_string()), thread_id);
let timings = Arc::new(spin::Mutex::new(timings));
{
let timings = Arc::downgrade(&timings);
let global_timings = GlobalThreadTimings {
thread_id: std::thread::current().id(),
timings,
};
GLOBAL_THREAD_TIMINGS.lock().push(global_timings);
}
timings
});
}
#[doc(hidden)]
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,
}
impl ThreadTimings {
pub fn new(thread_name: Option<String>, thread_id: ThreadId) -> Self {
ThreadTimings {
thread_name,
thread_id,
timings: TaskTimings::new(),
stats: TaskStatistics::default(),
total_pushed: 0,
running: None,
}
}
#[cfg(feature = "profiler")]
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,
});
}
#[cfg(not(feature = "profiler"))]
pub fn update_running_task(&mut self, _: SpawnTime, _: &'static std::panic::Location<'_>) {}
#[cfg(feature = "profiler")]
pub fn save_task_timing(&mut self, ended: YieldTime) -> TaskTiming {
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() {
std::hint::cold_path(); if self.timings.len() >= MAX_TASK_TIMINGS {
self.timings.pop_front();
}
self.timings.push_back(timing);
self.total_pushed += 1;
}
timing
}
#[cfg(not(feature = "profiler"))]
pub fn save_task_timing(&mut self, _: YieldTime) {}
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()
.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,
}
}
}
impl Drop for ThreadTimings {
fn drop(&mut self) {
let mut thread_timings = GLOBAL_THREAD_TIMINGS.lock();
let Some((index, _)) = thread_timings
.iter()
.enumerate()
.find(|(_, t)| t.thread_id == self.thread_id)
else {
return;
};
thread_timings.swap_remove(index);
}
}
#[doc(hidden)]
pub fn update_running_task(spawned: SpawnTime, location: &'static std::panic::Location<'_>) {
#[cfg(feature = "profiler")]
journal::begin_foreground_turn();
THREAD_TIMINGS.with(|timings| {
timings.lock().update_running_task(spawned, location);
});
}
#[doc(hidden)]
pub fn save_task_timing() {
let yielded_at = YieldTime(Instant::now());
#[cfg(feature = "profiler")]
{
let timing = THREAD_TIMINGS.with(|timings| timings.lock().save_task_timing(yielded_at));
journal::record_task_poll(timing);
}
#[cfg(not(feature = "profiler"))]
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))
}
const TRACE_SETTING_ENABLED: u64 = 1 << 63;
const TRACE_SCOPE_COUNT_MASK: u64 = TRACE_SETTING_ENABLED - 1;
static TRACE_STATE: AtomicU64 = AtomicU64::new(0);
pub fn set_trace_enabled(enabled: bool) -> bool {
let mut state = TRACE_STATE.load(Ordering::Acquire);
loop {
let was_enabled = state & TRACE_SETTING_ENABLED != 0;
if was_enabled == enabled {
return false;
}
let next_state = if enabled {
state | TRACE_SETTING_ENABLED
} else {
state & TRACE_SCOPE_COUNT_MASK
};
match TRACE_STATE.compare_exchange_weak(
state,
next_state,
Ordering::AcqRel,
Ordering::Acquire,
) {
Ok(_) => {
if next_state == 0 {
clear_trace_buffers();
}
return true;
}
Err(updated_state) => state = updated_state,
}
}
}
#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
pub(crate) struct TraceGuard;
#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
pub(crate) fn trace_scope() -> TraceGuard {
let incremented = TRACE_STATE.fetch_update(Ordering::AcqRel, Ordering::Acquire, |state| {
(state & TRACE_SCOPE_COUNT_MASK < TRACE_SCOPE_COUNT_MASK).then_some(state + 1)
});
assert!(incremented.is_ok(), "too many active profiler trace scopes");
TraceGuard
}
#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
impl Drop for TraceGuard {
fn drop(&mut self) {
let previous_state =
TRACE_STATE.fetch_update(Ordering::AcqRel, Ordering::Acquire, |state| {
(state & TRACE_SCOPE_COUNT_MASK > 0).then_some(state - 1)
});
match previous_state {
Ok(1) => clear_trace_buffers(),
Ok(_) => {}
Err(_) => debug_assert!(false, "profiler trace scope count underflowed"),
}
}
}
pub fn trace_enabled() -> bool {
TRACE_STATE.load(Ordering::Relaxed) != 0
}
fn clear_trace_buffers() {
for (_, timings) in upgraded_thread_timings() {
let mut timings = timings.lock();
timings.timings.clear();
timings.timings.shrink_to_fit();
timings.total_pushed = 0;
}
#[cfg(feature = "profiler")]
{
let mut frames = FRAME_TIMINGS.lock();
frames.timings.clear();
frames.timings.shrink_to_fit();
frames.total_pushed = 0;
}
}
#[cfg(feature = "profiler")]
#[derive(Debug, Copy, Clone)]
pub struct FrameTiming {
pub window_id: WindowId,
pub dirty_at: Option<Instant>,
pub invalidations: u64,
pub draw_start: Instant,
pub draw_end: Instant,
}
#[cfg(feature = "profiler")]
impl FrameTiming {
pub fn draw_duration(&self) -> Duration {
self.draw_end.duration_since(self.draw_start)
}
pub fn dirty_to_draw_duration(&self) -> Option<Duration> {
self.dirty_at
.map(|dirty_at| self.draw_end.duration_since(dirty_at))
}
}
#[cfg(feature = "profiler")]
#[derive(Debug, Copy, Clone)]
pub struct PresentTiming {
pub window_id: WindowId,
pub present_start: Instant,
pub present_end: Instant,
pub animation_interval: Option<Duration>,
}
#[cfg(feature = "profiler")]
impl PresentTiming {
pub fn present_duration(&self) -> Duration {
self.present_end.duration_since(self.present_start)
}
}
#[cfg(feature = "profiler")]
#[derive(Debug, Copy, Clone)]
pub enum FrameEvent {
Draw(FrameTiming),
Present(PresentTiming),
}
#[cfg(feature = "profiler")]
#[derive(Clone)]
pub struct FrameDurationSnapshot {
pub dirty_to_present_histogram: Histogram<u64>,
pub draw_duration_histogram: Histogram<u64>,
pub present_interval_histogram: Histogram<u64>,
}
#[cfg(feature = "profiler")]
#[derive(Clone)]
pub struct InputLatencySnapshot {
pub latency_histogram: Histogram<u64>,
pub events_per_frame_histogram: Histogram<u64>,
pub mid_draw_events_dropped: u64,
}
#[cfg(feature = "profiler")]
enum WindowActivity {
Input {
started_at: Instant,
kind: &'static str,
},
Draw {
started_at: Instant,
},
}
#[cfg(feature = "profiler")]
pub struct WindowProfiler {
window_id: WindowId,
active_activities: SmallVec<[WindowActivity; 4]>,
active_actions: SmallVec<[(&'static str, Instant); 2]>,
dirty_to_present_histogram: Histogram<u64>,
draw_duration_histogram: Histogram<u64>,
present_interval_histogram: Histogram<u64>,
first_input_at: Option<Instant>,
pending_input_count: u64,
input_latency_histogram: Histogram<u64>,
events_per_frame_histogram: Histogram<u64>,
mid_draw_events_dropped: u64,
last_present_at: Option<Instant>,
animating_at_last_present: bool,
pending_frame: Option<FrameTiming>,
}
#[cfg(feature = "profiler")]
impl WindowProfiler {
pub fn new(window_id: WindowId) -> anyhow::Result<Self> {
let profiler = Self {
window_id,
active_activities: SmallVec::new(),
active_actions: SmallVec::new(),
dirty_to_present_histogram: Histogram::new(3).map_err(|error| {
anyhow::anyhow!("Failed to create dirty-to-present histogram: {error}")
})?,
draw_duration_histogram: Histogram::new(3).map_err(|error| {
anyhow::anyhow!("Failed to create draw duration histogram: {error}")
})?,
present_interval_histogram: Histogram::new(3).map_err(|error| {
anyhow::anyhow!("Failed to create present interval histogram: {error}")
})?,
first_input_at: None,
pending_input_count: 0,
input_latency_histogram: Histogram::new(3).map_err(|error| {
anyhow::anyhow!("Failed to create input latency histogram: {error}")
})?,
events_per_frame_histogram: Histogram::new(3).map_err(|error| {
anyhow::anyhow!("Failed to create events per frame histogram: {error}")
})?,
mid_draw_events_dropped: 0,
last_present_at: None,
animating_at_last_present: false,
pending_frame: None,
};
journal::record_frame_pending(window_id, Instant::now());
Ok(profiler)
}
pub fn begin_input(&mut self, kind: &'static str) {
journal::begin_foreground_turn();
self.active_activities.push(WindowActivity::Input {
started_at: Instant::now(),
kind,
});
}
pub fn end_input(&mut self, caused_invalidation: bool) {
let Some(WindowActivity::Input { started_at, kind }) = self.active_activities.pop() else {
debug_assert!(false, "input activity must be the current window activity");
journal::end_foreground_turn();
return;
};
journal::record_input(journal::InputTiming {
kind,
start: started_at,
end: Instant::now(),
caused_invalidation,
});
journal::end_foreground_turn();
if !caused_invalidation {
return;
}
let arrived_during_draw = self
.active_activities
.iter()
.any(|activity| matches!(activity, WindowActivity::Draw { .. }));
if arrived_during_draw {
self.mid_draw_events_dropped += 1;
} else {
self.first_input_at.get_or_insert(started_at);
self.pending_input_count += 1;
}
}
pub fn begin_action_handler(&mut self, action: &(dyn Action + 'static), cx: &mut App) {
journal::begin_foreground_turn();
let name = actions::update_running_action(action, cx);
self.active_actions.push((name, Instant::now()));
}
pub fn end_action_handler(&mut self) {
actions::save_action_timing();
let Some((name, start)) = self.active_actions.pop() else {
debug_assert!(false, "action handler must be begun before it ends");
journal::end_foreground_turn();
return;
};
journal::record_action(ActionTiming {
name,
start,
end: Instant::now(),
});
journal::end_foreground_turn();
}
pub fn begin_draw(&mut self) {
journal::begin_foreground_turn();
let started_at = Instant::now();
journal::record_frame_pending(self.window_id, started_at);
self.active_activities
.push(WindowActivity::Draw { started_at });
}
pub fn end_draw(&mut self, dirty_at: Option<Instant>, invalidations: u64) -> Duration {
let Some(WindowActivity::Draw {
started_at: draw_start,
}) = self.active_activities.pop()
else {
debug_assert!(false, "draw activity must be the current window activity");
journal::end_foreground_turn();
return Duration::ZERO;
};
let draw_end = Instant::now();
let frame_timing = FrameTiming {
window_id: self.window_id,
dirty_at,
invalidations,
draw_start,
draw_end,
};
let draw_duration = frame_timing.draw_duration();
self.record_draw_timing(frame_timing);
journal::end_foreground_turn();
draw_duration
}
pub fn record_present(
&mut self,
present_start: Instant,
present_end: Instant,
window_active: bool,
next_frame_scheduled: bool,
) {
self.record_present_at(
present_start,
present_end,
window_active,
next_frame_scheduled,
);
}
pub fn input_latency_snapshot(&self) -> InputLatencySnapshot {
InputLatencySnapshot {
latency_histogram: self.input_latency_histogram.clone(),
events_per_frame_histogram: self.events_per_frame_histogram.clone(),
mid_draw_events_dropped: self.mid_draw_events_dropped,
}
}
pub fn frame_duration_snapshot(&self) -> FrameDurationSnapshot {
FrameDurationSnapshot {
dirty_to_present_histogram: self.dirty_to_present_histogram.clone(),
draw_duration_histogram: self.draw_duration_histogram.clone(),
present_interval_histogram: self.present_interval_histogram.clone(),
}
}
fn record_present_at(
&mut self,
present_start: Instant,
present_end: Instant,
window_active: bool,
next_frame_scheduled: bool,
) {
if let Some(first_input_at) = self.first_input_at.take() {
let latency_nanos = present_end.duration_since(first_input_at).as_nanos() as u64;
self.input_latency_histogram.record(latency_nanos).ok();
}
if self.pending_input_count > 0 {
self.events_per_frame_histogram
.record(self.pending_input_count)
.ok();
self.pending_input_count = 0;
}
let frame = self.pending_frame.take();
let animation_interval =
if frame.is_some() && self.animating_at_last_present && window_active {
self.last_present_at
.map(|last_present_at| present_end.duration_since(last_present_at))
} else {
None
};
let present_timing = PresentTiming {
window_id: self.window_id,
present_start,
present_end,
animation_interval,
};
journal::record_present(present_timing, frame);
let Some(frame) = frame else {
return;
};
if let Some(dirty_at) = frame.dirty_at
&& let Err(error) = self
.dirty_to_present_histogram
.record(present_end.duration_since(dirty_at).as_nanos() as u64)
{
log::error!("failed to record dirty-to-present frame timing: {error}");
}
if let Some(animation_interval) = animation_interval {
self.present_interval_histogram
.record(animation_interval.as_nanos() as u64)
.ok();
}
record_frame_event(FrameEvent::Present(present_timing));
self.last_present_at = Some(present_end);
self.animating_at_last_present = next_frame_scheduled && window_active;
}
fn record_draw_timing(&mut self, timing: FrameTiming) {
self.record_draw_duration(timing.draw_duration());
self.pending_frame = Some(timing);
record_frame_event(FrameEvent::Draw(timing));
journal::record_draw(timing);
}
fn record_draw_duration(&mut self, duration: Duration) {
self.draw_duration_histogram
.record(duration.as_nanos() as u64)
.ok();
}
}
#[cfg(feature = "profiler")]
impl Drop for WindowProfiler {
fn drop(&mut self) {
journal::record_window_closed(self.window_id);
}
}
#[cfg(feature = "profiler")]
const MAX_FRAME_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<FrameEvent>();
#[cfg(feature = "profiler")]
struct FrameTimings {
timings: VecDeque<FrameEvent>,
total_pushed: u64,
}
#[cfg(feature = "profiler")]
static FRAME_TIMINGS: spin::Mutex<FrameTimings> = spin::Mutex::new(FrameTimings {
timings: VecDeque::new(),
total_pushed: 0,
});
#[cfg(feature = "profiler")]
pub fn record_frame_event(event: FrameEvent) {
if !trace_enabled() {
return;
}
std::hint::cold_path();
let mut frames = FRAME_TIMINGS.lock();
if frames.timings.len() >= MAX_FRAME_TIMINGS {
frames.timings.pop_front();
}
frames.timings.push_back(event);
frames.total_pushed += 1;
}
#[cfg(feature = "profiler")]
pub struct FrameTimingCollector {
cursor: u64,
}
#[cfg(feature = "profiler")]
impl Default for FrameTimingCollector {
fn default() -> Self {
Self::new()
}
}
#[cfg(feature = "profiler")]
impl FrameTimingCollector {
pub fn new() -> Self {
Self {
cursor: FRAME_TIMINGS.lock().total_pushed,
}
}
pub fn collect_unseen(&mut self) -> Vec<FrameEvent> {
let frames = FRAME_TIMINGS.lock();
let buffer_len = frames.timings.len() as u64;
let buffer_start = frames.total_pushed.saturating_sub(buffer_len);
let skip = self.cursor.saturating_sub(buffer_start) as usize;
let unseen = frames
.timings
.iter()
.skip(skip.min(frames.timings.len()))
.copied()
.collect();
self.cursor = frames.total_pushed;
unseen
}
}
#[cfg(all(test, feature = "profiler"))]
mod tests {
use super::*;
use std::sync::{Mutex, MutexGuard};
#[test]
fn records_draw_events_only_while_tracing() {
let _trace_test_guard = TraceTestGuard::new();
let window_id = WindowId::from(0xD0A0);
let mut window_profiler =
WindowProfiler::new(window_id).expect("window profiler should initialize");
let dirty_at = Instant::now();
let mut collector = FrameTimingCollector::new();
window_profiler.begin_draw();
window_profiler.end_draw(Some(dirty_at), 3);
assert!(
collector
.collect_unseen()
.iter()
.all(|event| !event_matches_window(*event, window_id))
);
set_trace_enabled(true);
let mut collector = FrameTimingCollector::new();
window_profiler.begin_draw();
window_profiler.end_draw(Some(dirty_at), 3);
let timing = collector
.collect_unseen()
.into_iter()
.find_map(|event| match event {
FrameEvent::Draw(timing) if timing.window_id == window_id => Some(timing),
_ => None,
})
.expect("draw event should be recorded while tracing");
assert_eq!(timing.dirty_at, Some(dirty_at));
assert_eq!(timing.invalidations, 3);
assert!(timing.draw_start >= dirty_at);
}
#[test]
fn records_present_events_for_newly_drawn_frames() {
let _trace_test_guard = TraceTestGuard::new();
set_trace_enabled(true);
let window_id = WindowId::from(0xA11E);
let mut window_profiler =
WindowProfiler::new(window_id).expect("window profiler should initialize");
let start = Instant::now();
let mut collector = FrameTimingCollector::new();
record_test_draw(&mut window_profiler, start);
window_profiler.record_present_at(start, start, true, true);
record_test_draw(&mut window_profiler, start + FRAME);
window_profiler.record_present_at(start + FRAME, start + FRAME, true, true);
window_profiler.record_present_at(
start + FRAME + FRAME / 2,
start + FRAME + FRAME / 2,
true,
true,
);
let present_timings = collector
.collect_unseen()
.into_iter()
.filter_map(|event| match event {
FrameEvent::Present(timing) if timing.window_id == window_id => Some(timing),
_ => None,
})
.collect::<Vec<_>>();
let [first_present, second_present] = present_timings.as_slice() else {
panic!("expected exactly two present events, got {present_timings:?}");
};
assert_eq!(first_present.animation_interval, None);
assert_eq!(second_present.animation_interval, Some(FRAME));
#[cfg(feature = "profiler")]
{
assert_eq!(window_profiler.present_interval_histogram.len(), 1);
assert!(
window_profiler.present_interval_histogram.max()
>= second_present
.animation_interval
.expect("second present should have an animation interval")
.as_nanos() as u64
);
}
}
#[test]
fn disabling_tracing_clears_frame_events() {
let _trace_test_guard = TraceTestGuard::new();
set_trace_enabled(true);
let window_id = WindowId::from(0xC1EA);
let mut window_profiler =
WindowProfiler::new(window_id).expect("window profiler should initialize");
let mut collector = FrameTimingCollector::new();
window_profiler.begin_draw();
window_profiler.end_draw(None, 0);
assert!(
FRAME_TIMINGS
.lock()
.timings
.iter()
.copied()
.any(|event| event_matches_window(event, window_id))
);
set_trace_enabled(false);
assert!(
collector
.collect_unseen()
.iter()
.all(|event| !event_matches_window(*event, window_id))
);
}
#[cfg(feature = "profiler")]
#[test]
fn records_intervals_only_between_animation_frames() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(1)).expect("window profiler should initialize");
let start = Instant::now();
draw_and_present(&mut window_profiler, start, true, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 0);
draw_and_present(&mut window_profiler, start + FRAME, true, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 1);
draw_and_present(&mut window_profiler, start + FRAME * 2, true, false);
assert_eq!(window_profiler.present_interval_histogram.len(), 2);
draw_and_present(&mut window_profiler, start + FRAME * 100, true, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 2);
}
#[cfg(feature = "profiler")]
#[test]
fn missed_frames_stretch_the_recorded_interval() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(2)).expect("window profiler should initialize");
let start = Instant::now();
draw_and_present(&mut window_profiler, start, true, true);
draw_and_present(&mut window_profiler, start + FRAME * 5, true, true);
let recorded = window_profiler.present_interval_histogram.max();
assert!(recorded >= (FRAME * 4).as_nanos() as u64);
}
#[cfg(feature = "profiler")]
#[test]
fn ignores_re_presents_of_unchanged_frames() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(3)).expect("window profiler should initialize");
let start = Instant::now();
draw_and_present(&mut window_profiler, start, true, true);
window_profiler.record_present_at(start + FRAME / 2, start + FRAME / 2, true, true);
draw_and_present(&mut window_profiler, start + FRAME, true, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 1);
assert!(
window_profiler.present_interval_histogram.max() >= (FRAME * 3 / 4).as_nanos() as u64
);
}
#[cfg(feature = "profiler")]
#[test]
fn skips_intervals_for_inactive_windows() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(4)).expect("window profiler should initialize");
let start = Instant::now();
draw_and_present(&mut window_profiler, start, false, true);
draw_and_present(&mut window_profiler, start + FRAME, false, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 0);
draw_and_present(&mut window_profiler, start + FRAME * 2, true, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 0);
draw_and_present(&mut window_profiler, start + FRAME * 3, true, true);
assert_eq!(window_profiler.present_interval_histogram.len(), 1);
}
#[test]
fn records_dirty_to_present_durations() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(8)).expect("window profiler should initialize");
let draw_end = Instant::now();
let present_end = draw_end + Duration::from_millis(6);
record_test_draw(&mut window_profiler, draw_end);
window_profiler.record_present_at(present_end, present_end, true, false);
let snapshot = window_profiler.frame_duration_snapshot();
let histogram = snapshot.dirty_to_present_histogram;
assert_eq!(histogram.len(), 1);
assert!(histogram.max() >= Duration::from_millis(10).as_nanos() as u64);
}
#[cfg(feature = "profiler")]
#[test]
fn records_every_draw_duration() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(5)).expect("window profiler should initialize");
window_profiler.record_draw_duration(Duration::from_millis(2));
window_profiler.record_draw_duration(Duration::from_millis(40));
let snapshot = window_profiler.frame_duration_snapshot();
assert_eq!(snapshot.draw_duration_histogram.len(), 2);
assert!(snapshot.draw_duration_histogram.max() >= 39_000_000);
}
#[test]
fn records_input_latency_at_the_frame_presentation_timestamp() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(6)).expect("window profiler should initialize");
let first_input_at = Instant::now();
let presented_at = first_input_at + Duration::from_millis(12);
begin_input_at(&mut window_profiler, first_input_at);
window_profiler.end_input(true);
begin_input_at(
&mut window_profiler,
first_input_at + Duration::from_millis(2),
);
window_profiler.end_input(true);
record_test_draw(&mut window_profiler, presented_at);
window_profiler.record_present_at(presented_at, presented_at, true, false);
let snapshot = window_profiler.input_latency_snapshot();
assert_eq!(snapshot.latency_histogram.len(), 1);
assert!(snapshot.latency_histogram.max() >= Duration::from_millis(12).as_nanos() as u64);
assert_eq!(snapshot.events_per_frame_histogram.len(), 1);
assert_eq!(snapshot.events_per_frame_histogram.max(), 2);
assert_eq!(snapshot.mid_draw_events_dropped, 0);
}
#[test]
fn excludes_input_that_arrives_during_a_draw() {
let mut window_profiler =
WindowProfiler::new(WindowId::from(7)).expect("window profiler should initialize");
window_profiler.begin_draw();
begin_input_at(&mut window_profiler, Instant::now());
window_profiler.end_input(true);
window_profiler.end_draw(None, 0);
let snapshot = window_profiler.input_latency_snapshot();
assert!(snapshot.latency_histogram.is_empty());
assert!(snapshot.events_per_frame_histogram.is_empty());
assert_eq!(snapshot.mid_draw_events_dropped, 1);
}
#[test]
fn overlapping_trace_scopes_keep_tracing_enabled() {
let _trace_test_guard = TraceTestGuard::new();
let first_scope = trace_scope();
let second_scope = trace_scope();
assert!(trace_enabled());
drop(first_scope);
assert!(trace_enabled());
drop(second_scope);
assert!(!trace_enabled());
}
const FRAME: Duration = Duration::from_millis(16);
static TRACE_TEST_LOCK: Mutex<()> = Mutex::new(());
struct TraceTestGuard {
was_enabled: bool,
_lock: MutexGuard<'static, ()>,
}
impl TraceTestGuard {
fn new() -> Self {
let lock = TRACE_TEST_LOCK
.lock()
.unwrap_or_else(|poisoned| poisoned.into_inner());
let was_enabled = trace_enabled();
set_trace_enabled(false);
Self {
was_enabled,
_lock: lock,
}
}
}
impl Drop for TraceTestGuard {
fn drop(&mut self) {
set_trace_enabled(false);
if self.was_enabled {
set_trace_enabled(true);
}
}
}
fn event_matches_window(event: FrameEvent, window_id: WindowId) -> bool {
match event {
FrameEvent::Draw(timing) => timing.window_id == window_id,
FrameEvent::Present(timing) => timing.window_id == window_id,
}
}
fn begin_input_at(window_profiler: &mut WindowProfiler, started_at: Instant) {
window_profiler
.active_activities
.push(WindowActivity::Input {
started_at,
kind: "test",
});
}
#[cfg(feature = "profiler")]
fn draw_and_present(
window_profiler: &mut WindowProfiler,
presented_at: Instant,
window_active: bool,
next_frame_scheduled: bool,
) {
record_test_draw(window_profiler, presented_at);
window_profiler.record_present_at(
presented_at,
presented_at,
window_active,
next_frame_scheduled,
);
}
fn record_test_draw(window_profiler: &mut WindowProfiler, draw_end: Instant) {
window_profiler.record_draw_timing(FrameTiming {
window_id: window_profiler.window_id,
dirty_at: Some(draw_end - Duration::from_millis(4)),
invalidations: 1,
draw_start: draw_end - Duration::from_millis(2),
draw_end,
});
}
}