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