Skip to main content

gpui/
profiler.rs

1//! Profiling utilities for task, frame, and thread performance tracking.
2
3#[cfg(feature = "profiler")]
4use hdrhistogram::Histogram;
5use itertools::Itertools;
6use scheduler::{Instant, SpawnTime};
7#[cfg(feature = "profiler")]
8use smallvec::SmallVec;
9use std::{
10    cell::LazyCell,
11    collections::{HashMap, VecDeque},
12    hash::{DefaultHasher, Hash, Hasher},
13    sync::{
14        Arc,
15        atomic::{AtomicU64, Ordering},
16    },
17    thread::ThreadId,
18    time::Duration,
19};
20
21mod actions;
22#[cfg(feature = "profiler")]
23pub mod hang;
24#[cfg(feature = "profiler")]
25pub mod journal;
26pub use actions::{ActionStatistics, ActionTiming, take_action_stats};
27
28use serde::{Deserialize, Serialize};
29
30#[cfg(feature = "profiler")]
31use crate::{Action, App, WindowId};
32use crate::{SharedString, TasksIncluded};
33
34#[cfg(feature = "profiler")]
35#[doc(hidden)]
36pub fn get_all_timings(included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
37    ThreadTaskTimings::collect(upgraded_thread_timings(), included)
38}
39
40#[cfg(feature = "profiler")]
41#[doc(hidden)]
42pub fn get_current_thread_timings(included: TasksIncluded) -> gpui::ThreadTaskTimings {
43    gpui::profiler::get_current_thread_task_timings(included)
44}
45
46#[cfg(feature = "profiler")]
47#[doc(hidden)]
48pub fn take_all_stats(included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
49    ThreadTaskStatistics::collect_and_reset(upgraded_thread_timings(), included)
50}
51
52#[cfg(not(feature = "profiler"))]
53#[doc(hidden)]
54pub fn get_all_timings(_included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
55    Vec::new()
56}
57#[cfg(not(feature = "profiler"))]
58#[doc(hidden)]
59pub fn get_current_thread_timings(_included: TasksIncluded) -> gpui::ThreadTaskTimings {
60    gpui::ThreadTaskTimings {
61        thread_name: None,
62        thread_id: std::thread::current().id(),
63        timings: Vec::new(),
64        stats: TaskStatistics::default(),
65        total_pushed: 0,
66    }
67}
68#[cfg(not(feature = "profiler"))]
69#[doc(hidden)]
70pub fn take_all_stats(_included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
71    Vec::new()
72}
73
74#[doc(hidden)]
75#[derive(Debug, Copy, Clone)]
76pub struct YieldTime(pub Instant);
77
78#[doc(hidden)]
79#[derive(Copy, Clone)]
80pub struct TaskTiming {
81    pub location: &'static core::panic::Location<'static>,
82    pub spawned: SpawnTime,
83    pub start: Instant,
84    pub end: YieldTime,
85}
86
87impl std::fmt::Debug for TaskTiming {
88    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
89        f.debug_struct("TaskTiming")
90            .field("location", &self.location)
91            .field("since_spawned", &self.spawned.0.elapsed())
92            .field("last_poll_duration", &self.poll_duration())
93            .field("total_runtime", &self.since_spawn())
94            .finish()
95    }
96}
97
98#[doc(hidden)]
99#[derive(Debug, Copy, Clone)]
100pub struct ActiveTiming {
101    pub location: &'static core::panic::Location<'static>,
102    pub spawned: SpawnTime,
103    pub start: Instant,
104}
105
106impl TaskTiming {
107    /// A task timing with a duration of zero. Any task will replace this in history.
108    pub fn placeholder() -> Self {
109        let now = Instant::now();
110        Self {
111            location: std::panic::Location::caller(),
112            spawned: SpawnTime(now),
113            start: now,
114            end: YieldTime(now),
115        }
116    }
117
118    #[inline(always)]
119    pub fn poll_duration(&self) -> Duration {
120        self.end.0 - self.start
121    }
122
123    #[inline(always)]
124    fn since_spawn(&self) -> Duration {
125        self.end.0 - self.spawned.0
126    }
127}
128
129#[doc(hidden)]
130#[derive(Debug, Clone)]
131pub struct ThreadTaskTimings {
132    pub thread_name: Option<String>,
133    pub thread_id: ThreadId,
134    pub timings: Vec<TaskTiming>,
135    pub stats: TaskStatistics,
136    pub total_pushed: u64,
137}
138
139impl ThreadTaskTimings {
140    /// Convert upgraded per-thread timings into their structured format.
141    pub fn collect(
142        timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
143        included: TasksIncluded,
144    ) -> Vec<Self> {
145        timings
146            .into_iter()
147            .map(|(thread_id, timings)| {
148                let timings = timings.lock();
149                let thread_name = timings.thread_name.clone();
150                let total_pushed = timings.total_pushed;
151                let completed = &timings.timings;
152
153                let mut vec = Vec::with_capacity(completed.len() + 1); // +1 for running task
154                let (s1, s2) = completed.as_slices();
155                vec.extend_from_slice(s1);
156                vec.extend_from_slice(s2);
157                if let TasksIncluded::CompletedAndRunning = included
158                    && let Some(running) = timings.running
159                {
160                    vec.push(TaskTiming {
161                        location: running.location,
162                        spawned: running.spawned,
163                        start: running.start,
164                        end: YieldTime(Instant::now()),
165                    })
166                }
167
168                ThreadTaskTimings {
169                    thread_name,
170                    thread_id,
171                    timings: vec,
172                    stats: timings.stats.clone(),
173                    total_pushed,
174                }
175            })
176            .collect()
177    }
178}
179
180#[doc(hidden)]
181#[derive(Debug)]
182pub struct ThreadTaskStatistics {
183    pub thread_name: Option<String>,
184    pub thread_id: ThreadId,
185    pub stats: TaskStatistics,
186}
187
188impl ThreadTaskStatistics {
189    pub fn collect_and_reset(
190        timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
191        include_running: TasksIncluded,
192    ) -> Vec<Self> {
193        timings
194            .into_iter()
195            .map(|(thread_id, timings)| {
196                let mut timings = timings.lock();
197                let thread_name = timings.thread_name.clone();
198
199                let mut stats = std::mem::take(&mut timings.stats);
200                if let TasksIncluded::CompletedAndRunning = include_running
201                    && let Some(ActiveTiming {
202                        location,
203                        spawned,
204                        start,
205                    }) = timings.running
206                {
207                    let end = YieldTime(Instant::now());
208                    let timing = TaskTiming {
209                        location,
210                        spawned,
211                        start,
212                        end,
213                    };
214                    stats.add_runtime(timing);
215                    stats.add_yield_timing(timing);
216                }
217
218                Self {
219                    thread_name,
220                    thread_id,
221                    stats,
222                }
223            })
224            .collect()
225    }
226}
227
228/// Serializable variant of [`core::panic::Location`]
229#[derive(Debug, Clone, Serialize, Deserialize)]
230pub struct SerializedLocation {
231    /// Name of the source file
232    pub file: SharedString,
233    /// Line in the source file
234    pub line: u32,
235    /// Column in the source file
236    pub column: u32,
237}
238
239impl From<&core::panic::Location<'static>> for SerializedLocation {
240    fn from(value: &core::panic::Location<'static>) -> Self {
241        SerializedLocation {
242            file: value.file().into(),
243            line: value.line(),
244            column: value.column(),
245        }
246    }
247}
248
249/// Serializable variant of [`TaskTiming`]
250#[derive(Debug, Clone, Serialize, Deserialize)]
251pub struct SerializedTaskTiming {
252    /// Location of the timing
253    pub location: SerializedLocation,
254    /// Time at which the measurement was reported in nanoseconds
255    pub start: u128,
256    /// Duration of the measurement in nanoseconds
257    pub duration: u128,
258}
259
260impl SerializedTaskTiming {
261    /// Convert an array of [`TaskTiming`] into their serializable format
262    ///
263    /// # Params
264    ///
265    /// `anchor` - [`Instant`] that should be earlier than all timings to use as base anchor
266    pub fn convert(anchor: Instant, timings: &[TaskTiming]) -> Vec<SerializedTaskTiming> {
267        let serialized = timings
268            .iter()
269            .map(|timing| {
270                let start = timing.start.duration_since(anchor).as_nanos();
271                let duration = timing.end.0.duration_since(timing.start).as_nanos();
272                SerializedTaskTiming {
273                    location: timing.location.into(),
274                    start,
275                    duration,
276                }
277            })
278            .collect::<Vec<_>>();
279
280        serialized
281    }
282
283    /// `anchor` - [`Instant`] that should be earlier than all timings to use as base anchor
284    pub fn from(anchor: Instant, timing: TaskTiming) -> SerializedTaskTiming {
285        let start = timing.start.duration_since(anchor).as_nanos();
286        let duration = timing.end.0.duration_since(timing.start).as_nanos();
287        SerializedTaskTiming {
288            location: timing.location.into(),
289            start,
290            duration,
291        }
292    }
293}
294
295/// Serializable variant of [`ThreadTaskTimings`]
296#[derive(Debug, Clone, Serialize, Deserialize)]
297pub struct SerializedThreadTaskTimings {
298    /// Thread name
299    pub thread_name: Option<String>,
300    /// Hash of the thread id
301    pub thread_id: u64,
302    /// Timing records for this thread
303    pub timings: Vec<SerializedTaskTiming>,
304}
305
306impl SerializedThreadTaskTimings {
307    /// Convert [`ThreadTaskTimings`] into their serializable format
308    ///
309    /// # Params
310    ///
311    /// `anchor` - [`Instant`] that should be earlier than all timings to use as base anchor
312    pub fn convert(anchor: Instant, timings: ThreadTaskTimings) -> SerializedThreadTaskTimings {
313        let serialized_timings = SerializedTaskTiming::convert(anchor, &timings.timings);
314
315        let mut hasher = DefaultHasher::new();
316        timings.thread_id.hash(&mut hasher);
317        let thread_id = hasher.finish();
318
319        SerializedThreadTaskTimings {
320            thread_name: timings.thread_name,
321            thread_id,
322            timings: serialized_timings,
323        }
324    }
325}
326
327#[doc(hidden)]
328#[derive(Debug, Clone)]
329pub struct ThreadTimingsDelta {
330    /// Hashed thread id
331    pub thread_id: u64,
332    /// Thread name, if known
333    pub thread_name: Option<String>,
334    /// New timings since the last call. If the circular buffer wrapped around
335    /// since the previous poll, some entries may have been lost.
336    pub new_timings: Vec<SerializedTaskTiming>,
337}
338
339/// Tracks which timing events have already been seen so that callers can request only unseen events.
340#[doc(hidden)]
341pub struct ProfilingCollector {
342    startup_time: Instant,
343    cursors: HashMap<ThreadId, u64>,
344}
345
346impl ProfilingCollector {
347    pub fn new(startup_time: Instant) -> Self {
348        Self {
349            startup_time,
350            cursors: HashMap::default(),
351        }
352    }
353
354    pub fn startup_time(&self) -> Instant {
355        self.startup_time
356    }
357
358    pub fn collect_unseen(
359        &mut self,
360        all_timings: Vec<ThreadTaskTimings>,
361    ) -> Vec<ThreadTimingsDelta> {
362        let mut deltas = Vec::with_capacity(all_timings.len());
363
364        for thread in all_timings {
365            let mut hasher = DefaultHasher::new();
366            thread.thread_id.hash(&mut hasher);
367            let hashed_id = hasher.finish();
368
369            let prev_cursor = self.cursors.get(&thread.thread_id).copied().unwrap_or(0);
370            let buffer_len = thread.timings.len() as u64;
371            let buffer_start = thread.total_pushed.saturating_sub(buffer_len);
372
373            let slice = if prev_cursor < buffer_start {
374                // Cursor fell behind the buffer — some entries were evicted.
375                // Return everything still in the buffer.
376                thread.timings.as_slice()
377            } else {
378                let skip = (prev_cursor - buffer_start) as usize;
379                &thread.timings[skip.min(thread.timings.len())..]
380            };
381
382            let cursor_advance = thread.total_pushed;
383            self.cursors.insert(thread.thread_id, cursor_advance);
384
385            if slice.is_empty() {
386                continue;
387            }
388
389            let new_timings = SerializedTaskTiming::convert(self.startup_time, slice);
390
391            deltas.push(ThreadTimingsDelta {
392                thread_id: hashed_id,
393                thread_name: thread.thread_name,
394                new_timings,
395            });
396        }
397
398        deltas
399    }
400
401    pub fn reset(&mut self) {
402        self.cursors.clear();
403    }
404}
405
406// Allow 16MiB of task timing entries.
407// VecDeque grows by doubling its capacity when full, so keep this a power of 2 to avoid wasting
408// memory.
409#[cfg(feature = "profiler")]
410const MAX_TASK_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<TaskTiming>();
411
412#[doc(hidden)]
413pub(crate) type TaskTimings = VecDeque<TaskTiming>;
414
415#[doc(hidden)]
416pub type GuardedTaskTimings = spin::Mutex<ThreadTimings>;
417
418#[doc(hidden)]
419pub struct GlobalThreadTimings {
420    pub thread_id: ThreadId,
421    pub timings: std::sync::Weak<GuardedTaskTimings>,
422}
423
424#[doc(hidden)]
425#[derive(Debug, Clone)]
426pub struct TaskStatistics {
427    pub poll_time_to_beat: Duration,
428    pub runtime_to_beat: Duration,
429    pub longest_poll_times: [TaskTiming; 5],
430    pub longest_runtimes: [TaskTiming; 5],
431}
432
433impl std::fmt::Display for TaskStatistics {
434    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
435        f.write_str("Tasks that blocked the longest before yielding\n")?;
436        for timing in self.longest_poll_times {
437            f.write_fmt(format_args!(
438                "{:<20} - {}:{}\n",
439                format!("{:?}", timing.poll_duration()),
440                timing.location.file(),
441                timing.location.column()
442            ))?;
443        }
444        f.write_str("Tasks that ran the longest\n")?;
445        for timing in self.longest_runtimes {
446            f.write_fmt(format_args!(
447                "{:<20} - {}:{}\n",
448                format!("{:?}", timing.since_spawn()),
449                timing.location.file(),
450                timing.location.column()
451            ))?;
452        }
453        Ok(())
454    }
455}
456
457impl Default for TaskStatistics {
458    fn default() -> Self {
459        Self {
460            // Do not track polls that are not problematic
461            // this keeps more calls on the fast path
462            poll_time_to_beat: Duration::from_micros(100),
463            runtime_to_beat: Duration::from_micros(100),
464            longest_poll_times: [TaskTiming::placeholder(); 5],
465            longest_runtimes: [TaskTiming::placeholder(); 5],
466        }
467    }
468}
469
470impl TaskStatistics {
471    #[inline(always)]
472    fn add_yield_timing(&mut self, task: TaskTiming) {
473        let yielded_after = task.poll_duration();
474        if yielded_after >= self.poll_time_to_beat {
475            std::hint::cold_path(); // most tasks are not the worst, optimize for that
476            let to_replace = self
477                .longest_poll_times
478                .iter()
479                .position_min_by_key(|task| task.since_spawn())
480                .expect("guarded by the comparison with nth_longest_yield_time");
481            self.longest_poll_times[to_replace] = task;
482
483            self.poll_time_to_beat = self
484                .longest_poll_times
485                .iter()
486                .map(|task| task.since_spawn())
487                .min()
488                .expect("never empty");
489        }
490    }
491
492    #[inline(always)]
493    fn add_runtime(&mut self, task: TaskTiming) {
494        let runtime = task.since_spawn();
495        if runtime >= self.runtime_to_beat {
496            std::hint::cold_path(); // most tasks are not the worst, optimize for that
497            let to_replace = self
498                .longest_runtimes
499                .iter()
500                .position_min_by_key(|task| task.since_spawn())
501                .expect("guarded by the comparison with nth_longest_yield_time");
502            self.longest_runtimes[to_replace] = task;
503
504            self.runtime_to_beat = self
505                .longest_runtimes
506                .iter()
507                .map(|task| task.since_spawn())
508                .min()
509                .expect("never empty");
510        }
511    }
512}
513
514#[doc(hidden)]
515pub static GLOBAL_THREAD_TIMINGS: spin::Mutex<Vec<GlobalThreadTimings>> =
516    spin::Mutex::new(Vec::new());
517
518/// Upgrades all live per-thread timing handles, holding the global registry
519/// lock only for the duration of the upgrades.
520///
521/// The upgraded `Arc`s must never be dropped while `GLOBAL_THREAD_TIMINGS` is
522/// locked: dropping the last strong reference runs [`ThreadTimings::drop`],
523/// which locks `GLOBAL_THREAD_TIMINGS` again and would deadlock the
524/// non-reentrant spinlock. A thread exiting concurrently can hand off its last
525/// reference to us at any time, so callers of this function process (lock,
526/// read, drop) the returned handles only after the global lock is released.
527fn upgraded_thread_timings() -> Vec<(ThreadId, Arc<GuardedTaskTimings>)> {
528    let global_thread_timings = GLOBAL_THREAD_TIMINGS.lock();
529    global_thread_timings
530        .iter()
531        .filter_map(|t| Some((t.thread_id, t.timings.upgrade()?)))
532        .collect()
533}
534
535thread_local! {
536    #[doc(hidden)]
537    pub static THREAD_TIMINGS: LazyCell<Arc<GuardedTaskTimings>> = LazyCell::new(|| {
538        let current_thread = std::thread::current();
539        let thread_name = current_thread.name();
540        let thread_id = current_thread.id();
541        let timings = ThreadTimings::new(thread_name.map(|e| e.to_string()), thread_id);
542        let timings = Arc::new(spin::Mutex::new(timings));
543
544        {
545            let timings = Arc::downgrade(&timings);
546            let global_timings = GlobalThreadTimings {
547                thread_id: std::thread::current().id(),
548                timings,
549            };
550            GLOBAL_THREAD_TIMINGS.lock().push(global_timings);
551        }
552
553        timings
554    });
555}
556
557#[doc(hidden)]
558pub struct ThreadTimings {
559    pub thread_name: Option<String>,
560    pub thread_id: ThreadId,
561    pub timings: TaskTimings,
562    pub running: Option<ActiveTiming>,
563    pub stats: TaskStatistics,
564    pub total_pushed: u64,
565}
566
567impl ThreadTimings {
568    pub fn new(thread_name: Option<String>, thread_id: ThreadId) -> Self {
569        ThreadTimings {
570            thread_name,
571            thread_id,
572            timings: TaskTimings::new(),
573            stats: TaskStatistics::default(),
574            total_pushed: 0,
575            running: None,
576        }
577    }
578
579    #[cfg(feature = "profiler")]
580    pub fn update_running_task(
581        &mut self,
582        spawned: SpawnTime,
583        location: &'static std::panic::Location<'_>,
584    ) {
585        let start = Instant::now();
586        self.running = Some(ActiveTiming {
587            spawned,
588            location,
589            start,
590        });
591    }
592    #[cfg(not(feature = "profiler"))]
593    pub fn update_running_task(&mut self, _: SpawnTime, _: &'static std::panic::Location<'_>) {}
594
595    #[cfg(feature = "profiler")]
596    pub fn save_task_timing(&mut self, ended: YieldTime) -> TaskTiming {
597        let ActiveTiming {
598            location,
599            start,
600            spawned,
601        } = self
602            .running
603            .take()
604            .expect("this function is only ever called after register_task_start");
605
606        let timing = TaskTiming {
607            location,
608            spawned,
609            start,
610            end: ended,
611        };
612        self.stats.add_yield_timing(timing);
613        self.stats.add_runtime(timing);
614
615        if trace_enabled() {
616            std::hint::cold_path(); // optimize for when the profiling is off
617            if self.timings.len() >= MAX_TASK_TIMINGS {
618                self.timings.pop_front();
619            }
620            self.timings.push_back(timing);
621            self.total_pushed += 1;
622        }
623        timing
624    }
625    #[cfg(not(feature = "profiler"))]
626    pub fn save_task_timing(&mut self, _: YieldTime) {}
627
628    // Running tasks are included in the reliability trace, which is written
629    // whenever the foreground executor makes no progress for > n seconds
630    pub fn get_thread_task_timings(&self, includes: TasksIncluded) -> ThreadTaskTimings {
631        ThreadTaskTimings {
632            thread_name: self.thread_name.clone(),
633            thread_id: self.thread_id,
634            timings: self
635                .timings
636                .iter()
637                .cloned()
638                .chain(
639                    self.running
640                        .filter(|_| matches!(includes, TasksIncluded::CompletedAndRunning))
641                        .map(|running| TaskTiming {
642                            spawned: running.spawned,
643                            location: running.location,
644                            start: running.start,
645                            end: YieldTime(Instant::now()),
646                        }),
647                )
648                .collect(),
649            stats: self.stats.clone(),
650            total_pushed: self.total_pushed,
651        }
652    }
653}
654
655impl Drop for ThreadTimings {
656    fn drop(&mut self) {
657        let mut thread_timings = GLOBAL_THREAD_TIMINGS.lock();
658
659        let Some((index, _)) = thread_timings
660            .iter()
661            .enumerate()
662            .find(|(_, t)| t.thread_id == self.thread_id)
663        else {
664            return;
665        };
666        thread_timings.swap_remove(index);
667    }
668}
669
670#[doc(hidden)]
671pub fn update_running_task(spawned: SpawnTime, location: &'static std::panic::Location<'_>) {
672    #[cfg(feature = "profiler")]
673    journal::begin_foreground_turn();
674    THREAD_TIMINGS.with(|timings| {
675        timings.lock().update_running_task(spawned, location);
676    });
677}
678
679#[doc(hidden)]
680pub fn save_task_timing() {
681    let yielded_at = YieldTime(Instant::now());
682    #[cfg(feature = "profiler")]
683    {
684        let timing = THREAD_TIMINGS.with(|timings| timings.lock().save_task_timing(yielded_at));
685        journal::record_task_poll(timing);
686    }
687    #[cfg(not(feature = "profiler"))]
688    THREAD_TIMINGS.with(|timings| {
689        timings.lock().save_task_timing(yielded_at);
690    });
691}
692
693#[doc(hidden)]
694pub fn get_current_thread_task_timings(include_running: TasksIncluded) -> ThreadTaskTimings {
695    THREAD_TIMINGS.with(|timings| timings.lock().get_thread_task_timings(include_running))
696}
697
698const TRACE_SETTING_ENABLED: u64 = 1 << 63;
699const TRACE_SCOPE_COUNT_MASK: u64 = TRACE_SETTING_ENABLED - 1;
700static TRACE_STATE: AtomicU64 = AtomicU64::new(0);
701
702/// Enables or disables profiler trace collection at runtime.
703///
704/// When transitioning from enabled to disabled, `add_task_timing` becomes
705/// cheaper since only cheap statistics are gathered. The existing per-thread
706/// task buffers and the frame-event buffer are cleared so stale data isn't
707/// reported after a later re-enable. Active trace scopes keep collection enabled
708/// until the last scope ends. Calls with the current setting are a no-op.
709pub fn set_trace_enabled(enabled: bool) -> bool {
710    let mut state = TRACE_STATE.load(Ordering::Acquire);
711    loop {
712        let was_enabled = state & TRACE_SETTING_ENABLED != 0;
713        if was_enabled == enabled {
714            return false;
715        }
716
717        let next_state = if enabled {
718            state | TRACE_SETTING_ENABLED
719        } else {
720            state & TRACE_SCOPE_COUNT_MASK
721        };
722        match TRACE_STATE.compare_exchange_weak(
723            state,
724            next_state,
725            Ordering::AcqRel,
726            Ordering::Acquire,
727        ) {
728            Ok(_) => {
729                if next_state == 0 {
730                    clear_trace_buffers();
731                }
732                return true;
733            }
734            Err(updated_state) => state = updated_state,
735        }
736    }
737}
738
739#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
740pub(crate) struct TraceGuard;
741
742#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
743pub(crate) fn trace_scope() -> TraceGuard {
744    let incremented = TRACE_STATE.fetch_update(Ordering::AcqRel, Ordering::Acquire, |state| {
745        (state & TRACE_SCOPE_COUNT_MASK < TRACE_SCOPE_COUNT_MASK).then_some(state + 1)
746    });
747    assert!(incremented.is_ok(), "too many active profiler trace scopes");
748    TraceGuard
749}
750
751#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
752impl Drop for TraceGuard {
753    fn drop(&mut self) {
754        let previous_state =
755            TRACE_STATE.fetch_update(Ordering::AcqRel, Ordering::Acquire, |state| {
756                (state & TRACE_SCOPE_COUNT_MASK > 0).then_some(state - 1)
757            });
758        match previous_state {
759            Ok(1) => clear_trace_buffers(),
760            Ok(_) => {}
761            Err(_) => debug_assert!(false, "profiler trace scope count underflowed"),
762        }
763    }
764}
765
766/// Returns whether profiler trace collection is enabled.
767pub fn trace_enabled() -> bool {
768    TRACE_STATE.load(Ordering::Relaxed) != 0
769}
770
771fn clear_trace_buffers() {
772    for (_, timings) in upgraded_thread_timings() {
773        let mut timings = timings.lock();
774        timings.timings.clear();
775        timings.timings.shrink_to_fit();
776        timings.total_pushed = 0;
777    }
778    #[cfg(feature = "profiler")]
779    {
780        let mut frames = FRAME_TIMINGS.lock();
781        frames.timings.clear();
782        frames.timings.shrink_to_fit();
783        frames.total_pushed = 0;
784    }
785}
786
787/// Timing for a single drawn window frame.
788#[cfg(feature = "profiler")]
789#[derive(Debug, Copy, Clone)]
790pub struct FrameTiming {
791    /// The window that was drawn.
792    pub window_id: WindowId,
793    /// When the frame first became dirty (its first invalidation). `None` if
794    /// profiler tracing was not yet enabled when the invalidation occurred.
795    pub dirty_at: Option<Instant>,
796    /// Number of invalidations coalesced into this frame.
797    pub invalidations: u64,
798    /// When `Window::draw` started.
799    pub draw_start: Instant,
800    /// When `Window::draw` finished.
801    pub draw_end: Instant,
802    /// The refresh interval of the window's display when the frame was drawn,
803    /// or `None` when the platform doesn't report it.
804    pub refresh_interval: Option<Duration>,
805    /// When the platform's frame signal for this frame fired, or `None` when
806    /// the platform doesn't report it. Coalesced signals report the first.
807    pub signal_at: Option<Instant>,
808    /// How long each phase of the draw took.
809    pub phases: DrawPhases,
810}
811
812/// How long each phase of a window draw took.
813#[cfg(feature = "profiler")]
814#[derive(Debug, Copy, Clone, Default, PartialEq, Eq)]
815pub struct DrawPhases {
816    /// Rendering views into elements and requesting their layout.
817    pub request_layout: Duration,
818    /// Computing layout and prepainting elements, including deferred draws,
819    /// prompts, drags, and tooltips.
820    pub prepaint: Duration,
821    /// Painting elements into the scene.
822    pub paint: Duration,
823}
824
825/// A phase of drawing a view.
826#[cfg(feature = "profiler")]
827#[derive(Debug, Copy, Clone, PartialEq, Eq)]
828pub enum ViewPhase {
829    /// Rendering the view and requesting its layout.
830    RequestLayout,
831    /// Prepainting the view's elements. Views whose cached elements are
832    /// stale also render and lay out here.
833    Prepaint,
834    /// Painting the view's elements.
835    Paint,
836}
837
838#[cfg(feature = "profiler")]
839impl ViewPhase {
840    /// The phase's name, e.g. `"prepaint"`.
841    pub fn as_str(self) -> &'static str {
842        match self {
843            Self::RequestLayout => "request_layout",
844            Self::Prepaint => "prepaint",
845            Self::Paint => "paint",
846        }
847    }
848}
849
850/// Views whose own work in one draw phase takes less than this aren't
851/// recorded, keeping the journal's per-frame cost bounded while still naming
852/// the views that make a frame late.
853#[cfg(feature = "profiler")]
854pub const VIEW_TIMING_FLOOR: Duration = Duration::from_micros(500);
855
856/// One phase of drawing one view, recorded when its own work took at least
857/// [`VIEW_TIMING_FLOOR`].
858#[cfg(feature = "profiler")]
859#[derive(Debug, Copy, Clone)]
860pub struct ViewTiming {
861    /// The view's type name.
862    pub name: &'static str,
863    /// The draw phase.
864    pub phase: ViewPhase,
865    /// When the view's phase began.
866    pub start: Instant,
867    /// When the view's phase ended.
868    pub end: Instant,
869    /// The phase's duration excluding views nested inside it, so a parent
870    /// view isn't blamed for its children's work.
871    pub self_duration: Duration,
872}
873
874/// The least work a frame can take before it counts as late: one refresh
875/// at 120 Hz. Frames rarely fit a single refresh on faster displays yet, so
876/// judging them by it would count nearly every frame as late and hide
877/// regressions; missed refreshes still measure against the real interval.
878#[cfg(feature = "profiler")]
879pub const FRAME_BUDGET_FLOOR: Duration = Duration::from_nanos(8_333_333);
880
881/// The work a frame can take before it counts as late when its display's
882/// refresh interval is unknown: one refresh at 60 Hz, the most common rate,
883/// so frames on faster displays may be judged leniently but none too strictly.
884#[cfg(feature = "profiler")]
885pub const UNKNOWN_REFRESH_FRAME_BUDGET: Duration = Duration::from_nanos(16_666_667);
886
887#[cfg(feature = "profiler")]
888impl FrameTiming {
889    /// When the frame's work began: the later of its signal and its first
890    /// invalidation, since waiting for the platform's frame signal isn't work,
891    /// however late it fires. `None` without a frame signal.
892    pub fn work_start(&self) -> Option<Instant> {
893        let signal_at = self.signal_at?;
894        // A frame signal can fire while the main thread is busy and only be
895        // handled after the window became dirty; time before then isn't the
896        // frame's.
897        Some(
898            self.dirty_at
899                .map_or(signal_at, |dirty_at| dirty_at.max(signal_at)),
900        )
901    }
902
903    /// The main-thread time from [`FrameTiming::work_start`] until the frame
904    /// was submitted at `submitted_at`: the start of its submission, which may
905    /// consist mostly of waiting for the display to free a buffer.
906    pub fn work(&self, submitted_at: Instant) -> Option<Duration> {
907        Some(submitted_at.saturating_duration_since(self.work_start()?))
908    }
909
910    /// Whether the frame's work, submitted at `submitted_at`, exceeded
911    /// [`FrameTiming::budget`], when its work is known.
912    pub fn is_late(&self, submitted_at: Instant) -> Option<bool> {
913        Some(self.work(submitted_at)? > self.budget())
914    }
915
916    /// The work a frame can take before it counts as late: one refresh
917    /// interval, but no less than [`FRAME_BUDGET_FLOOR`], or
918    /// [`UNKNOWN_REFRESH_FRAME_BUDGET`] when the interval is unknown.
919    pub fn budget(&self) -> Duration {
920        self.refresh_interval
921            .map_or(UNKNOWN_REFRESH_FRAME_BUDGET, |interval| {
922                interval.max(FRAME_BUDGET_FLOOR)
923            })
924    }
925
926    /// How many refreshes the frame missed when submitted at `submitted_at`:
927    /// zero when its work fit within one refresh interval.
928    pub fn missed_refreshes(&self, submitted_at: Instant) -> Option<u64> {
929        let refresh_interval = self.refresh_interval?;
930        let work = self.work(submitted_at)?;
931        let refreshes = work.as_nanos().div_ceil(refresh_interval.as_nanos()).max(1);
932        Some(u64::try_from(refreshes - 1).unwrap_or(u64::MAX))
933    }
934
935    /// Time spent inside `Window::draw`.
936    pub fn draw_duration(&self) -> Duration {
937        self.draw_end.duration_since(self.draw_start)
938    }
939
940    /// Time from the frame's first invalidation to the end of its draw, if the
941    /// first invalidation was observed.
942    pub fn dirty_to_draw_duration(&self) -> Option<Duration> {
943        self.dirty_at
944            .map(|dirty_at| self.draw_end.duration_since(dirty_at))
945    }
946}
947
948/// Work spent submitting a window frame to the platform.
949#[cfg(feature = "profiler")]
950#[derive(Debug, Copy, Clone)]
951pub struct PresentTiming {
952    /// The window whose frame was submitted.
953    pub window_id: WindowId,
954    /// When the platform submission began.
955    pub present_start: Instant,
956    /// When the platform submission completed.
957    pub present_end: Instant,
958    /// The interval since the previous newly drawn frame was submitted, when
959    /// both frames belong to an active animation.
960    pub animation_interval: Option<Duration>,
961}
962
963#[cfg(feature = "profiler")]
964impl PresentTiming {
965    /// Time spent submitting the frame to the platform.
966    pub fn present_duration(&self) -> Duration {
967        self.present_end.duration_since(self.present_start)
968    }
969}
970
971/// A frame event observed by the profiler.
972#[cfg(feature = "profiler")]
973#[derive(Debug, Copy, Clone)]
974pub enum FrameEvent {
975    /// A window frame was drawn.
976    Draw(FrameTiming),
977    /// A newly drawn window frame was presented.
978    Present(PresentTiming),
979}
980
981/// A point-in-time snapshot of the frame-duration histograms for a window,
982/// suitable for external formatting.
983#[cfg(feature = "profiler")]
984#[derive(Clone)]
985pub struct FrameDurationSnapshot {
986    /// Histogram of durations from the first invalidation through presentation, in nanoseconds.
987    pub dirty_to_present_histogram: Histogram<u64>,
988    /// Histogram of `Window::draw` durations, in nanoseconds.
989    pub draw_duration_histogram: Histogram<u64>,
990    /// Histogram of intervals between consecutively presented frames while the
991    /// window was animating, in nanoseconds.
992    pub present_interval_histogram: Histogram<u64>,
993    /// The same frames, split by the refresh interval of the window's display
994    /// when they were drawn.
995    pub by_refresh_interval: Vec<RefreshIntervalFrames>,
996}
997
998/// Upper bounds, in milliseconds, of the duration buckets in
999/// [`RefreshIntervalFrames`]. Each bucket counts values up to and including its
1000/// bound; a final bucket counts everything longer.
1001#[cfg(feature = "profiler")]
1002pub const FRAME_DURATION_BUCKETS_MS: [u64; 9] = [4, 8, 16, 33, 50, 100, 250, 500, 1000];
1003
1004/// Upper bounds, in percent of the display's real refresh interval, of the
1005/// work-per-frame buckets in [`RefreshIntervalFrames`]. Each bucket counts
1006/// values up to and including its bound; a final bucket counts everything
1007/// more. Whether a frame was on time is judged by [`FrameTiming::budget`]
1008/// instead, which never drops below [`FRAME_BUDGET_FLOOR`], so on displays
1009/// faster than 120 Hz frames above 100% can still be on time.
1010#[cfg(feature = "profiler")]
1011pub const FRAME_WORK_BUCKETS_PERCENT: [u64; 7] = [25, 50, 75, 100, 150, 200, 400];
1012
1013/// Counts `histogram`'s values above the previous bound and up to and
1014/// including each of `upper_bounds`, plus a final count of the values above
1015/// the last bound.
1016#[cfg(feature = "profiler")]
1017pub fn histogram_bucket_counts(
1018    histogram: &Histogram<u64>,
1019    upper_bounds: impl IntoIterator<Item = u64>,
1020) -> Vec<u64> {
1021    let mut counted = 0;
1022    let mut counts: Vec<u64> = upper_bounds
1023        .into_iter()
1024        .map(|bound| {
1025            // Cumulative counts, since adjacent bounds can share a histogram
1026            // bucket.
1027            let cumulative = histogram.count_between(0, bound);
1028            let count = cumulative.saturating_sub(counted);
1029            counted = counted.max(cumulative);
1030            count
1031        })
1032        .collect();
1033    counts.push(histogram.len().saturating_sub(counted));
1034    counts
1035}
1036
1037/// Statistics for the frames a window drew and presented while its display had
1038/// one refresh interval.
1039///
1040/// A frame is on time when its [`FrameTiming::work`] fit within
1041/// [`FrameTiming::budget`].
1042#[cfg(feature = "profiler")]
1043#[derive(Clone, Debug)]
1044pub struct RefreshIntervalFrames {
1045    /// The display's refresh interval, or `None` when the platform doesn't
1046    /// report it. Frame pacing is only measured for known intervals.
1047    pub refresh_interval: Option<Duration>,
1048    /// Frames drawn, whether or not they were presented.
1049    pub frames_drawn: u64,
1050    /// Draw durations, in nanoseconds.
1051    pub draw_duration: Histogram<u64>,
1052    /// Presented frames whose work fit within [`FrameTiming::budget`].
1053    pub frames_on_time: u64,
1054    /// Presented frames whose work exceeded [`FrameTiming::budget`].
1055    pub frames_late: u64,
1056    /// Refreshes that on-time and late frames missed in total, when the
1057    /// refresh interval is known.
1058    pub missed_refreshes: u64,
1059    /// Presented frames without a frame signal to measure their work from.
1060    pub frames_unmeasured: u64,
1061    /// Work of on-time and late frames, in nanoseconds.
1062    pub work: Histogram<u64>,
1063    /// Of `frames_on_time`, the frames that responded to input.
1064    pub input_frames_on_time: u64,
1065    /// Of `frames_late`, the frames that responded to input.
1066    pub input_frames_late: u64,
1067    /// Work of on-time and late frames that responded to input, in
1068    /// nanoseconds.
1069    pub input_work: Histogram<u64>,
1070}
1071
1072#[cfg(feature = "profiler")]
1073impl RefreshIntervalFrames {
1074    fn new(refresh_interval: Option<Duration>, empty_histogram: &Histogram<u64>) -> Self {
1075        Self {
1076            refresh_interval,
1077            frames_drawn: 0,
1078            draw_duration: empty_histogram.clone(),
1079            frames_on_time: 0,
1080            frames_late: 0,
1081            missed_refreshes: 0,
1082            frames_unmeasured: 0,
1083            work: empty_histogram.clone(),
1084            input_frames_on_time: 0,
1085            input_frames_late: 0,
1086            input_work: empty_histogram.clone(),
1087        }
1088    }
1089
1090    /// The frames recorded since `earlier`, a previous snapshot of the same
1091    /// statistics.
1092    pub fn since(&self, earlier: &Self) -> Self {
1093        let subtract = |current: &Histogram<u64>, earlier: &Histogram<u64>| {
1094            let mut delta = current.clone();
1095            match delta.subtract(earlier) {
1096                Ok(()) => delta,
1097                Err(error) => {
1098                    log::error!("failed to subtract frame histograms: {error}");
1099                    current.clone()
1100                }
1101            }
1102        };
1103        Self {
1104            refresh_interval: self.refresh_interval,
1105            frames_drawn: self.frames_drawn.saturating_sub(earlier.frames_drawn),
1106            draw_duration: subtract(&self.draw_duration, &earlier.draw_duration),
1107            frames_on_time: self.frames_on_time.saturating_sub(earlier.frames_on_time),
1108            frames_late: self.frames_late.saturating_sub(earlier.frames_late),
1109            missed_refreshes: self
1110                .missed_refreshes
1111                .saturating_sub(earlier.missed_refreshes),
1112            frames_unmeasured: self
1113                .frames_unmeasured
1114                .saturating_sub(earlier.frames_unmeasured),
1115            work: subtract(&self.work, &earlier.work),
1116            input_frames_on_time: self
1117                .input_frames_on_time
1118                .saturating_sub(earlier.input_frames_on_time),
1119            input_frames_late: self
1120                .input_frames_late
1121                .saturating_sub(earlier.input_frames_late),
1122            input_work: subtract(&self.input_work, &earlier.input_work),
1123        }
1124    }
1125
1126    fn record_presented_frame(
1127        &mut self,
1128        frame: &FrameTiming,
1129        presentation: &PresentTiming,
1130        responded_to_input: bool,
1131    ) {
1132        let submitted_at = presentation.present_start;
1133        let (Some(work), Some(is_late)) = (frame.work(submitted_at), frame.is_late(submitted_at))
1134        else {
1135            self.frames_unmeasured += 1;
1136            return;
1137        };
1138        record_duration(&mut self.work, work);
1139        if responded_to_input {
1140            record_duration(&mut self.input_work, work);
1141        }
1142        self.missed_refreshes += frame.missed_refreshes(submitted_at).unwrap_or(0);
1143        if is_late {
1144            self.frames_late += 1;
1145            self.input_frames_late += u64::from(responded_to_input);
1146        } else {
1147            self.frames_on_time += 1;
1148            self.input_frames_on_time += u64::from(responded_to_input);
1149        }
1150    }
1151}
1152
1153/// Records `duration` in nanoseconds, growing the histogram as needed.
1154#[cfg(feature = "profiler")]
1155fn record_duration(histogram: &mut Histogram<u64>, duration: Duration) {
1156    let nanos = u64::try_from(duration.as_nanos()).unwrap_or(u64::MAX);
1157    if let Err(error) = histogram.record(nanos) {
1158        log::error!("failed to record frame duration: {error}");
1159    }
1160}
1161
1162/// A point-in-time snapshot of the input-latency histograms for a window,
1163/// suitable for external formatting.
1164#[cfg(feature = "profiler")]
1165#[derive(Clone)]
1166pub struct InputLatencySnapshot {
1167    /// Histogram of input-to-frame latency samples, in nanoseconds.
1168    pub latency_histogram: Histogram<u64>,
1169    /// Histogram of input events coalesced per rendered frame.
1170    pub events_per_frame_histogram: Histogram<u64>,
1171    /// Count of input events that arrived mid-draw and were excluded from
1172    /// latency recording.
1173    pub mid_draw_events_dropped: u64,
1174}
1175
1176#[cfg(feature = "profiler")]
1177enum WindowActivity {
1178    Input {
1179        started_at: Instant,
1180        kind: &'static str,
1181    },
1182    Draw {
1183        started_at: Instant,
1184    },
1185}
1186
1187/// Collects profiling information for one window.
1188///
1189/// Aggregate histograms are always populated when the `profiler` feature is
1190/// compiled in. Individual draw and present events are added to the global
1191/// profiler buffer only while tracing is enabled.
1192#[cfg(feature = "profiler")]
1193pub struct WindowProfiler {
1194    window_id: WindowId,
1195    active_activities: SmallVec<[WindowActivity; 4]>,
1196    active_actions: SmallVec<[(&'static str, Instant); 2]>,
1197    dirty_to_present_histogram: Histogram<u64>,
1198    draw_duration_histogram: Histogram<u64>,
1199    present_interval_histogram: Histogram<u64>,
1200    first_input_at: Option<Instant>,
1201    pending_input_count: u64,
1202    input_latency_histogram: Histogram<u64>,
1203    events_per_frame_histogram: Histogram<u64>,
1204    mid_draw_events_dropped: u64,
1205    last_present_at: Option<Instant>,
1206    animating_at_last_present: bool,
1207    pending_frame: Option<FrameTiming>,
1208    refresh_interval: Option<Duration>,
1209    frame_signal_at: Option<Instant>,
1210    by_refresh_interval: Vec<RefreshIntervalFrames>,
1211    /// Cloned for each new refresh interval's histograms, since creating one
1212    /// can fail.
1213    empty_histogram: Histogram<u64>,
1214    draw_phases: DrawPhases,
1215    /// For each view phase in progress, the time spent in views nested
1216    /// inside it so far.
1217    nested_view_time: SmallVec<[Duration; 16]>,
1218}
1219
1220#[cfg(feature = "profiler")]
1221impl WindowProfiler {
1222    /// Creates a profiler for a window.
1223    pub fn new(window_id: WindowId) -> anyhow::Result<Self> {
1224        let profiler = Self {
1225            window_id,
1226            active_activities: SmallVec::new(),
1227            active_actions: SmallVec::new(),
1228            dirty_to_present_histogram: Histogram::new(3).map_err(|error| {
1229                anyhow::anyhow!("Failed to create dirty-to-present histogram: {error}")
1230            })?,
1231            draw_duration_histogram: Histogram::new(3).map_err(|error| {
1232                anyhow::anyhow!("Failed to create draw duration histogram: {error}")
1233            })?,
1234            present_interval_histogram: Histogram::new(3).map_err(|error| {
1235                anyhow::anyhow!("Failed to create present interval histogram: {error}")
1236            })?,
1237            first_input_at: None,
1238            pending_input_count: 0,
1239            input_latency_histogram: Histogram::new(3).map_err(|error| {
1240                anyhow::anyhow!("Failed to create input latency histogram: {error}")
1241            })?,
1242            events_per_frame_histogram: Histogram::new(3).map_err(|error| {
1243                anyhow::anyhow!("Failed to create events per frame histogram: {error}")
1244            })?,
1245            mid_draw_events_dropped: 0,
1246            last_present_at: None,
1247            animating_at_last_present: false,
1248            pending_frame: None,
1249            refresh_interval: None,
1250            frame_signal_at: None,
1251            by_refresh_interval: Vec::new(),
1252            empty_histogram: Histogram::new(3)
1253                .map_err(|error| anyhow::anyhow!("Failed to create frame histogram: {error}"))?,
1254            draw_phases: DrawPhases::default(),
1255            nested_view_time: SmallVec::new(),
1256        };
1257        journal::record_frame_pending(window_id, Instant::now());
1258        Ok(profiler)
1259    }
1260
1261    /// Records the beginning of an input dispatch. `kind` names the platform
1262    /// input variant being dispatched (see [`crate::PlatformInput::kind_name`]).
1263    pub fn begin_input(&mut self, kind: &'static str) {
1264        journal::begin_foreground_turn();
1265        self.active_activities.push(WindowActivity::Input {
1266            started_at: Instant::now(),
1267            kind,
1268        });
1269    }
1270
1271    /// Records the end of an input dispatch.
1272    pub fn end_input(&mut self, caused_invalidation: bool) {
1273        let Some(WindowActivity::Input { started_at, kind }) = self.active_activities.pop() else {
1274            debug_assert!(false, "input activity must be the current window activity");
1275            journal::end_foreground_turn();
1276            return;
1277        };
1278
1279        if !journal::power_interrupted_since(started_at) {
1280            journal::record_input(journal::InputTiming {
1281                kind,
1282                start: started_at,
1283                end: Instant::now(),
1284                caused_invalidation,
1285            });
1286        }
1287        journal::end_foreground_turn();
1288
1289        if !caused_invalidation || !journal::frame_sample_is_valid(self.window_id, started_at) {
1290            return;
1291        }
1292        if self
1293            .first_input_at
1294            .is_some_and(|at| !journal::frame_sample_is_valid(self.window_id, at))
1295        {
1296            self.first_input_at = None;
1297            self.pending_input_count = 0;
1298        }
1299
1300        let arrived_during_draw = self
1301            .active_activities
1302            .iter()
1303            .any(|activity| matches!(activity, WindowActivity::Draw { .. }));
1304        if arrived_during_draw {
1305            self.mid_draw_events_dropped += 1;
1306        } else {
1307            self.first_input_at.get_or_insert(started_at);
1308            self.pending_input_count += 1;
1309        }
1310    }
1311
1312    /// Records the beginning of an action handler.
1313    pub fn begin_action_handler(&mut self, action: &(dyn Action + 'static), cx: &mut App) {
1314        journal::begin_foreground_turn();
1315        let name = actions::update_running_action(action, cx);
1316        self.active_actions.push((name, Instant::now()));
1317    }
1318
1319    /// Records the end of the current action handler.
1320    pub fn end_action_handler(&mut self) {
1321        // Dual-write to the legacy aggregate store; its single global running
1322        // slot misbehaves when tests run actions concurrently, which is why
1323        // the journal entry is tracked here on the window instead.
1324        actions::save_action_timing();
1325        let Some((name, start)) = self.active_actions.pop() else {
1326            debug_assert!(false, "action handler must be begun before it ends");
1327            journal::end_foreground_turn();
1328            return;
1329        };
1330        if !journal::power_interrupted_since(start) {
1331            journal::record_action(ActionTiming {
1332                name,
1333                start,
1334                end: Instant::now(),
1335            });
1336        }
1337        journal::end_foreground_turn();
1338    }
1339
1340    /// Records when the frame signal for the frame the next draw will produce
1341    /// fired. Coalesced signals report the first.
1342    pub fn record_frame_signal(&mut self, signal_at: Option<Instant>) {
1343        self.frame_signal_at = signal_at;
1344    }
1345
1346    /// Sets the refresh interval of the window's display, which frames drawn
1347    /// from now on are attributed to.
1348    pub fn set_refresh_interval(&mut self, refresh_interval: Option<Duration>) {
1349        self.refresh_interval = refresh_interval;
1350    }
1351
1352    /// Records the beginning of a window draw.
1353    pub fn begin_draw(&mut self) {
1354        journal::begin_foreground_turn();
1355        let started_at = Instant::now();
1356        journal::record_frame_pending(self.window_id, started_at);
1357        self.active_activities
1358            .push(WindowActivity::Draw { started_at });
1359    }
1360
1361    /// Records the phases of the window draw in progress.
1362    pub fn record_draw_phases(&mut self, phases: DrawPhases) {
1363        self.draw_phases = phases;
1364    }
1365
1366    /// Records the start of one phase of drawing a view, returning its start
1367    /// time to pass to [`WindowProfiler::end_view`].
1368    pub fn begin_view(&mut self) -> Instant {
1369        self.nested_view_time.push(Duration::ZERO);
1370        Instant::now()
1371    }
1372
1373    /// Records the end of a view phase begun at `start`, journaling it when
1374    /// its own work reached [`VIEW_TIMING_FLOOR`].
1375    pub fn end_view(&mut self, start: Instant, name: &'static str, phase: ViewPhase) {
1376        let end = Instant::now();
1377        let duration = end.saturating_duration_since(start);
1378        let nested = self.nested_view_time.pop().unwrap_or_default();
1379        if let Some(parent_nested) = self.nested_view_time.last_mut() {
1380            *parent_nested += duration;
1381        }
1382        let self_duration = duration.saturating_sub(nested);
1383        if self_duration >= VIEW_TIMING_FLOOR {
1384            journal::record_view(ViewTiming {
1385                name,
1386                phase,
1387                start,
1388                end,
1389                self_duration,
1390            });
1391        }
1392    }
1393
1394    /// Records the end of a window draw and returns the draw duration.
1395    pub fn end_draw(&mut self, dirty_at: Option<Instant>, invalidations: u64) -> Duration {
1396        let Some(WindowActivity::Draw {
1397            started_at: draw_start,
1398        }) = self.active_activities.pop()
1399        else {
1400            debug_assert!(false, "draw activity must be the current window activity");
1401            journal::end_foreground_turn();
1402            return Duration::ZERO;
1403        };
1404
1405        let draw_end = Instant::now();
1406        // Taken even when the draw isn't recorded, so a later draw can't claim it.
1407        let signal_at = self.frame_signal_at.take();
1408        let dirty_at = dirty_at.filter(|at| journal::frame_sample_is_valid(self.window_id, *at));
1409        let frame_timing = FrameTiming {
1410            window_id: self.window_id,
1411            dirty_at,
1412            invalidations,
1413            draw_start,
1414            draw_end,
1415            refresh_interval: self.refresh_interval,
1416            signal_at,
1417            phases: std::mem::take(&mut self.draw_phases),
1418        };
1419        let draw_duration = frame_timing.draw_duration();
1420        if !journal::power_interrupted_since(draw_start) {
1421            self.record_draw_timing(frame_timing);
1422        }
1423        journal::end_foreground_turn();
1424        draw_duration
1425    }
1426
1427    /// Records that a frame was presented.
1428    ///
1429    /// `next_frame_scheduled` marks the animation state for the interval
1430    /// ending at the next newly drawn frame's presentation.
1431    pub fn record_present(
1432        &mut self,
1433        present_start: Instant,
1434        present_end: Instant,
1435        window_active: bool,
1436        next_frame_scheduled: bool,
1437    ) {
1438        self.record_present_at(
1439            present_start,
1440            present_end,
1441            window_active,
1442            next_frame_scheduled,
1443        );
1444    }
1445
1446    /// Returns a snapshot of the current input-latency histograms.
1447    pub fn input_latency_snapshot(&self) -> InputLatencySnapshot {
1448        InputLatencySnapshot {
1449            latency_histogram: self.input_latency_histogram.clone(),
1450            events_per_frame_histogram: self.events_per_frame_histogram.clone(),
1451            mid_draw_events_dropped: self.mid_draw_events_dropped,
1452        }
1453    }
1454
1455    /// Returns a snapshot of the current frame-duration histograms.
1456    pub fn frame_duration_snapshot(&self) -> FrameDurationSnapshot {
1457        FrameDurationSnapshot {
1458            dirty_to_present_histogram: self.dirty_to_present_histogram.clone(),
1459            draw_duration_histogram: self.draw_duration_histogram.clone(),
1460            present_interval_histogram: self.present_interval_histogram.clone(),
1461            by_refresh_interval: self.by_refresh_interval.clone(),
1462        }
1463    }
1464
1465    fn frames_for(&mut self, refresh_interval: Option<Duration>) -> &mut RefreshIntervalFrames {
1466        let index = match self
1467            .by_refresh_interval
1468            .iter()
1469            .position(|frames| frames.refresh_interval == refresh_interval)
1470        {
1471            Some(index) => index,
1472            None => {
1473                self.by_refresh_interval.push(RefreshIntervalFrames::new(
1474                    refresh_interval,
1475                    &self.empty_histogram,
1476                ));
1477                self.by_refresh_interval.len() - 1
1478            }
1479        };
1480        &mut self.by_refresh_interval[index]
1481    }
1482
1483    fn record_present_at(
1484        &mut self,
1485        present_start: Instant,
1486        present_end: Instant,
1487        window_active: bool,
1488        next_frame_scheduled: bool,
1489    ) {
1490        let mut responded_to_input = false;
1491        if let Some(first_input_at) = self.first_input_at.take()
1492            && journal::frame_sample_is_valid(self.window_id, first_input_at)
1493        {
1494            responded_to_input = true;
1495            let latency_nanos = present_end.duration_since(first_input_at).as_nanos() as u64;
1496            self.input_latency_histogram.record(latency_nanos).ok();
1497            if self.pending_input_count > 0 {
1498                self.events_per_frame_histogram
1499                    .record(self.pending_input_count)
1500                    .ok();
1501            }
1502        }
1503        self.pending_input_count = 0;
1504
1505        let frame = self
1506            .pending_frame
1507            .take()
1508            .filter(|frame| journal::frame_sample_is_valid(self.window_id, frame.draw_start))
1509            .map(|mut frame| {
1510                frame.dirty_at = frame
1511                    .dirty_at
1512                    .filter(|at| journal::frame_sample_is_valid(self.window_id, *at));
1513                frame
1514            });
1515        let animation_interval =
1516            if frame.is_some() && self.animating_at_last_present && window_active {
1517                self.last_present_at
1518                    .filter(|at| journal::frame_sample_is_valid(self.window_id, *at))
1519                    .map(|last_present_at| present_end.duration_since(last_present_at))
1520            } else {
1521                None
1522            };
1523        let present_timing = PresentTiming {
1524            window_id: self.window_id,
1525            present_start,
1526            present_end,
1527            animation_interval,
1528        };
1529        journal::record_present(present_timing, frame);
1530
1531        let Some(frame) = frame else {
1532            return;
1533        };
1534        self.frames_for(frame.refresh_interval)
1535            .record_presented_frame(&frame, &present_timing, responded_to_input);
1536
1537        if let Some(dirty_at) = frame.dirty_at
1538            && let Err(error) = self
1539                .dirty_to_present_histogram
1540                .record(present_end.duration_since(dirty_at).as_nanos() as u64)
1541        {
1542            log::error!("failed to record dirty-to-present frame timing: {error}");
1543        }
1544
1545        if let Some(animation_interval) = animation_interval {
1546            self.present_interval_histogram
1547                .record(animation_interval.as_nanos() as u64)
1548                .ok();
1549        }
1550        record_frame_event(FrameEvent::Present(present_timing));
1551
1552        self.last_present_at = Some(present_end);
1553        self.animating_at_last_present = next_frame_scheduled && window_active;
1554    }
1555
1556    fn record_draw_timing(&mut self, timing: FrameTiming) {
1557        self.record_draw_duration(timing.draw_duration());
1558        let frames = self.frames_for(timing.refresh_interval);
1559        frames.frames_drawn += 1;
1560        record_duration(&mut frames.draw_duration, timing.draw_duration());
1561        self.pending_frame = Some(timing);
1562        record_frame_event(FrameEvent::Draw(timing));
1563        journal::record_draw(timing);
1564    }
1565
1566    fn record_draw_duration(&mut self, duration: Duration) {
1567        self.draw_duration_histogram
1568            .record(duration.as_nanos() as u64)
1569            .ok();
1570    }
1571}
1572
1573#[cfg(feature = "profiler")]
1574impl Drop for WindowProfiler {
1575    fn drop(&mut self) {
1576        journal::record_window_closed(self.window_id);
1577    }
1578}
1579
1580// Allow 16MiB of frame event entries.
1581#[cfg(feature = "profiler")]
1582const MAX_FRAME_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<FrameEvent>();
1583
1584#[cfg(feature = "profiler")]
1585struct FrameTimings {
1586    timings: VecDeque<FrameEvent>,
1587    total_pushed: u64,
1588}
1589
1590#[cfg(feature = "profiler")]
1591static FRAME_TIMINGS: spin::Mutex<FrameTimings> = spin::Mutex::new(FrameTimings {
1592    timings: VecDeque::new(),
1593    total_pushed: 0,
1594});
1595
1596/// Records a frame event.
1597///
1598/// No-op unless profiler tracing is enabled via [`set_trace_enabled`].
1599#[cfg(feature = "profiler")]
1600pub fn record_frame_event(event: FrameEvent) {
1601    if !trace_enabled() {
1602        return;
1603    }
1604    std::hint::cold_path(); // optimize for when profiling is off
1605
1606    let mut frames = FRAME_TIMINGS.lock();
1607    if frames.timings.len() >= MAX_FRAME_TIMINGS {
1608        frames.timings.pop_front();
1609    }
1610    frames.timings.push_back(event);
1611    frames.total_pushed += 1;
1612}
1613
1614/// Drains frame events recorded after this collector was created, tracking a
1615/// cursor so each call to [`Self::collect_unseen`] returns only new entries.
1616#[cfg(feature = "profiler")]
1617pub struct FrameTimingCollector {
1618    cursor: u64,
1619}
1620
1621#[cfg(feature = "profiler")]
1622impl Default for FrameTimingCollector {
1623    fn default() -> Self {
1624        Self::new()
1625    }
1626}
1627
1628#[cfg(feature = "profiler")]
1629impl FrameTimingCollector {
1630    /// Creates a collector that only sees frame events recorded from this point on.
1631    pub fn new() -> Self {
1632        Self {
1633            cursor: FRAME_TIMINGS.lock().total_pushed,
1634        }
1635    }
1636
1637    /// Returns frame events recorded since the previous call (or since the
1638    /// collector was created). If the ring buffer wrapped around since the
1639    /// previous poll, the evicted entries are lost.
1640    pub fn collect_unseen(&mut self) -> Vec<FrameEvent> {
1641        let frames = FRAME_TIMINGS.lock();
1642        let buffer_len = frames.timings.len() as u64;
1643        let buffer_start = frames.total_pushed.saturating_sub(buffer_len);
1644        let skip = self.cursor.saturating_sub(buffer_start) as usize;
1645        let unseen = frames
1646            .timings
1647            .iter()
1648            .skip(skip.min(frames.timings.len()))
1649            .copied()
1650            .collect();
1651        self.cursor = frames.total_pushed;
1652        unseen
1653    }
1654}
1655
1656#[cfg(all(test, feature = "profiler"))]
1657mod tests {
1658    use super::*;
1659    use std::sync::{Mutex, MutexGuard};
1660
1661    #[test]
1662    fn interruptions_drop_latency_samples_but_hiding_keeps_draw_work() {
1663        for sleep in [false, true] {
1664            let (_journal, _guard) = journal::install_test_foreground_journal(64, 4);
1665            let id = WindowId::from(1);
1666            let mut profiler = WindowProfiler::new(id).expect("valid histograms");
1667            let old = Instant::now() - Duration::from_secs(1);
1668            record_test_draw(&mut profiler, old);
1669            profiler.record_present_at(old, old, true, true);
1670            profiler.first_input_at = Some(old);
1671            profiler.pending_input_count = 1;
1672            profiler.begin_draw();
1673            if sleep {
1674                journal::record_power_transition(journal::PowerState::Suspended);
1675                journal::record_power_transition(journal::PowerState::Awake);
1676            } else {
1677                journal::record_window_visibility(id, crate::WindowVisibility::Hidden);
1678                journal::record_window_visibility(id, crate::WindowVisibility::Visible);
1679            }
1680            profiler.end_draw(Some(old), 1);
1681            let now = Instant::now();
1682            profiler.record_present_at(now, now, true, true);
1683            assert_eq!(
1684                profiler.draw_duration_histogram.len(),
1685                if sleep { 1 } else { 2 }
1686            );
1687            assert_eq!(profiler.input_latency_histogram.len(), 0);
1688            assert_eq!(profiler.dirty_to_present_histogram.len(), 1);
1689            assert_eq!(profiler.present_interval_histogram.len(), 0);
1690            profiler.begin_draw();
1691            profiler.end_draw(Some(Instant::now()), 1);
1692            let now = Instant::now();
1693            profiler.record_present_at(now, now, true, true);
1694            assert_eq!(profiler.dirty_to_present_histogram.len(), 2);
1695        }
1696    }
1697
1698    #[test]
1699    fn frame_work_starts_at_the_later_of_signal_and_invalidation() {
1700        let refresh = Duration::from_millis(10);
1701        let start = Instant::now();
1702        let at = |ms| start + Duration::from_millis(ms);
1703        let frame_with = |dirty: Option<u64>, signal: Option<u64>| FrameTiming {
1704            window_id: WindowId::from(1),
1705            dirty_at: dirty.map(at),
1706            invalidations: 1,
1707            draw_start: at(1),
1708            draw_end: at(2),
1709            refresh_interval: Some(refresh),
1710            signal_at: signal.map(at),
1711            phases: Default::default(),
1712        };
1713        let work = |dirty, signal| frame_with(dirty, signal).work(at(50));
1714
1715        // Waiting for the frame signal isn't work, however late it fires.
1716        assert_eq!(work(Some(0), Some(8)), Some(Duration::from_millis(42)));
1717        assert_eq!(work(Some(0), Some(40)), Some(Duration::from_millis(10)));
1718        // A frame needed after its signal fired is measured from when it was
1719        // needed.
1720        assert_eq!(work(Some(5), Some(0)), Some(Duration::from_millis(45)));
1721        // Animation frames have no invalidation to wait for.
1722        assert_eq!(work(None, Some(0)), Some(Duration::from_millis(50)));
1723        assert_eq!(work(Some(0), None), None);
1724
1725        let frame = frame_with(Some(0), Some(0));
1726        for (submitted_ms, missed) in [(7, 0), (10, 0), (20, 1), (25, 2)] {
1727            assert_eq!(frame.missed_refreshes(at(submitted_ms)), Some(missed));
1728        }
1729    }
1730
1731    #[test]
1732    fn frames_are_split_by_refresh_interval_and_classified() {
1733        let (_journal, _guard) = journal::install_test_foreground_journal(64, 4);
1734        let mut profiler = WindowProfiler::new(WindowId::from(1)).expect("valid histograms");
1735        let sixty_hertz = Duration::from_secs(1) / 60;
1736        let one_hundred_twenty_hertz = Duration::from_secs(1) / 120;
1737        let three_hundred_sixty_hertz = Duration::from_secs(1) / 360;
1738        let base = Instant::now();
1739        let at = |ms| base + Duration::from_millis(ms);
1740
1741        struct Frame {
1742            refresh_interval: Option<Duration>,
1743            signal_ms: Option<u64>,
1744            present_start_ms: u64,
1745            responded_to_input: bool,
1746        }
1747        let frames = [
1748            // On time, responding to input.
1749            Frame {
1750                refresh_interval: Some(sixty_hertz),
1751                signal_ms: Some(1),
1752                present_start_ms: 5,
1753                responded_to_input: true,
1754            },
1755            Frame {
1756                refresh_interval: Some(sixty_hertz),
1757                signal_ms: Some(0),
1758                present_start_ms: 40,
1759                responded_to_input: true,
1760            },
1761            Frame {
1762                refresh_interval: Some(sixty_hertz),
1763                signal_ms: None,
1764                present_start_ms: 5,
1765                responded_to_input: false,
1766            },
1767            // A late frame signal: only the 2 ms after it count.
1768            Frame {
1769                refresh_interval: Some(sixty_hertz),
1770                signal_ms: Some(40),
1771                present_start_ms: 42,
1772                responded_to_input: false,
1773            },
1774            Frame {
1775                refresh_interval: Some(one_hundred_twenty_hertz),
1776                signal_ms: Some(0),
1777                present_start_ms: 12,
1778                responded_to_input: false,
1779            },
1780            // Misses refreshes but fits the budget floor.
1781            Frame {
1782                refresh_interval: Some(three_hundred_sixty_hertz),
1783                signal_ms: Some(0),
1784                present_start_ms: 6,
1785                responded_to_input: false,
1786            },
1787            Frame {
1788                refresh_interval: Some(three_hundred_sixty_hertz),
1789                signal_ms: Some(0),
1790                present_start_ms: 9,
1791                responded_to_input: false,
1792            },
1793            Frame {
1794                refresh_interval: None,
1795                signal_ms: Some(0),
1796                present_start_ms: 2,
1797                responded_to_input: false,
1798            },
1799        ];
1800        for frame in frames {
1801            profiler.set_refresh_interval(frame.refresh_interval);
1802            profiler.record_draw_timing(FrameTiming {
1803                window_id: profiler.window_id,
1804                dirty_at: Some(at(0)),
1805                invalidations: 1,
1806                draw_start: at(0),
1807                draw_end: at(1),
1808                refresh_interval: frame.refresh_interval,
1809                signal_at: frame.signal_ms.map(at),
1810                phases: Default::default(),
1811            });
1812            if frame.responded_to_input {
1813                profiler.first_input_at = Some(at(0));
1814            }
1815            profiler.record_present_at(
1816                at(frame.present_start_ms),
1817                at(frame.present_start_ms + 1),
1818                true,
1819                false,
1820            );
1821        }
1822
1823        let snapshot = profiler.frame_duration_snapshot();
1824        let frames_for = |refresh_interval| {
1825            snapshot
1826                .by_refresh_interval
1827                .iter()
1828                .find(|frames| frames.refresh_interval == refresh_interval)
1829                .cloned()
1830                .expect("frames for the refresh interval")
1831        };
1832        let work_buckets = |work: &Histogram<u64>, refresh_interval: Duration| {
1833            histogram_bucket_counts(
1834                work,
1835                FRAME_WORK_BUCKETS_PERCENT
1836                    .map(|percent| (refresh_interval * percent as u32 / 100).as_nanos() as u64),
1837            )
1838        };
1839        let sixty = frames_for(Some(sixty_hertz));
1840        assert_eq!(sixty.frames_drawn, 4);
1841        assert_eq!(sixty.frames_on_time, 2);
1842        assert_eq!(sixty.frames_late, 1);
1843        // 40 ms of work at 16.7 ms per refresh.
1844        assert_eq!(sixty.missed_refreshes, 2);
1845        assert_eq!(sixty.frames_unmeasured, 1);
1846        assert_eq!(
1847            work_buckets(&sixty.work, sixty_hertz),
1848            [2, 0, 0, 0, 0, 0, 1, 0]
1849        );
1850        assert_eq!(sixty.input_frames_on_time, 1);
1851        assert_eq!(sixty.input_frames_late, 1);
1852        assert_eq!(
1853            work_buckets(&sixty.input_work, sixty_hertz),
1854            [1, 0, 0, 0, 0, 0, 1, 0]
1855        );
1856
1857        let one_hundred_twenty = frames_for(Some(one_hundred_twenty_hertz));
1858        assert_eq!(one_hundred_twenty.frames_late, 1);
1859        assert_eq!(one_hundred_twenty.missed_refreshes, 1);
1860        assert_eq!(one_hundred_twenty.input_frames_late, 0);
1861
1862        let three_hundred_sixty = frames_for(Some(three_hundred_sixty_hertz));
1863        assert_eq!(three_hundred_sixty.frames_on_time, 1);
1864        assert_eq!(three_hundred_sixty.frames_late, 1);
1865        // 6 ms of work misses 2 refreshes at 2.78 ms each, and 9 ms misses 3.
1866        assert_eq!(three_hundred_sixty.missed_refreshes, 5);
1867
1868        // Judged against the 60 Hz budget, without missed refreshes.
1869        let unknown = frames_for(None);
1870        assert_eq!(unknown.frames_drawn, 1);
1871        assert_eq!(unknown.frames_on_time, 1);
1872        assert_eq!(unknown.missed_refreshes, 0);
1873
1874        let later = profiler.frame_duration_snapshot();
1875        let delta = later.by_refresh_interval[0].since(&snapshot.by_refresh_interval[0]);
1876        assert_eq!(
1877            delta.frames_drawn + delta.frames_on_time + delta.frames_late,
1878            0
1879        );
1880        assert_eq!(
1881            delta.draw_duration.len() + delta.work.len() + delta.input_work.len(),
1882            0
1883        );
1884    }
1885
1886    #[test]
1887    fn records_draw_events_only_while_tracing() {
1888        let _trace_test_guard = TraceTestGuard::new();
1889        let window_id = WindowId::from(0xD0A0);
1890        let mut window_profiler =
1891            WindowProfiler::new(window_id).expect("window profiler should initialize");
1892        let dirty_at = Instant::now();
1893        let mut collector = FrameTimingCollector::new();
1894
1895        window_profiler.begin_draw();
1896        window_profiler.end_draw(Some(dirty_at), 3);
1897        assert!(
1898            collector
1899                .collect_unseen()
1900                .iter()
1901                .all(|event| !event_matches_window(*event, window_id))
1902        );
1903
1904        set_trace_enabled(true);
1905        let mut collector = FrameTimingCollector::new();
1906        window_profiler.begin_draw();
1907        window_profiler.end_draw(Some(dirty_at), 3);
1908
1909        let timing = collector
1910            .collect_unseen()
1911            .into_iter()
1912            .find_map(|event| match event {
1913                FrameEvent::Draw(timing) if timing.window_id == window_id => Some(timing),
1914                _ => None,
1915            })
1916            .expect("draw event should be recorded while tracing");
1917        assert_eq!(timing.dirty_at, Some(dirty_at));
1918        assert_eq!(timing.invalidations, 3);
1919        assert!(timing.draw_start >= dirty_at);
1920    }
1921
1922    #[test]
1923    fn records_present_events_for_newly_drawn_frames() {
1924        let _trace_test_guard = TraceTestGuard::new();
1925        set_trace_enabled(true);
1926        let window_id = WindowId::from(0xA11E);
1927        let mut window_profiler =
1928            WindowProfiler::new(window_id).expect("window profiler should initialize");
1929        let start = Instant::now();
1930        let mut collector = FrameTimingCollector::new();
1931
1932        record_test_draw(&mut window_profiler, start);
1933        window_profiler.record_present_at(start, start, true, true);
1934        record_test_draw(&mut window_profiler, start + FRAME);
1935        window_profiler.record_present_at(start + FRAME, start + FRAME, true, true);
1936        window_profiler.record_present_at(
1937            start + FRAME + FRAME / 2,
1938            start + FRAME + FRAME / 2,
1939            true,
1940            true,
1941        );
1942
1943        let present_timings = collector
1944            .collect_unseen()
1945            .into_iter()
1946            .filter_map(|event| match event {
1947                FrameEvent::Present(timing) if timing.window_id == window_id => Some(timing),
1948                _ => None,
1949            })
1950            .collect::<Vec<_>>();
1951        let [first_present, second_present] = present_timings.as_slice() else {
1952            panic!("expected exactly two present events, got {present_timings:?}");
1953        };
1954        assert_eq!(first_present.animation_interval, None);
1955        assert_eq!(second_present.animation_interval, Some(FRAME));
1956
1957        #[cfg(feature = "profiler")]
1958        {
1959            assert_eq!(window_profiler.present_interval_histogram.len(), 1);
1960            assert!(
1961                window_profiler.present_interval_histogram.max()
1962                    >= second_present
1963                        .animation_interval
1964                        .expect("second present should have an animation interval")
1965                        .as_nanos() as u64
1966            );
1967        }
1968    }
1969
1970    #[test]
1971    fn disabling_tracing_clears_frame_events() {
1972        let _trace_test_guard = TraceTestGuard::new();
1973        set_trace_enabled(true);
1974        let window_id = WindowId::from(0xC1EA);
1975        let mut window_profiler =
1976            WindowProfiler::new(window_id).expect("window profiler should initialize");
1977        let mut collector = FrameTimingCollector::new();
1978
1979        window_profiler.begin_draw();
1980        window_profiler.end_draw(None, 0);
1981        assert!(
1982            FRAME_TIMINGS
1983                .lock()
1984                .timings
1985                .iter()
1986                .copied()
1987                .any(|event| event_matches_window(event, window_id))
1988        );
1989
1990        set_trace_enabled(false);
1991        assert!(
1992            collector
1993                .collect_unseen()
1994                .iter()
1995                .all(|event| !event_matches_window(*event, window_id))
1996        );
1997    }
1998
1999    #[cfg(feature = "profiler")]
2000    #[test]
2001    fn records_intervals_only_between_animation_frames() {
2002        let mut window_profiler =
2003            WindowProfiler::new(WindowId::from(1)).expect("window profiler should initialize");
2004        let start = Instant::now();
2005
2006        draw_and_present(&mut window_profiler, start, true, true);
2007        assert_eq!(window_profiler.present_interval_histogram.len(), 0);
2008
2009        draw_and_present(&mut window_profiler, start + FRAME, true, true);
2010        assert_eq!(window_profiler.present_interval_histogram.len(), 1);
2011
2012        draw_and_present(&mut window_profiler, start + FRAME * 2, true, false);
2013        assert_eq!(window_profiler.present_interval_histogram.len(), 2);
2014
2015        draw_and_present(&mut window_profiler, start + FRAME * 100, true, true);
2016        assert_eq!(window_profiler.present_interval_histogram.len(), 2);
2017    }
2018
2019    #[cfg(feature = "profiler")]
2020    #[test]
2021    fn missed_frames_stretch_the_recorded_interval() {
2022        let mut window_profiler =
2023            WindowProfiler::new(WindowId::from(2)).expect("window profiler should initialize");
2024        let start = Instant::now();
2025
2026        draw_and_present(&mut window_profiler, start, true, true);
2027        draw_and_present(&mut window_profiler, start + FRAME * 5, true, true);
2028
2029        let recorded = window_profiler.present_interval_histogram.max();
2030        assert!(recorded >= (FRAME * 4).as_nanos() as u64);
2031    }
2032
2033    #[cfg(feature = "profiler")]
2034    #[test]
2035    fn ignores_re_presents_of_unchanged_frames() {
2036        let mut window_profiler =
2037            WindowProfiler::new(WindowId::from(3)).expect("window profiler should initialize");
2038        let start = Instant::now();
2039
2040        draw_and_present(&mut window_profiler, start, true, true);
2041        window_profiler.record_present_at(start + FRAME / 2, start + FRAME / 2, true, true);
2042        draw_and_present(&mut window_profiler, start + FRAME, true, true);
2043
2044        assert_eq!(window_profiler.present_interval_histogram.len(), 1);
2045        assert!(
2046            window_profiler.present_interval_histogram.max() >= (FRAME * 3 / 4).as_nanos() as u64
2047        );
2048    }
2049
2050    #[cfg(feature = "profiler")]
2051    #[test]
2052    fn skips_intervals_for_inactive_windows() {
2053        let mut window_profiler =
2054            WindowProfiler::new(WindowId::from(4)).expect("window profiler should initialize");
2055        let start = Instant::now();
2056
2057        draw_and_present(&mut window_profiler, start, false, true);
2058        draw_and_present(&mut window_profiler, start + FRAME, false, true);
2059        assert_eq!(window_profiler.present_interval_histogram.len(), 0);
2060
2061        draw_and_present(&mut window_profiler, start + FRAME * 2, true, true);
2062        assert_eq!(window_profiler.present_interval_histogram.len(), 0);
2063
2064        draw_and_present(&mut window_profiler, start + FRAME * 3, true, true);
2065        assert_eq!(window_profiler.present_interval_histogram.len(), 1);
2066    }
2067
2068    #[test]
2069    fn records_dirty_to_present_durations() {
2070        let mut window_profiler =
2071            WindowProfiler::new(WindowId::from(8)).expect("window profiler should initialize");
2072        let draw_end = Instant::now();
2073        let present_end = draw_end + Duration::from_millis(6);
2074
2075        record_test_draw(&mut window_profiler, draw_end);
2076        window_profiler.record_present_at(present_end, present_end, true, false);
2077
2078        let snapshot = window_profiler.frame_duration_snapshot();
2079        let histogram = snapshot.dirty_to_present_histogram;
2080        assert_eq!(histogram.len(), 1);
2081        assert!(histogram.max() >= Duration::from_millis(10).as_nanos() as u64);
2082    }
2083
2084    #[cfg(feature = "profiler")]
2085    #[test]
2086    fn records_every_draw_duration() {
2087        let mut window_profiler =
2088            WindowProfiler::new(WindowId::from(5)).expect("window profiler should initialize");
2089
2090        window_profiler.record_draw_duration(Duration::from_millis(2));
2091        window_profiler.record_draw_duration(Duration::from_millis(40));
2092
2093        let snapshot = window_profiler.frame_duration_snapshot();
2094        assert_eq!(snapshot.draw_duration_histogram.len(), 2);
2095        assert!(snapshot.draw_duration_histogram.max() >= 39_000_000);
2096    }
2097
2098    #[test]
2099    fn records_input_latency_at_the_frame_presentation_timestamp() {
2100        let mut window_profiler =
2101            WindowProfiler::new(WindowId::from(6)).expect("window profiler should initialize");
2102        let first_input_at = Instant::now();
2103        let presented_at = first_input_at + Duration::from_millis(12);
2104
2105        begin_input_at(&mut window_profiler, first_input_at);
2106        window_profiler.end_input(true);
2107        begin_input_at(
2108            &mut window_profiler,
2109            first_input_at + Duration::from_millis(2),
2110        );
2111        window_profiler.end_input(true);
2112        record_test_draw(&mut window_profiler, presented_at);
2113        window_profiler.record_present_at(presented_at, presented_at, true, false);
2114
2115        let snapshot = window_profiler.input_latency_snapshot();
2116        assert_eq!(snapshot.latency_histogram.len(), 1);
2117        assert!(snapshot.latency_histogram.max() >= Duration::from_millis(12).as_nanos() as u64);
2118        assert_eq!(snapshot.events_per_frame_histogram.len(), 1);
2119        assert_eq!(snapshot.events_per_frame_histogram.max(), 2);
2120        assert_eq!(snapshot.mid_draw_events_dropped, 0);
2121    }
2122
2123    #[test]
2124    fn excludes_input_that_arrives_during_a_draw() {
2125        let mut window_profiler =
2126            WindowProfiler::new(WindowId::from(7)).expect("window profiler should initialize");
2127
2128        window_profiler.begin_draw();
2129        begin_input_at(&mut window_profiler, Instant::now());
2130        window_profiler.end_input(true);
2131        window_profiler.end_draw(None, 0);
2132
2133        let snapshot = window_profiler.input_latency_snapshot();
2134        assert!(snapshot.latency_histogram.is_empty());
2135        assert!(snapshot.events_per_frame_histogram.is_empty());
2136        assert_eq!(snapshot.mid_draw_events_dropped, 1);
2137    }
2138
2139    #[test]
2140    fn overlapping_trace_scopes_keep_tracing_enabled() {
2141        let _trace_test_guard = TraceTestGuard::new();
2142        let first_scope = trace_scope();
2143        let second_scope = trace_scope();
2144
2145        assert!(trace_enabled());
2146        drop(first_scope);
2147        assert!(trace_enabled());
2148        drop(second_scope);
2149        assert!(!trace_enabled());
2150    }
2151
2152    const FRAME: Duration = Duration::from_millis(16);
2153    static TRACE_TEST_LOCK: Mutex<()> = Mutex::new(());
2154
2155    struct TraceTestGuard {
2156        was_enabled: bool,
2157        _lock: MutexGuard<'static, ()>,
2158    }
2159
2160    impl TraceTestGuard {
2161        fn new() -> Self {
2162            let lock = TRACE_TEST_LOCK
2163                .lock()
2164                .unwrap_or_else(|poisoned| poisoned.into_inner());
2165            let was_enabled = trace_enabled();
2166            set_trace_enabled(false);
2167            Self {
2168                was_enabled,
2169                _lock: lock,
2170            }
2171        }
2172    }
2173
2174    impl Drop for TraceTestGuard {
2175        fn drop(&mut self) {
2176            set_trace_enabled(false);
2177            if self.was_enabled {
2178                set_trace_enabled(true);
2179            }
2180        }
2181    }
2182
2183    fn event_matches_window(event: FrameEvent, window_id: WindowId) -> bool {
2184        match event {
2185            FrameEvent::Draw(timing) => timing.window_id == window_id,
2186            FrameEvent::Present(timing) => timing.window_id == window_id,
2187        }
2188    }
2189
2190    fn begin_input_at(window_profiler: &mut WindowProfiler, started_at: Instant) {
2191        window_profiler
2192            .active_activities
2193            .push(WindowActivity::Input {
2194                started_at,
2195                kind: "test",
2196            });
2197    }
2198
2199    #[cfg(feature = "profiler")]
2200    fn draw_and_present(
2201        window_profiler: &mut WindowProfiler,
2202        presented_at: Instant,
2203        window_active: bool,
2204        next_frame_scheduled: bool,
2205    ) {
2206        record_test_draw(window_profiler, presented_at);
2207        window_profiler.record_present_at(
2208            presented_at,
2209            presented_at,
2210            window_active,
2211            next_frame_scheduled,
2212        );
2213    }
2214
2215    fn record_test_draw(window_profiler: &mut WindowProfiler, draw_end: Instant) {
2216        window_profiler.record_draw_timing(FrameTiming {
2217            window_id: window_profiler.window_id,
2218            dirty_at: Some(draw_end - Duration::from_millis(4)),
2219            invalidations: 1,
2220            draw_start: draw_end - Duration::from_millis(2),
2221            draw_end,
2222            refresh_interval: None,
2223            signal_at: None,
2224            phases: Default::default(),
2225        });
2226    }
2227}