Skip to main content

gpui_authoring/
profiler.rs

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