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