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 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 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); 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#[derive(Debug, Clone, Serialize, Deserialize)]
228pub struct SerializedLocation {
229 pub file: SharedString,
231 pub line: u32,
233 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#[derive(Debug, Clone, Serialize, Deserialize)]
249pub struct SerializedTaskTiming {
250 pub location: SerializedLocation,
252 pub start: u128,
254 pub duration: u128,
256}
257
258impl SerializedTaskTiming {
259 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 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#[derive(Debug, Clone, Serialize, Deserialize)]
295pub struct SerializedThreadTaskTimings {
296 pub thread_name: Option<String>,
298 pub thread_id: u64,
300 pub timings: Vec<SerializedTaskTiming>,
302}
303
304impl SerializedThreadTaskTimings {
305 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 pub thread_id: u64,
330 pub thread_name: Option<String>,
332 pub new_timings: Vec<SerializedTaskTiming>,
335}
336
337#[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 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#[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 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(); 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(); 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
516fn 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(); 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 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
691pub 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
710pub 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
774pub 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#[cfg(feature = "profiler")]
797#[derive(Debug, Copy, Clone)]
798pub struct FrameTiming {
799 pub window_id: WindowId,
801 pub dirty_at: Option<Instant>,
804 pub invalidations: u64,
806 pub draw_start: Instant,
808 pub draw_end: Instant,
810 pub refresh_interval: Option<Duration>,
813 pub signal_at: Option<Instant>,
816 pub phases: DrawPhases,
818}
819
820#[cfg(feature = "profiler")]
822#[derive(Debug, Copy, Clone, Default, PartialEq, Eq)]
823pub struct DrawPhases {
824 pub request_layout: Duration,
826 pub prepaint: Duration,
829 pub paint: Duration,
831}
832
833#[cfg(feature = "profiler")]
835#[derive(Debug, Copy, Clone, PartialEq, Eq)]
836pub enum ViewPhase {
837 RequestLayout,
839 Prepaint,
842 Paint,
844}
845
846#[cfg(feature = "profiler")]
847impl ViewPhase {
848 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#[cfg(feature = "profiler")]
862pub const VIEW_TIMING_FLOOR: Duration = Duration::from_micros(500);
863
864#[cfg(feature = "profiler")]
867#[derive(Debug, Copy, Clone)]
868pub struct ViewTiming {
869 pub name: &'static str,
871 pub phase: ViewPhase,
873 pub start: Instant,
875 pub end: Instant,
877 pub self_duration: Duration,
880}
881
882#[cfg(feature = "profiler")]
887pub const FRAME_BUDGET_FLOOR: Duration = Duration::from_nanos(8_333_333);
888
889#[cfg(feature = "profiler")]
893pub const UNKNOWN_REFRESH_FRAME_BUDGET: Duration = Duration::from_nanos(16_666_667);
894
895#[cfg(feature = "profiler")]
896impl FrameTiming {
897 pub fn work_start(&self) -> Option<Instant> {
901 let signal_at = self.signal_at?;
902 Some(
906 self.dirty_at
907 .map_or(signal_at, |dirty_at| dirty_at.max(signal_at)),
908 )
909 }
910
911 pub fn work(&self, submitted_at: Instant) -> Option<Duration> {
915 Some(submitted_at.saturating_duration_since(self.work_start()?))
916 }
917
918 pub fn is_late(&self, submitted_at: Instant) -> Option<bool> {
921 Some(self.work(submitted_at)? > self.budget())
922 }
923
924 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 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 pub fn draw_duration(&self) -> Duration {
945 self.draw_end.duration_since(self.draw_start)
946 }
947
948 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#[cfg(feature = "profiler")]
958#[derive(Debug, Copy, Clone)]
959pub struct PresentTiming {
960 pub window_id: WindowId,
962 pub present_start: Instant,
964 pub present_end: Instant,
966 pub animation_interval: Option<Duration>,
969}
970
971#[cfg(feature = "profiler")]
972impl PresentTiming {
973 pub fn present_duration(&self) -> Duration {
975 self.present_end.duration_since(self.present_start)
976 }
977}
978
979#[cfg(feature = "profiler")]
981#[derive(Debug, Copy, Clone)]
982pub enum FrameEvent {
983 Draw(FrameTiming),
985 Present(PresentTiming),
987}
988
989#[cfg(feature = "profiler")]
992#[derive(Clone)]
993pub struct FrameDurationSnapshot {
994 pub dirty_to_present_histogram: Histogram<u64>,
996 pub draw_duration_histogram: Histogram<u64>,
998 pub present_interval_histogram: Histogram<u64>,
1001 pub by_refresh_interval: Vec<RefreshIntervalFrames>,
1004}
1005
1006#[cfg(feature = "profiler")]
1010pub const FRAME_DURATION_BUCKETS_MS: [u64; 9] = [4, 8, 16, 33, 50, 100, 250, 500, 1000];
1011
1012#[cfg(feature = "profiler")]
1019pub const FRAME_WORK_BUCKETS_PERCENT: [u64; 7] = [25, 50, 75, 100, 150, 200, 400];
1020
1021#[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 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#[cfg(feature = "profiler")]
1051#[derive(Clone, Debug)]
1052pub struct RefreshIntervalFrames {
1053 pub refresh_interval: Option<Duration>,
1056 pub frames_drawn: u64,
1058 pub draw_duration: Histogram<u64>,
1060 pub frames_on_time: u64,
1062 pub frames_late: u64,
1064 pub missed_refreshes: u64,
1067 pub frames_unmeasured: u64,
1069 pub work: Histogram<u64>,
1071 pub input_frames_on_time: u64,
1073 pub input_frames_late: u64,
1075 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 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#[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#[cfg(feature = "profiler")]
1173#[derive(Clone)]
1174pub struct InputLatencySnapshot {
1175 pub latency_histogram: Histogram<u64>,
1177 pub events_per_frame_histogram: Histogram<u64>,
1179 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#[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 empty_histogram: Histogram<u64>,
1222 draw_phases: DrawPhases,
1223 nested_view_time: SmallVec<[Duration; 16]>,
1226}
1227
1228#[cfg(feature = "profiler")]
1229impl WindowProfiler {
1230 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 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 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 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 pub fn end_action_handler(&mut self) {
1329 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 pub fn record_frame_signal(&mut self, signal_at: Option<Instant>) {
1351 self.frame_signal_at = signal_at;
1352 }
1353
1354 pub fn set_refresh_interval(&mut self, refresh_interval: Option<Duration>) {
1357 self.refresh_interval = refresh_interval;
1358 }
1359
1360 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 pub fn record_draw_phases(&mut self, phases: DrawPhases) {
1371 self.draw_phases = phases;
1372 }
1373
1374 pub fn begin_view(&mut self) -> Instant {
1377 self.nested_view_time.push(Duration::ZERO);
1378 Instant::now()
1379 }
1380
1381 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 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 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 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 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 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#[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#[cfg(feature = "profiler")]
1608pub fn record_frame_event(event: FrameEvent) {
1609 if !trace_enabled() {
1610 return;
1611 }
1612 std::hint::cold_path(); 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#[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 pub fn new() -> Self {
1640 Self {
1641 cursor: FRAME_TIMINGS.lock().total_pushed,
1642 }
1643 }
1644
1645 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#[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 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 assert_eq!(work(Some(5), Some(0)), Some(Duration::from_millis(45)));
1743 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 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 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 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 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 assert_eq!(three_hundred_sixty.missed_refreshes, 5);
1889
1890 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}