1#[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 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 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); 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#[derive(Debug, Clone, Serialize, Deserialize)]
230pub struct SerializedLocation {
231 pub file: SharedString,
233 pub line: u32,
235 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#[derive(Debug, Clone, Serialize, Deserialize)]
251pub struct SerializedTaskTiming {
252 pub location: SerializedLocation,
254 pub start: u128,
256 pub duration: u128,
258}
259
260impl SerializedTaskTiming {
261 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 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#[derive(Debug, Clone, Serialize, Deserialize)]
297pub struct SerializedThreadTaskTimings {
298 pub thread_name: Option<String>,
300 pub thread_id: u64,
302 pub timings: Vec<SerializedTaskTiming>,
304}
305
306impl SerializedThreadTaskTimings {
307 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 pub thread_id: u64,
332 pub thread_name: Option<String>,
334 pub new_timings: Vec<SerializedTaskTiming>,
337}
338
339#[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 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#[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 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(); 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(); 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
518fn 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(); 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 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
702pub 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.try_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 = TRACE_STATE.try_update(Ordering::AcqRel, Ordering::Acquire, |state| {
755 (state & TRACE_SCOPE_COUNT_MASK > 0).then_some(state - 1)
756 });
757 match previous_state {
758 Ok(1) => clear_trace_buffers(),
759 Ok(_) => {}
760 Err(_) => debug_assert!(false, "profiler trace scope count underflowed"),
761 }
762 }
763}
764
765pub fn trace_enabled() -> bool {
767 TRACE_STATE.load(Ordering::Relaxed) != 0
768}
769
770fn clear_trace_buffers() {
771 for (_, timings) in upgraded_thread_timings() {
772 let mut timings = timings.lock();
773 timings.timings.clear();
774 timings.timings.shrink_to_fit();
775 timings.total_pushed = 0;
776 }
777 #[cfg(feature = "profiler")]
778 {
779 let mut frames = FRAME_TIMINGS.lock();
780 frames.timings.clear();
781 frames.timings.shrink_to_fit();
782 frames.total_pushed = 0;
783 }
784}
785
786#[cfg(feature = "profiler")]
788#[derive(Debug, Copy, Clone)]
789pub struct FrameTiming {
790 pub window_id: WindowId,
792 pub dirty_at: Option<Instant>,
795 pub invalidations: u64,
797 pub draw_start: Instant,
799 pub draw_end: Instant,
801 pub refresh_interval: Option<Duration>,
804 pub signal_at: Option<Instant>,
807 pub phases: DrawPhases,
809}
810
811#[cfg(feature = "profiler")]
813#[derive(Debug, Copy, Clone, Default, PartialEq, Eq)]
814pub struct DrawPhases {
815 pub request_layout: Duration,
817 pub prepaint: Duration,
820 pub paint: Duration,
822}
823
824#[cfg(feature = "profiler")]
826#[derive(Debug, Copy, Clone, PartialEq, Eq)]
827pub enum ViewPhase {
828 RequestLayout,
830 Prepaint,
833 Paint,
835}
836
837#[cfg(feature = "profiler")]
838impl ViewPhase {
839 pub fn as_str(self) -> &'static str {
841 match self {
842 Self::RequestLayout => "request_layout",
843 Self::Prepaint => "prepaint",
844 Self::Paint => "paint",
845 }
846 }
847}
848
849#[cfg(feature = "profiler")]
853pub const VIEW_TIMING_FLOOR: Duration = Duration::from_micros(500);
854
855#[cfg(feature = "profiler")]
858#[derive(Debug, Copy, Clone)]
859pub struct ViewTiming {
860 pub name: &'static str,
862 pub phase: ViewPhase,
864 pub start: Instant,
866 pub end: Instant,
868 pub self_duration: Duration,
871}
872
873#[cfg(feature = "profiler")]
878pub const FRAME_BUDGET_FLOOR: Duration = Duration::from_nanos(8_333_333);
879
880#[cfg(feature = "profiler")]
884pub const UNKNOWN_REFRESH_FRAME_BUDGET: Duration = Duration::from_nanos(16_666_667);
885
886#[cfg(feature = "profiler")]
887impl FrameTiming {
888 pub fn work_start(&self) -> Option<Instant> {
892 let signal_at = self.signal_at?;
893 Some(
897 self.dirty_at
898 .map_or(signal_at, |dirty_at| dirty_at.max(signal_at)),
899 )
900 }
901
902 pub fn work(&self, submitted_at: Instant) -> Option<Duration> {
906 Some(submitted_at.saturating_duration_since(self.work_start()?))
907 }
908
909 pub fn is_late(&self, submitted_at: Instant) -> Option<bool> {
912 Some(self.work(submitted_at)? > self.budget())
913 }
914
915 pub fn budget(&self) -> Duration {
919 self.refresh_interval
920 .map_or(UNKNOWN_REFRESH_FRAME_BUDGET, |interval| {
921 interval.max(FRAME_BUDGET_FLOOR)
922 })
923 }
924
925 pub fn missed_refreshes(&self, submitted_at: Instant) -> Option<u64> {
928 let refresh_interval = self.refresh_interval?;
929 let work = self.work(submitted_at)?;
930 let refreshes = work.as_nanos().div_ceil(refresh_interval.as_nanos()).max(1);
931 Some(u64::try_from(refreshes - 1).unwrap_or(u64::MAX))
932 }
933
934 pub fn draw_duration(&self) -> Duration {
936 self.draw_end.duration_since(self.draw_start)
937 }
938
939 pub fn dirty_to_draw_duration(&self) -> Option<Duration> {
942 self.dirty_at
943 .map(|dirty_at| self.draw_end.duration_since(dirty_at))
944 }
945}
946
947#[cfg(feature = "profiler")]
949#[derive(Debug, Copy, Clone)]
950pub struct PresentTiming {
951 pub window_id: WindowId,
953 pub present_start: Instant,
955 pub present_end: Instant,
957 pub animation_interval: Option<Duration>,
960}
961
962#[cfg(feature = "profiler")]
963impl PresentTiming {
964 pub fn present_duration(&self) -> Duration {
966 self.present_end.duration_since(self.present_start)
967 }
968}
969
970#[cfg(feature = "profiler")]
972#[derive(Debug, Copy, Clone)]
973pub enum FrameEvent {
974 Draw(FrameTiming),
976 Present(PresentTiming),
978}
979
980#[cfg(feature = "profiler")]
983#[derive(Clone)]
984pub struct FrameDurationSnapshot {
985 pub dirty_to_present_histogram: Histogram<u64>,
987 pub draw_duration_histogram: Histogram<u64>,
989 pub present_interval_histogram: Histogram<u64>,
992 pub by_refresh_interval: Vec<RefreshIntervalFrames>,
995}
996
997#[cfg(feature = "profiler")]
1001pub const FRAME_DURATION_BUCKETS_MS: [u64; 9] = [4, 8, 16, 33, 50, 100, 250, 500, 1000];
1002
1003#[cfg(feature = "profiler")]
1010pub const FRAME_WORK_BUCKETS_PERCENT: [u64; 7] = [25, 50, 75, 100, 150, 200, 400];
1011
1012#[cfg(feature = "profiler")]
1016pub fn histogram_bucket_counts(
1017 histogram: &Histogram<u64>,
1018 upper_bounds: impl IntoIterator<Item = u64>,
1019) -> Vec<u64> {
1020 let mut counted = 0;
1021 let mut counts: Vec<u64> = upper_bounds
1022 .into_iter()
1023 .map(|bound| {
1024 let cumulative = histogram.count_between(0, bound);
1027 let count = cumulative.saturating_sub(counted);
1028 counted = counted.max(cumulative);
1029 count
1030 })
1031 .collect();
1032 counts.push(histogram.len().saturating_sub(counted));
1033 counts
1034}
1035
1036#[cfg(feature = "profiler")]
1042#[derive(Clone, Debug)]
1043pub struct RefreshIntervalFrames {
1044 pub refresh_interval: Option<Duration>,
1047 pub frames_drawn: u64,
1049 pub draw_duration: Histogram<u64>,
1051 pub frames_on_time: u64,
1053 pub frames_late: u64,
1055 pub missed_refreshes: u64,
1058 pub frames_unmeasured: u64,
1060 pub work: Histogram<u64>,
1062 pub input_frames_on_time: u64,
1064 pub input_frames_late: u64,
1066 pub input_work: Histogram<u64>,
1069}
1070
1071#[cfg(feature = "profiler")]
1072impl RefreshIntervalFrames {
1073 fn new(refresh_interval: Option<Duration>, empty_histogram: &Histogram<u64>) -> Self {
1074 Self {
1075 refresh_interval,
1076 frames_drawn: 0,
1077 draw_duration: empty_histogram.clone(),
1078 frames_on_time: 0,
1079 frames_late: 0,
1080 missed_refreshes: 0,
1081 frames_unmeasured: 0,
1082 work: empty_histogram.clone(),
1083 input_frames_on_time: 0,
1084 input_frames_late: 0,
1085 input_work: empty_histogram.clone(),
1086 }
1087 }
1088
1089 pub fn since(&self, earlier: &Self) -> Self {
1092 let subtract = |current: &Histogram<u64>, earlier: &Histogram<u64>| {
1093 let mut delta = current.clone();
1094 match delta.subtract(earlier) {
1095 Ok(()) => delta,
1096 Err(error) => {
1097 log::error!("failed to subtract frame histograms: {error}");
1098 current.clone()
1099 }
1100 }
1101 };
1102 Self {
1103 refresh_interval: self.refresh_interval,
1104 frames_drawn: self.frames_drawn.saturating_sub(earlier.frames_drawn),
1105 draw_duration: subtract(&self.draw_duration, &earlier.draw_duration),
1106 frames_on_time: self.frames_on_time.saturating_sub(earlier.frames_on_time),
1107 frames_late: self.frames_late.saturating_sub(earlier.frames_late),
1108 missed_refreshes: self
1109 .missed_refreshes
1110 .saturating_sub(earlier.missed_refreshes),
1111 frames_unmeasured: self
1112 .frames_unmeasured
1113 .saturating_sub(earlier.frames_unmeasured),
1114 work: subtract(&self.work, &earlier.work),
1115 input_frames_on_time: self
1116 .input_frames_on_time
1117 .saturating_sub(earlier.input_frames_on_time),
1118 input_frames_late: self
1119 .input_frames_late
1120 .saturating_sub(earlier.input_frames_late),
1121 input_work: subtract(&self.input_work, &earlier.input_work),
1122 }
1123 }
1124
1125 fn record_presented_frame(
1126 &mut self,
1127 frame: &FrameTiming,
1128 presentation: &PresentTiming,
1129 responded_to_input: bool,
1130 ) {
1131 let submitted_at = presentation.present_start;
1132 let (Some(work), Some(is_late)) = (frame.work(submitted_at), frame.is_late(submitted_at))
1133 else {
1134 self.frames_unmeasured += 1;
1135 return;
1136 };
1137 record_duration(&mut self.work, work);
1138 if responded_to_input {
1139 record_duration(&mut self.input_work, work);
1140 }
1141 self.missed_refreshes += frame.missed_refreshes(submitted_at).unwrap_or(0);
1142 if is_late {
1143 self.frames_late += 1;
1144 self.input_frames_late += u64::from(responded_to_input);
1145 } else {
1146 self.frames_on_time += 1;
1147 self.input_frames_on_time += u64::from(responded_to_input);
1148 }
1149 }
1150}
1151
1152#[cfg(feature = "profiler")]
1154fn record_duration(histogram: &mut Histogram<u64>, duration: Duration) {
1155 let nanos = u64::try_from(duration.as_nanos()).unwrap_or(u64::MAX);
1156 if let Err(error) = histogram.record(nanos) {
1157 log::error!("failed to record frame duration: {error}");
1158 }
1159}
1160
1161#[cfg(feature = "profiler")]
1164#[derive(Clone)]
1165pub struct InputLatencySnapshot {
1166 pub latency_histogram: Histogram<u64>,
1168 pub events_per_frame_histogram: Histogram<u64>,
1170 pub mid_draw_events_dropped: u64,
1173}
1174
1175#[cfg(feature = "profiler")]
1176enum WindowActivity {
1177 Input {
1178 started_at: Instant,
1179 kind: &'static str,
1180 },
1181 Draw {
1182 started_at: Instant,
1183 },
1184}
1185
1186#[cfg(feature = "profiler")]
1192pub struct WindowProfiler {
1193 window_id: WindowId,
1194 active_activities: SmallVec<[WindowActivity; 4]>,
1195 active_actions: SmallVec<[(&'static str, Instant); 2]>,
1196 dirty_to_present_histogram: Histogram<u64>,
1197 draw_duration_histogram: Histogram<u64>,
1198 present_interval_histogram: Histogram<u64>,
1199 first_input_at: Option<Instant>,
1200 pending_input_count: u64,
1201 input_latency_histogram: Histogram<u64>,
1202 events_per_frame_histogram: Histogram<u64>,
1203 mid_draw_events_dropped: u64,
1204 last_present_at: Option<Instant>,
1205 animating_at_last_present: bool,
1206 pending_frame: Option<FrameTiming>,
1207 refresh_interval: Option<Duration>,
1208 frame_signal_at: Option<Instant>,
1209 by_refresh_interval: Vec<RefreshIntervalFrames>,
1210 empty_histogram: Histogram<u64>,
1213 draw_phases: DrawPhases,
1214 nested_view_time: SmallVec<[Duration; 16]>,
1217}
1218
1219#[cfg(feature = "profiler")]
1220impl WindowProfiler {
1221 pub fn new(window_id: WindowId) -> anyhow::Result<Self> {
1223 let profiler = Self {
1224 window_id,
1225 active_activities: SmallVec::new(),
1226 active_actions: SmallVec::new(),
1227 dirty_to_present_histogram: Histogram::new(3).map_err(|error| {
1228 anyhow::anyhow!("Failed to create dirty-to-present histogram: {error}")
1229 })?,
1230 draw_duration_histogram: Histogram::new(3).map_err(|error| {
1231 anyhow::anyhow!("Failed to create draw duration histogram: {error}")
1232 })?,
1233 present_interval_histogram: Histogram::new(3).map_err(|error| {
1234 anyhow::anyhow!("Failed to create present interval histogram: {error}")
1235 })?,
1236 first_input_at: None,
1237 pending_input_count: 0,
1238 input_latency_histogram: Histogram::new(3).map_err(|error| {
1239 anyhow::anyhow!("Failed to create input latency histogram: {error}")
1240 })?,
1241 events_per_frame_histogram: Histogram::new(3).map_err(|error| {
1242 anyhow::anyhow!("Failed to create events per frame histogram: {error}")
1243 })?,
1244 mid_draw_events_dropped: 0,
1245 last_present_at: None,
1246 animating_at_last_present: false,
1247 pending_frame: None,
1248 refresh_interval: None,
1249 frame_signal_at: None,
1250 by_refresh_interval: Vec::new(),
1251 empty_histogram: Histogram::new(3)
1252 .map_err(|error| anyhow::anyhow!("Failed to create frame histogram: {error}"))?,
1253 draw_phases: DrawPhases::default(),
1254 nested_view_time: SmallVec::new(),
1255 };
1256 journal::record_frame_pending(window_id, Instant::now());
1257 Ok(profiler)
1258 }
1259
1260 pub fn begin_input(&mut self, kind: &'static str) {
1263 journal::begin_foreground_turn();
1264 self.active_activities.push(WindowActivity::Input {
1265 started_at: Instant::now(),
1266 kind,
1267 });
1268 }
1269
1270 pub fn end_input(&mut self, caused_invalidation: bool) {
1272 let Some(WindowActivity::Input { started_at, kind }) = self.active_activities.pop() else {
1273 debug_assert!(false, "input activity must be the current window activity");
1274 journal::end_foreground_turn();
1275 return;
1276 };
1277
1278 if !journal::power_interrupted_since(started_at) {
1279 journal::record_input(journal::InputTiming {
1280 kind,
1281 start: started_at,
1282 end: Instant::now(),
1283 caused_invalidation,
1284 });
1285 }
1286 journal::end_foreground_turn();
1287
1288 if !caused_invalidation || !journal::frame_sample_is_valid(self.window_id, started_at) {
1289 return;
1290 }
1291 if self
1292 .first_input_at
1293 .is_some_and(|at| !journal::frame_sample_is_valid(self.window_id, at))
1294 {
1295 self.first_input_at = None;
1296 self.pending_input_count = 0;
1297 }
1298
1299 let arrived_during_draw = self
1300 .active_activities
1301 .iter()
1302 .any(|activity| matches!(activity, WindowActivity::Draw { .. }));
1303 if arrived_during_draw {
1304 self.mid_draw_events_dropped += 1;
1305 } else {
1306 self.first_input_at.get_or_insert(started_at);
1307 self.pending_input_count += 1;
1308 }
1309 }
1310
1311 pub fn begin_action_handler(&mut self, action: &(dyn Action + 'static), cx: &mut App) {
1313 journal::begin_foreground_turn();
1314 let name = actions::update_running_action(action, cx);
1315 self.active_actions.push((name, Instant::now()));
1316 }
1317
1318 pub fn end_action_handler(&mut self) {
1320 actions::save_action_timing();
1324 let Some((name, start)) = self.active_actions.pop() else {
1325 debug_assert!(false, "action handler must be begun before it ends");
1326 journal::end_foreground_turn();
1327 return;
1328 };
1329 if !journal::power_interrupted_since(start) {
1330 journal::record_action(ActionTiming {
1331 name,
1332 start,
1333 end: Instant::now(),
1334 });
1335 }
1336 journal::end_foreground_turn();
1337 }
1338
1339 pub fn record_frame_signal(&mut self, signal_at: Option<Instant>) {
1342 self.frame_signal_at = signal_at;
1343 }
1344
1345 pub fn set_refresh_interval(&mut self, refresh_interval: Option<Duration>) {
1348 self.refresh_interval = refresh_interval;
1349 }
1350
1351 pub fn begin_draw(&mut self) {
1353 journal::begin_foreground_turn();
1354 let started_at = Instant::now();
1355 journal::record_frame_pending(self.window_id, started_at);
1356 self.active_activities
1357 .push(WindowActivity::Draw { started_at });
1358 }
1359
1360 pub fn record_draw_phases(&mut self, phases: DrawPhases) {
1362 self.draw_phases = phases;
1363 }
1364
1365 pub fn begin_view(&mut self) -> Instant {
1368 self.nested_view_time.push(Duration::ZERO);
1369 Instant::now()
1370 }
1371
1372 pub fn end_view(&mut self, start: Instant, name: &'static str, phase: ViewPhase) {
1375 let end = Instant::now();
1376 let duration = end.saturating_duration_since(start);
1377 let nested = self.nested_view_time.pop().unwrap_or_default();
1378 if let Some(parent_nested) = self.nested_view_time.last_mut() {
1379 *parent_nested += duration;
1380 }
1381 let self_duration = duration.saturating_sub(nested);
1382 if self_duration >= VIEW_TIMING_FLOOR {
1383 journal::record_view(ViewTiming {
1384 name,
1385 phase,
1386 start,
1387 end,
1388 self_duration,
1389 });
1390 }
1391 }
1392
1393 pub fn end_draw(&mut self, dirty_at: Option<Instant>, invalidations: u64) -> Duration {
1395 let Some(WindowActivity::Draw {
1396 started_at: draw_start,
1397 }) = self.active_activities.pop()
1398 else {
1399 debug_assert!(false, "draw activity must be the current window activity");
1400 journal::end_foreground_turn();
1401 return Duration::ZERO;
1402 };
1403
1404 let draw_end = Instant::now();
1405 let signal_at = self.frame_signal_at.take();
1407 let dirty_at = dirty_at.filter(|at| journal::frame_sample_is_valid(self.window_id, *at));
1408 let frame_timing = FrameTiming {
1409 window_id: self.window_id,
1410 dirty_at,
1411 invalidations,
1412 draw_start,
1413 draw_end,
1414 refresh_interval: self.refresh_interval,
1415 signal_at,
1416 phases: std::mem::take(&mut self.draw_phases),
1417 };
1418 let draw_duration = frame_timing.draw_duration();
1419 if !journal::power_interrupted_since(draw_start) {
1420 self.record_draw_timing(frame_timing);
1421 }
1422 journal::end_foreground_turn();
1423 draw_duration
1424 }
1425
1426 pub fn record_present(
1431 &mut self,
1432 present_start: Instant,
1433 present_end: Instant,
1434 window_active: bool,
1435 next_frame_scheduled: bool,
1436 ) {
1437 self.record_present_at(
1438 present_start,
1439 present_end,
1440 window_active,
1441 next_frame_scheduled,
1442 );
1443 }
1444
1445 pub fn input_latency_snapshot(&self) -> InputLatencySnapshot {
1447 InputLatencySnapshot {
1448 latency_histogram: self.input_latency_histogram.clone(),
1449 events_per_frame_histogram: self.events_per_frame_histogram.clone(),
1450 mid_draw_events_dropped: self.mid_draw_events_dropped,
1451 }
1452 }
1453
1454 pub fn frame_duration_snapshot(&self) -> FrameDurationSnapshot {
1456 FrameDurationSnapshot {
1457 dirty_to_present_histogram: self.dirty_to_present_histogram.clone(),
1458 draw_duration_histogram: self.draw_duration_histogram.clone(),
1459 present_interval_histogram: self.present_interval_histogram.clone(),
1460 by_refresh_interval: self.by_refresh_interval.clone(),
1461 }
1462 }
1463
1464 fn frames_for(&mut self, refresh_interval: Option<Duration>) -> &mut RefreshIntervalFrames {
1465 let index = match self
1466 .by_refresh_interval
1467 .iter()
1468 .position(|frames| frames.refresh_interval == refresh_interval)
1469 {
1470 Some(index) => index,
1471 None => {
1472 self.by_refresh_interval.push(RefreshIntervalFrames::new(
1473 refresh_interval,
1474 &self.empty_histogram,
1475 ));
1476 self.by_refresh_interval.len() - 1
1477 }
1478 };
1479 &mut self.by_refresh_interval[index]
1480 }
1481
1482 fn record_present_at(
1483 &mut self,
1484 present_start: Instant,
1485 present_end: Instant,
1486 window_active: bool,
1487 next_frame_scheduled: bool,
1488 ) {
1489 let mut responded_to_input = false;
1490 if let Some(first_input_at) = self.first_input_at.take()
1491 && journal::frame_sample_is_valid(self.window_id, first_input_at)
1492 {
1493 responded_to_input = true;
1494 let latency_nanos = present_end.duration_since(first_input_at).as_nanos() as u64;
1495 self.input_latency_histogram.record(latency_nanos).ok();
1496 if self.pending_input_count > 0 {
1497 self.events_per_frame_histogram
1498 .record(self.pending_input_count)
1499 .ok();
1500 }
1501 }
1502 self.pending_input_count = 0;
1503
1504 let frame = self
1505 .pending_frame
1506 .take()
1507 .filter(|frame| journal::frame_sample_is_valid(self.window_id, frame.draw_start))
1508 .map(|mut frame| {
1509 frame.dirty_at = frame
1510 .dirty_at
1511 .filter(|at| journal::frame_sample_is_valid(self.window_id, *at));
1512 frame
1513 });
1514 let animation_interval =
1515 if frame.is_some() && self.animating_at_last_present && window_active {
1516 self.last_present_at
1517 .filter(|at| journal::frame_sample_is_valid(self.window_id, *at))
1518 .map(|last_present_at| present_end.duration_since(last_present_at))
1519 } else {
1520 None
1521 };
1522 let present_timing = PresentTiming {
1523 window_id: self.window_id,
1524 present_start,
1525 present_end,
1526 animation_interval,
1527 };
1528 journal::record_present(present_timing, frame);
1529
1530 let Some(frame) = frame else {
1531 return;
1532 };
1533 self.frames_for(frame.refresh_interval)
1534 .record_presented_frame(&frame, &present_timing, responded_to_input);
1535
1536 if let Some(dirty_at) = frame.dirty_at
1537 && let Err(error) = self
1538 .dirty_to_present_histogram
1539 .record(present_end.duration_since(dirty_at).as_nanos() as u64)
1540 {
1541 log::error!("failed to record dirty-to-present frame timing: {error}");
1542 }
1543
1544 if let Some(animation_interval) = animation_interval {
1545 self.present_interval_histogram
1546 .record(animation_interval.as_nanos() as u64)
1547 .ok();
1548 }
1549 record_frame_event(FrameEvent::Present(present_timing));
1550
1551 self.last_present_at = Some(present_end);
1552 self.animating_at_last_present = next_frame_scheduled && window_active;
1553 }
1554
1555 fn record_draw_timing(&mut self, timing: FrameTiming) {
1556 self.record_draw_duration(timing.draw_duration());
1557 let frames = self.frames_for(timing.refresh_interval);
1558 frames.frames_drawn += 1;
1559 record_duration(&mut frames.draw_duration, timing.draw_duration());
1560 self.pending_frame = Some(timing);
1561 record_frame_event(FrameEvent::Draw(timing));
1562 journal::record_draw(timing);
1563 }
1564
1565 fn record_draw_duration(&mut self, duration: Duration) {
1566 self.draw_duration_histogram
1567 .record(duration.as_nanos() as u64)
1568 .ok();
1569 }
1570}
1571
1572#[cfg(feature = "profiler")]
1573impl Drop for WindowProfiler {
1574 fn drop(&mut self) {
1575 journal::record_window_closed(self.window_id);
1576 }
1577}
1578
1579#[cfg(feature = "profiler")]
1581const MAX_FRAME_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<FrameEvent>();
1582
1583#[cfg(feature = "profiler")]
1584struct FrameTimings {
1585 timings: VecDeque<FrameEvent>,
1586 total_pushed: u64,
1587}
1588
1589#[cfg(feature = "profiler")]
1590static FRAME_TIMINGS: spin::Mutex<FrameTimings> = spin::Mutex::new(FrameTimings {
1591 timings: VecDeque::new(),
1592 total_pushed: 0,
1593});
1594
1595#[cfg(feature = "profiler")]
1599pub fn record_frame_event(event: FrameEvent) {
1600 if !trace_enabled() {
1601 return;
1602 }
1603 std::hint::cold_path(); let mut frames = FRAME_TIMINGS.lock();
1606 if frames.timings.len() >= MAX_FRAME_TIMINGS {
1607 frames.timings.pop_front();
1608 }
1609 frames.timings.push_back(event);
1610 frames.total_pushed += 1;
1611}
1612
1613#[cfg(feature = "profiler")]
1616pub struct FrameTimingCollector {
1617 cursor: u64,
1618}
1619
1620#[cfg(feature = "profiler")]
1621impl Default for FrameTimingCollector {
1622 fn default() -> Self {
1623 Self::new()
1624 }
1625}
1626
1627#[cfg(feature = "profiler")]
1628impl FrameTimingCollector {
1629 pub fn new() -> Self {
1631 Self {
1632 cursor: FRAME_TIMINGS.lock().total_pushed,
1633 }
1634 }
1635
1636 pub fn collect_unseen(&mut self) -> Vec<FrameEvent> {
1640 let frames = FRAME_TIMINGS.lock();
1641 let buffer_len = frames.timings.len() as u64;
1642 let buffer_start = frames.total_pushed.saturating_sub(buffer_len);
1643 let skip = self.cursor.saturating_sub(buffer_start) as usize;
1644 let unseen = frames
1645 .timings
1646 .iter()
1647 .skip(skip.min(frames.timings.len()))
1648 .copied()
1649 .collect();
1650 self.cursor = frames.total_pushed;
1651 unseen
1652 }
1653}
1654
1655#[cfg(all(test, feature = "profiler"))]
1656mod tests {
1657 use super::*;
1658 use std::sync::{Mutex, MutexGuard};
1659
1660 #[test]
1661 fn interruptions_drop_latency_samples_but_hiding_keeps_draw_work() {
1662 for sleep in [false, true] {
1663 let (_journal, _guard) = journal::install_test_foreground_journal(64, 4);
1664 let id = WindowId::from(1);
1665 let mut profiler = WindowProfiler::new(id).expect("valid histograms");
1666 let old = Instant::now() - Duration::from_secs(1);
1667 record_test_draw(&mut profiler, old);
1668 profiler.record_present_at(old, old, true, true);
1669 profiler.first_input_at = Some(old);
1670 profiler.pending_input_count = 1;
1671 profiler.begin_draw();
1672 if sleep {
1673 journal::record_power_transition(journal::PowerState::Suspended);
1674 journal::record_power_transition(journal::PowerState::Awake);
1675 } else {
1676 journal::record_window_visibility(id, crate::WindowVisibility::Hidden);
1677 journal::record_window_visibility(id, crate::WindowVisibility::Visible);
1678 }
1679 profiler.end_draw(Some(old), 1);
1680 let now = Instant::now();
1681 profiler.record_present_at(now, now, true, true);
1682 assert_eq!(
1683 profiler.draw_duration_histogram.len(),
1684 if sleep { 1 } else { 2 }
1685 );
1686 assert_eq!(profiler.input_latency_histogram.len(), 0);
1687 assert_eq!(profiler.dirty_to_present_histogram.len(), 1);
1688 assert_eq!(profiler.present_interval_histogram.len(), 0);
1689 profiler.begin_draw();
1690 profiler.end_draw(Some(Instant::now()), 1);
1691 let now = Instant::now();
1692 profiler.record_present_at(now, now, true, true);
1693 assert_eq!(profiler.dirty_to_present_histogram.len(), 2);
1694 }
1695 }
1696
1697 #[test]
1698 fn frame_work_starts_at_the_later_of_signal_and_invalidation() {
1699 let refresh = Duration::from_millis(10);
1700 let start = Instant::now();
1701 let at = |ms| start + Duration::from_millis(ms);
1702 let frame_with = |dirty: Option<u64>, signal: Option<u64>| FrameTiming {
1703 window_id: WindowId::from(1),
1704 dirty_at: dirty.map(at),
1705 invalidations: 1,
1706 draw_start: at(1),
1707 draw_end: at(2),
1708 refresh_interval: Some(refresh),
1709 signal_at: signal.map(at),
1710 phases: Default::default(),
1711 };
1712 let work = |dirty, signal| frame_with(dirty, signal).work(at(50));
1713
1714 assert_eq!(work(Some(0), Some(8)), Some(Duration::from_millis(42)));
1716 assert_eq!(work(Some(0), Some(40)), Some(Duration::from_millis(10)));
1717 assert_eq!(work(Some(5), Some(0)), Some(Duration::from_millis(45)));
1720 assert_eq!(work(None, Some(0)), Some(Duration::from_millis(50)));
1722 assert_eq!(work(Some(0), None), None);
1723
1724 let frame = frame_with(Some(0), Some(0));
1725 for (submitted_ms, missed) in [(7, 0), (10, 0), (20, 1), (25, 2)] {
1726 assert_eq!(frame.missed_refreshes(at(submitted_ms)), Some(missed));
1727 }
1728 }
1729
1730 #[test]
1731 fn frames_are_split_by_refresh_interval_and_classified() {
1732 let (_journal, _guard) = journal::install_test_foreground_journal(64, 4);
1733 let mut profiler = WindowProfiler::new(WindowId::from(1)).expect("valid histograms");
1734 let sixty_hertz = Duration::from_secs(1) / 60;
1735 let one_hundred_twenty_hertz = Duration::from_secs(1) / 120;
1736 let three_hundred_sixty_hertz = Duration::from_secs(1) / 360;
1737 let base = Instant::now();
1738 let at = |ms| base + Duration::from_millis(ms);
1739
1740 struct Frame {
1741 refresh_interval: Option<Duration>,
1742 signal_ms: Option<u64>,
1743 present_start_ms: u64,
1744 responded_to_input: bool,
1745 }
1746 let frames = [
1747 Frame {
1749 refresh_interval: Some(sixty_hertz),
1750 signal_ms: Some(1),
1751 present_start_ms: 5,
1752 responded_to_input: true,
1753 },
1754 Frame {
1755 refresh_interval: Some(sixty_hertz),
1756 signal_ms: Some(0),
1757 present_start_ms: 40,
1758 responded_to_input: true,
1759 },
1760 Frame {
1761 refresh_interval: Some(sixty_hertz),
1762 signal_ms: None,
1763 present_start_ms: 5,
1764 responded_to_input: false,
1765 },
1766 Frame {
1768 refresh_interval: Some(sixty_hertz),
1769 signal_ms: Some(40),
1770 present_start_ms: 42,
1771 responded_to_input: false,
1772 },
1773 Frame {
1774 refresh_interval: Some(one_hundred_twenty_hertz),
1775 signal_ms: Some(0),
1776 present_start_ms: 12,
1777 responded_to_input: false,
1778 },
1779 Frame {
1781 refresh_interval: Some(three_hundred_sixty_hertz),
1782 signal_ms: Some(0),
1783 present_start_ms: 6,
1784 responded_to_input: false,
1785 },
1786 Frame {
1787 refresh_interval: Some(three_hundred_sixty_hertz),
1788 signal_ms: Some(0),
1789 present_start_ms: 9,
1790 responded_to_input: false,
1791 },
1792 Frame {
1793 refresh_interval: None,
1794 signal_ms: Some(0),
1795 present_start_ms: 2,
1796 responded_to_input: false,
1797 },
1798 ];
1799 for frame in frames {
1800 profiler.set_refresh_interval(frame.refresh_interval);
1801 profiler.record_draw_timing(FrameTiming {
1802 window_id: profiler.window_id,
1803 dirty_at: Some(at(0)),
1804 invalidations: 1,
1805 draw_start: at(0),
1806 draw_end: at(1),
1807 refresh_interval: frame.refresh_interval,
1808 signal_at: frame.signal_ms.map(at),
1809 phases: Default::default(),
1810 });
1811 if frame.responded_to_input {
1812 profiler.first_input_at = Some(at(0));
1813 }
1814 profiler.record_present_at(
1815 at(frame.present_start_ms),
1816 at(frame.present_start_ms + 1),
1817 true,
1818 false,
1819 );
1820 }
1821
1822 let snapshot = profiler.frame_duration_snapshot();
1823 let frames_for = |refresh_interval| {
1824 snapshot
1825 .by_refresh_interval
1826 .iter()
1827 .find(|frames| frames.refresh_interval == refresh_interval)
1828 .cloned()
1829 .expect("frames for the refresh interval")
1830 };
1831 let work_buckets = |work: &Histogram<u64>, refresh_interval: Duration| {
1832 histogram_bucket_counts(
1833 work,
1834 FRAME_WORK_BUCKETS_PERCENT
1835 .map(|percent| (refresh_interval * percent as u32 / 100).as_nanos() as u64),
1836 )
1837 };
1838 let sixty = frames_for(Some(sixty_hertz));
1839 assert_eq!(sixty.frames_drawn, 4);
1840 assert_eq!(sixty.frames_on_time, 2);
1841 assert_eq!(sixty.frames_late, 1);
1842 assert_eq!(sixty.missed_refreshes, 2);
1844 assert_eq!(sixty.frames_unmeasured, 1);
1845 assert_eq!(
1846 work_buckets(&sixty.work, sixty_hertz),
1847 [2, 0, 0, 0, 0, 0, 1, 0]
1848 );
1849 assert_eq!(sixty.input_frames_on_time, 1);
1850 assert_eq!(sixty.input_frames_late, 1);
1851 assert_eq!(
1852 work_buckets(&sixty.input_work, sixty_hertz),
1853 [1, 0, 0, 0, 0, 0, 1, 0]
1854 );
1855
1856 let one_hundred_twenty = frames_for(Some(one_hundred_twenty_hertz));
1857 assert_eq!(one_hundred_twenty.frames_late, 1);
1858 assert_eq!(one_hundred_twenty.missed_refreshes, 1);
1859 assert_eq!(one_hundred_twenty.input_frames_late, 0);
1860
1861 let three_hundred_sixty = frames_for(Some(three_hundred_sixty_hertz));
1862 assert_eq!(three_hundred_sixty.frames_on_time, 1);
1863 assert_eq!(three_hundred_sixty.frames_late, 1);
1864 assert_eq!(three_hundred_sixty.missed_refreshes, 5);
1866
1867 let unknown = frames_for(None);
1869 assert_eq!(unknown.frames_drawn, 1);
1870 assert_eq!(unknown.frames_on_time, 1);
1871 assert_eq!(unknown.missed_refreshes, 0);
1872
1873 let later = profiler.frame_duration_snapshot();
1874 let delta = later.by_refresh_interval[0].since(&snapshot.by_refresh_interval[0]);
1875 assert_eq!(
1876 delta.frames_drawn + delta.frames_on_time + delta.frames_late,
1877 0
1878 );
1879 assert_eq!(
1880 delta.draw_duration.len() + delta.work.len() + delta.input_work.len(),
1881 0
1882 );
1883 }
1884
1885 #[test]
1886 fn records_draw_events_only_while_tracing() {
1887 let _trace_test_guard = TraceTestGuard::new();
1888 let window_id = WindowId::from(0xD0A0);
1889 let mut window_profiler =
1890 WindowProfiler::new(window_id).expect("window profiler should initialize");
1891 let dirty_at = Instant::now();
1892 let mut collector = FrameTimingCollector::new();
1893
1894 window_profiler.begin_draw();
1895 window_profiler.end_draw(Some(dirty_at), 3);
1896 assert!(
1897 collector
1898 .collect_unseen()
1899 .iter()
1900 .all(|event| !event_matches_window(*event, window_id))
1901 );
1902
1903 set_trace_enabled(true);
1904 let mut collector = FrameTimingCollector::new();
1905 window_profiler.begin_draw();
1906 window_profiler.end_draw(Some(dirty_at), 3);
1907
1908 let timing = collector
1909 .collect_unseen()
1910 .into_iter()
1911 .find_map(|event| match event {
1912 FrameEvent::Draw(timing) if timing.window_id == window_id => Some(timing),
1913 _ => None,
1914 })
1915 .expect("draw event should be recorded while tracing");
1916 assert_eq!(timing.dirty_at, Some(dirty_at));
1917 assert_eq!(timing.invalidations, 3);
1918 assert!(timing.draw_start >= dirty_at);
1919 }
1920
1921 #[test]
1922 fn records_present_events_for_newly_drawn_frames() {
1923 let _trace_test_guard = TraceTestGuard::new();
1924 set_trace_enabled(true);
1925 let window_id = WindowId::from(0xA11E);
1926 let mut window_profiler =
1927 WindowProfiler::new(window_id).expect("window profiler should initialize");
1928 let start = Instant::now();
1929 let mut collector = FrameTimingCollector::new();
1930
1931 record_test_draw(&mut window_profiler, start);
1932 window_profiler.record_present_at(start, start, true, true);
1933 record_test_draw(&mut window_profiler, start + FRAME);
1934 window_profiler.record_present_at(start + FRAME, start + FRAME, true, true);
1935 window_profiler.record_present_at(
1936 start + FRAME + FRAME / 2,
1937 start + FRAME + FRAME / 2,
1938 true,
1939 true,
1940 );
1941
1942 let present_timings = collector
1943 .collect_unseen()
1944 .into_iter()
1945 .filter_map(|event| match event {
1946 FrameEvent::Present(timing) if timing.window_id == window_id => Some(timing),
1947 _ => None,
1948 })
1949 .collect::<Vec<_>>();
1950 let [first_present, second_present] = present_timings.as_slice() else {
1951 panic!("expected exactly two present events, got {present_timings:?}");
1952 };
1953 assert_eq!(first_present.animation_interval, None);
1954 assert_eq!(second_present.animation_interval, Some(FRAME));
1955
1956 #[cfg(feature = "profiler")]
1957 {
1958 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
1959 assert!(
1960 window_profiler.present_interval_histogram.max()
1961 >= second_present
1962 .animation_interval
1963 .expect("second present should have an animation interval")
1964 .as_nanos() as u64
1965 );
1966 }
1967 }
1968
1969 #[test]
1970 fn disabling_tracing_clears_frame_events() {
1971 let _trace_test_guard = TraceTestGuard::new();
1972 set_trace_enabled(true);
1973 let window_id = WindowId::from(0xC1EA);
1974 let mut window_profiler =
1975 WindowProfiler::new(window_id).expect("window profiler should initialize");
1976 let mut collector = FrameTimingCollector::new();
1977
1978 window_profiler.begin_draw();
1979 window_profiler.end_draw(None, 0);
1980 assert!(
1981 FRAME_TIMINGS
1982 .lock()
1983 .timings
1984 .iter()
1985 .copied()
1986 .any(|event| event_matches_window(event, window_id))
1987 );
1988
1989 set_trace_enabled(false);
1990 assert!(
1991 collector
1992 .collect_unseen()
1993 .iter()
1994 .all(|event| !event_matches_window(*event, window_id))
1995 );
1996 }
1997
1998 #[cfg(feature = "profiler")]
1999 #[test]
2000 fn records_intervals_only_between_animation_frames() {
2001 let mut window_profiler =
2002 WindowProfiler::new(WindowId::from(1)).expect("window profiler should initialize");
2003 let start = Instant::now();
2004
2005 draw_and_present(&mut window_profiler, start, true, true);
2006 assert_eq!(window_profiler.present_interval_histogram.len(), 0);
2007
2008 draw_and_present(&mut window_profiler, start + FRAME, true, true);
2009 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
2010
2011 draw_and_present(&mut window_profiler, start + FRAME * 2, true, false);
2012 assert_eq!(window_profiler.present_interval_histogram.len(), 2);
2013
2014 draw_and_present(&mut window_profiler, start + FRAME * 100, true, true);
2015 assert_eq!(window_profiler.present_interval_histogram.len(), 2);
2016 }
2017
2018 #[cfg(feature = "profiler")]
2019 #[test]
2020 fn missed_frames_stretch_the_recorded_interval() {
2021 let mut window_profiler =
2022 WindowProfiler::new(WindowId::from(2)).expect("window profiler should initialize");
2023 let start = Instant::now();
2024
2025 draw_and_present(&mut window_profiler, start, true, true);
2026 draw_and_present(&mut window_profiler, start + FRAME * 5, true, true);
2027
2028 let recorded = window_profiler.present_interval_histogram.max();
2029 assert!(recorded >= (FRAME * 4).as_nanos() as u64);
2030 }
2031
2032 #[cfg(feature = "profiler")]
2033 #[test]
2034 fn ignores_re_presents_of_unchanged_frames() {
2035 let mut window_profiler =
2036 WindowProfiler::new(WindowId::from(3)).expect("window profiler should initialize");
2037 let start = Instant::now();
2038
2039 draw_and_present(&mut window_profiler, start, true, true);
2040 window_profiler.record_present_at(start + FRAME / 2, start + FRAME / 2, true, true);
2041 draw_and_present(&mut window_profiler, start + FRAME, true, true);
2042
2043 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
2044 assert!(
2045 window_profiler.present_interval_histogram.max() >= (FRAME * 3 / 4).as_nanos() as u64
2046 );
2047 }
2048
2049 #[cfg(feature = "profiler")]
2050 #[test]
2051 fn skips_intervals_for_inactive_windows() {
2052 let mut window_profiler =
2053 WindowProfiler::new(WindowId::from(4)).expect("window profiler should initialize");
2054 let start = Instant::now();
2055
2056 draw_and_present(&mut window_profiler, start, false, true);
2057 draw_and_present(&mut window_profiler, start + FRAME, false, true);
2058 assert_eq!(window_profiler.present_interval_histogram.len(), 0);
2059
2060 draw_and_present(&mut window_profiler, start + FRAME * 2, true, true);
2061 assert_eq!(window_profiler.present_interval_histogram.len(), 0);
2062
2063 draw_and_present(&mut window_profiler, start + FRAME * 3, true, true);
2064 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
2065 }
2066
2067 #[test]
2068 fn records_dirty_to_present_durations() {
2069 let mut window_profiler =
2070 WindowProfiler::new(WindowId::from(8)).expect("window profiler should initialize");
2071 let draw_end = Instant::now();
2072 let present_end = draw_end + Duration::from_millis(6);
2073
2074 record_test_draw(&mut window_profiler, draw_end);
2075 window_profiler.record_present_at(present_end, present_end, true, false);
2076
2077 let snapshot = window_profiler.frame_duration_snapshot();
2078 let histogram = snapshot.dirty_to_present_histogram;
2079 assert_eq!(histogram.len(), 1);
2080 assert!(histogram.max() >= Duration::from_millis(10).as_nanos() as u64);
2081 }
2082
2083 #[cfg(feature = "profiler")]
2084 #[test]
2085 fn records_every_draw_duration() {
2086 let mut window_profiler =
2087 WindowProfiler::new(WindowId::from(5)).expect("window profiler should initialize");
2088
2089 window_profiler.record_draw_duration(Duration::from_millis(2));
2090 window_profiler.record_draw_duration(Duration::from_millis(40));
2091
2092 let snapshot = window_profiler.frame_duration_snapshot();
2093 assert_eq!(snapshot.draw_duration_histogram.len(), 2);
2094 assert!(snapshot.draw_duration_histogram.max() >= 39_000_000);
2095 }
2096
2097 #[test]
2098 fn records_input_latency_at_the_frame_presentation_timestamp() {
2099 let mut window_profiler =
2100 WindowProfiler::new(WindowId::from(6)).expect("window profiler should initialize");
2101 let first_input_at = Instant::now();
2102 let presented_at = first_input_at + Duration::from_millis(12);
2103
2104 begin_input_at(&mut window_profiler, first_input_at);
2105 window_profiler.end_input(true);
2106 begin_input_at(
2107 &mut window_profiler,
2108 first_input_at + Duration::from_millis(2),
2109 );
2110 window_profiler.end_input(true);
2111 record_test_draw(&mut window_profiler, presented_at);
2112 window_profiler.record_present_at(presented_at, presented_at, true, false);
2113
2114 let snapshot = window_profiler.input_latency_snapshot();
2115 assert_eq!(snapshot.latency_histogram.len(), 1);
2116 assert!(snapshot.latency_histogram.max() >= Duration::from_millis(12).as_nanos() as u64);
2117 assert_eq!(snapshot.events_per_frame_histogram.len(), 1);
2118 assert_eq!(snapshot.events_per_frame_histogram.max(), 2);
2119 assert_eq!(snapshot.mid_draw_events_dropped, 0);
2120 }
2121
2122 #[test]
2123 fn excludes_input_that_arrives_during_a_draw() {
2124 let mut window_profiler =
2125 WindowProfiler::new(WindowId::from(7)).expect("window profiler should initialize");
2126
2127 window_profiler.begin_draw();
2128 begin_input_at(&mut window_profiler, Instant::now());
2129 window_profiler.end_input(true);
2130 window_profiler.end_draw(None, 0);
2131
2132 let snapshot = window_profiler.input_latency_snapshot();
2133 assert!(snapshot.latency_histogram.is_empty());
2134 assert!(snapshot.events_per_frame_histogram.is_empty());
2135 assert_eq!(snapshot.mid_draw_events_dropped, 1);
2136 }
2137
2138 #[test]
2139 fn overlapping_trace_scopes_keep_tracing_enabled() {
2140 let _trace_test_guard = TraceTestGuard::new();
2141 let first_scope = trace_scope();
2142 let second_scope = trace_scope();
2143
2144 assert!(trace_enabled());
2145 drop(first_scope);
2146 assert!(trace_enabled());
2147 drop(second_scope);
2148 assert!(!trace_enabled());
2149 }
2150
2151 const FRAME: Duration = Duration::from_millis(16);
2152 static TRACE_TEST_LOCK: Mutex<()> = Mutex::new(());
2153
2154 struct TraceTestGuard {
2155 was_enabled: bool,
2156 _lock: MutexGuard<'static, ()>,
2157 }
2158
2159 impl TraceTestGuard {
2160 fn new() -> Self {
2161 let lock = TRACE_TEST_LOCK
2162 .lock()
2163 .unwrap_or_else(|poisoned| poisoned.into_inner());
2164 let was_enabled = trace_enabled();
2165 set_trace_enabled(false);
2166 Self {
2167 was_enabled,
2168 _lock: lock,
2169 }
2170 }
2171 }
2172
2173 impl Drop for TraceTestGuard {
2174 fn drop(&mut self) {
2175 set_trace_enabled(false);
2176 if self.was_enabled {
2177 set_trace_enabled(true);
2178 }
2179 }
2180 }
2181
2182 fn event_matches_window(event: FrameEvent, window_id: WindowId) -> bool {
2183 match event {
2184 FrameEvent::Draw(timing) => timing.window_id == window_id,
2185 FrameEvent::Present(timing) => timing.window_id == window_id,
2186 }
2187 }
2188
2189 fn begin_input_at(window_profiler: &mut WindowProfiler, started_at: Instant) {
2190 window_profiler
2191 .active_activities
2192 .push(WindowActivity::Input {
2193 started_at,
2194 kind: "test",
2195 });
2196 }
2197
2198 #[cfg(feature = "profiler")]
2199 fn draw_and_present(
2200 window_profiler: &mut WindowProfiler,
2201 presented_at: Instant,
2202 window_active: bool,
2203 next_frame_scheduled: bool,
2204 ) {
2205 record_test_draw(window_profiler, presented_at);
2206 window_profiler.record_present_at(
2207 presented_at,
2208 presented_at,
2209 window_active,
2210 next_frame_scheduled,
2211 );
2212 }
2213
2214 fn record_test_draw(window_profiler: &mut WindowProfiler, draw_end: Instant) {
2215 window_profiler.record_draw_timing(FrameTiming {
2216 window_id: window_profiler.window_id,
2217 dirty_at: Some(draw_end - Duration::from_millis(4)),
2218 invalidations: 1,
2219 draw_start: draw_end - Duration::from_millis(2),
2220 draw_end,
2221 refresh_interval: None,
2222 signal_at: None,
2223 phases: Default::default(),
2224 });
2225 }
2226}