1#[cfg(feature = "profiler")]
2use hdrhistogram::Histogram;
3use itertools::Itertools;
4use scheduler::{Instant, SpawnTime};
5#[cfg(feature = "profiler")]
6use smallvec::SmallVec;
7use std::{
8 cell::LazyCell,
9 collections::{HashMap, VecDeque},
10 hash::{DefaultHasher, Hash, Hasher},
11 sync::{
12 Arc,
13 atomic::{AtomicU64, Ordering},
14 },
15 thread::ThreadId,
16 time::Duration,
17};
18
19mod actions;
20#[cfg(feature = "profiler")]
21pub mod hang;
22#[cfg(feature = "profiler")]
23pub mod journal;
24pub use actions::{ActionStatistics, ActionTiming, take_action_stats};
25
26use serde::{Deserialize, Serialize};
27
28#[cfg(feature = "profiler")]
29use crate::{Action, App, WindowId};
30use crate::{SharedString, TasksIncluded};
31
32#[cfg(feature = "profiler")]
33#[doc(hidden)]
34pub fn get_all_timings(included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
35 ThreadTaskTimings::collect(upgraded_thread_timings(), included)
36}
37
38#[cfg(feature = "profiler")]
39#[doc(hidden)]
40pub fn get_current_thread_timings(included: TasksIncluded) -> gpui::ThreadTaskTimings {
41 gpui::profiler::get_current_thread_task_timings(included)
42}
43
44#[cfg(feature = "profiler")]
45#[doc(hidden)]
46pub fn take_all_stats(included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
47 ThreadTaskStatistics::collect_and_reset(upgraded_thread_timings(), included)
48}
49
50#[cfg(not(feature = "profiler"))]
51#[doc(hidden)]
52pub fn get_all_timings(_included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
53 Vec::new()
54}
55#[cfg(not(feature = "profiler"))]
56#[doc(hidden)]
57pub fn get_current_thread_timings(_included: TasksIncluded) -> gpui::ThreadTaskTimings {
58 gpui::ThreadTaskTimings {
59 thread_name: None,
60 thread_id: std::thread::current().id(),
61 timings: Vec::new(),
62 stats: TaskStatistics::default(),
63 total_pushed: 0,
64 }
65}
66#[cfg(not(feature = "profiler"))]
67#[doc(hidden)]
68pub fn take_all_stats(_included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
69 Vec::new()
70}
71
72#[doc(hidden)]
73#[derive(Debug, Copy, Clone)]
74pub struct YieldTime(pub Instant);
75
76#[doc(hidden)]
77#[derive(Copy, Clone)]
78pub struct TaskTiming {
79 pub location: &'static core::panic::Location<'static>,
80 pub spawned: SpawnTime,
81 pub start: Instant,
82 pub end: YieldTime,
83}
84
85impl std::fmt::Debug for TaskTiming {
86 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
87 f.debug_struct("TaskTiming")
88 .field("location", &self.location)
89 .field("since_spawned", &self.spawned.0.elapsed())
90 .field("last_poll_duration", &self.poll_duration())
91 .field("total_runtime", &self.since_spawn())
92 .finish()
93 }
94}
95
96#[doc(hidden)]
97#[derive(Debug, Copy, Clone)]
98pub struct ActiveTiming {
99 pub location: &'static core::panic::Location<'static>,
100 pub spawned: SpawnTime,
101 pub start: Instant,
102}
103
104impl TaskTiming {
105 pub fn placeholder() -> Self {
107 let now = Instant::now();
108 Self {
109 location: std::panic::Location::caller(),
110 spawned: SpawnTime(now),
111 start: now,
112 end: YieldTime(now),
113 }
114 }
115
116 #[inline(always)]
117 pub fn poll_duration(&self) -> Duration {
118 self.end.0 - self.start
119 }
120
121 #[inline(always)]
122 fn since_spawn(&self) -> Duration {
123 self.end.0 - self.spawned.0
124 }
125}
126
127#[doc(hidden)]
128#[derive(Debug, Clone)]
129pub struct ThreadTaskTimings {
130 pub thread_name: Option<String>,
131 pub thread_id: ThreadId,
132 pub timings: Vec<TaskTiming>,
133 pub stats: TaskStatistics,
134 pub total_pushed: u64,
135}
136
137impl ThreadTaskTimings {
138 pub fn collect(
140 timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
141 included: TasksIncluded,
142 ) -> Vec<Self> {
143 timings
144 .into_iter()
145 .map(|(thread_id, timings)| {
146 let timings = timings.lock();
147 let thread_name = timings.thread_name.clone();
148 let total_pushed = timings.total_pushed;
149 let completed = &timings.timings;
150
151 let mut vec = Vec::with_capacity(completed.len() + 1); let (s1, s2) = completed.as_slices();
153 vec.extend_from_slice(s1);
154 vec.extend_from_slice(s2);
155 if let TasksIncluded::CompletedAndRunning = included
156 && let Some(running) = timings.running
157 {
158 vec.push(TaskTiming {
159 location: running.location,
160 spawned: running.spawned,
161 start: running.start,
162 end: YieldTime(Instant::now()),
163 })
164 }
165
166 ThreadTaskTimings {
167 thread_name,
168 thread_id,
169 timings: vec,
170 stats: timings.stats.clone(),
171 total_pushed,
172 }
173 })
174 .collect()
175 }
176}
177
178#[doc(hidden)]
179#[derive(Debug)]
180pub struct ThreadTaskStatistics {
181 pub thread_name: Option<String>,
182 pub thread_id: ThreadId,
183 pub stats: TaskStatistics,
184}
185
186impl ThreadTaskStatistics {
187 pub fn collect_and_reset(
188 timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
189 include_running: TasksIncluded,
190 ) -> Vec<Self> {
191 timings
192 .into_iter()
193 .map(|(thread_id, timings)| {
194 let mut timings = timings.lock();
195 let thread_name = timings.thread_name.clone();
196
197 let mut stats = std::mem::take(&mut timings.stats);
198 if let TasksIncluded::CompletedAndRunning = include_running
199 && let Some(ActiveTiming {
200 location,
201 spawned,
202 start,
203 }) = timings.running
204 {
205 let end = YieldTime(Instant::now());
206 let timing = TaskTiming {
207 location,
208 spawned,
209 start,
210 end,
211 };
212 stats.add_runtime(timing);
213 stats.add_yield_timing(timing);
214 }
215
216 Self {
217 thread_name,
218 thread_id,
219 stats,
220 }
221 })
222 .collect()
223 }
224}
225
226#[derive(Debug, Clone, Serialize, Deserialize)]
228pub struct SerializedLocation {
229 pub file: SharedString,
231 pub line: u32,
233 pub column: u32,
235}
236
237impl From<&core::panic::Location<'static>> for SerializedLocation {
238 fn from(value: &core::panic::Location<'static>) -> Self {
239 SerializedLocation {
240 file: value.file().into(),
241 line: value.line(),
242 column: value.column(),
243 }
244 }
245}
246
247#[derive(Debug, Clone, Serialize, Deserialize)]
249pub struct SerializedTaskTiming {
250 pub location: SerializedLocation,
252 pub start: u128,
254 pub duration: u128,
256}
257
258impl SerializedTaskTiming {
259 pub fn convert(anchor: Instant, timings: &[TaskTiming]) -> Vec<SerializedTaskTiming> {
265 let serialized = timings
266 .iter()
267 .map(|timing| {
268 let start = timing.start.duration_since(anchor).as_nanos();
269 let duration = timing.end.0.duration_since(timing.start).as_nanos();
270 SerializedTaskTiming {
271 location: timing.location.into(),
272 start,
273 duration,
274 }
275 })
276 .collect::<Vec<_>>();
277
278 serialized
279 }
280
281 pub fn from(anchor: Instant, timing: TaskTiming) -> SerializedTaskTiming {
283 let start = timing.start.duration_since(anchor).as_nanos();
284 let duration = timing.end.0.duration_since(timing.start).as_nanos();
285 SerializedTaskTiming {
286 location: timing.location.into(),
287 start,
288 duration,
289 }
290 }
291}
292
293#[derive(Debug, Clone, Serialize, Deserialize)]
295pub struct SerializedThreadTaskTimings {
296 pub thread_name: Option<String>,
298 pub thread_id: u64,
300 pub timings: Vec<SerializedTaskTiming>,
302}
303
304impl SerializedThreadTaskTimings {
305 pub fn convert(anchor: Instant, timings: ThreadTaskTimings) -> SerializedThreadTaskTimings {
311 let serialized_timings = SerializedTaskTiming::convert(anchor, &timings.timings);
312
313 let mut hasher = DefaultHasher::new();
314 timings.thread_id.hash(&mut hasher);
315 let thread_id = hasher.finish();
316
317 SerializedThreadTaskTimings {
318 thread_name: timings.thread_name,
319 thread_id,
320 timings: serialized_timings,
321 }
322 }
323}
324
325#[doc(hidden)]
326#[derive(Debug, Clone)]
327pub struct ThreadTimingsDelta {
328 pub thread_id: u64,
330 pub thread_name: Option<String>,
332 pub new_timings: Vec<SerializedTaskTiming>,
335}
336
337#[doc(hidden)]
339pub struct ProfilingCollector {
340 startup_time: Instant,
341 cursors: HashMap<ThreadId, u64>,
342}
343
344impl ProfilingCollector {
345 pub fn new(startup_time: Instant) -> Self {
346 Self {
347 startup_time,
348 cursors: HashMap::default(),
349 }
350 }
351
352 pub fn startup_time(&self) -> Instant {
353 self.startup_time
354 }
355
356 pub fn collect_unseen(
357 &mut self,
358 all_timings: Vec<ThreadTaskTimings>,
359 ) -> Vec<ThreadTimingsDelta> {
360 let mut deltas = Vec::with_capacity(all_timings.len());
361
362 for thread in all_timings {
363 let mut hasher = DefaultHasher::new();
364 thread.thread_id.hash(&mut hasher);
365 let hashed_id = hasher.finish();
366
367 let prev_cursor = self.cursors.get(&thread.thread_id).copied().unwrap_or(0);
368 let buffer_len = thread.timings.len() as u64;
369 let buffer_start = thread.total_pushed.saturating_sub(buffer_len);
370
371 let mut slice = if prev_cursor < buffer_start {
372 thread.timings.as_slice()
375 } else {
376 let skip = (prev_cursor - buffer_start) as usize;
377 &thread.timings[skip.min(thread.timings.len())..]
378 };
379
380 let cursor_advance = thread.total_pushed;
381 self.cursors.insert(thread.thread_id, cursor_advance);
382
383 if slice.is_empty() {
384 continue;
385 }
386
387 let new_timings = SerializedTaskTiming::convert(self.startup_time, slice);
388
389 deltas.push(ThreadTimingsDelta {
390 thread_id: hashed_id,
391 thread_name: thread.thread_name,
392 new_timings,
393 });
394 }
395
396 deltas
397 }
398
399 pub fn reset(&mut self) {
400 self.cursors.clear();
401 }
402}
403
404#[cfg(feature = "profiler")]
408const MAX_TASK_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<TaskTiming>();
409
410#[doc(hidden)]
411pub(crate) type TaskTimings = VecDeque<TaskTiming>;
412
413#[doc(hidden)]
414pub type GuardedTaskTimings = spin::Mutex<ThreadTimings>;
415
416#[doc(hidden)]
417pub struct GlobalThreadTimings {
418 pub thread_id: ThreadId,
419 pub timings: std::sync::Weak<GuardedTaskTimings>,
420}
421
422#[doc(hidden)]
423#[derive(Debug, Clone)]
424pub struct TaskStatistics {
425 pub poll_time_to_beat: Duration,
426 pub runtime_to_beat: Duration,
427 pub longest_poll_times: [TaskTiming; 5],
428 pub longest_runtimes: [TaskTiming; 5],
429}
430
431impl std::fmt::Display for TaskStatistics {
432 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
433 f.write_str("Tasks that blocked the longest before yielding\n")?;
434 for timing in self.longest_poll_times {
435 f.write_fmt(format_args!(
436 "{:<20} - {}:{}\n",
437 format!("{:?}", timing.poll_duration()),
438 timing.location.file(),
439 timing.location.column()
440 ))?;
441 }
442 f.write_str("Tasks that ran the longest\n")?;
443 for timing in self.longest_runtimes {
444 f.write_fmt(format_args!(
445 "{:<20} - {}:{}\n",
446 format!("{:?}", timing.since_spawn()),
447 timing.location.file(),
448 timing.location.column()
449 ))?;
450 }
451 Ok(())
452 }
453}
454
455impl Default for TaskStatistics {
456 fn default() -> Self {
457 Self {
458 poll_time_to_beat: Duration::from_micros(100),
461 runtime_to_beat: Duration::from_micros(100),
462 longest_poll_times: [TaskTiming::placeholder(); 5],
463 longest_runtimes: [TaskTiming::placeholder(); 5],
464 }
465 }
466}
467
468impl TaskStatistics {
469 #[inline(always)]
470 fn add_yield_timing(&mut self, task: TaskTiming) {
471 let yielded_after = task.poll_duration();
472 if yielded_after >= self.poll_time_to_beat {
473 std::hint::cold_path(); let to_replace = self
475 .longest_poll_times
476 .iter()
477 .position_min_by_key(|task| task.since_spawn())
478 .expect("guarded by the comparison with nth_longest_yield_time");
479 self.longest_poll_times[to_replace] = task;
480
481 self.poll_time_to_beat = self
482 .longest_poll_times
483 .iter()
484 .map(|task| task.since_spawn())
485 .min()
486 .expect("never empty");
487 }
488 }
489
490 #[inline(always)]
491 fn add_runtime(&mut self, task: TaskTiming) {
492 let runtime = task.since_spawn();
493 if runtime >= self.runtime_to_beat {
494 std::hint::cold_path(); let to_replace = self
496 .longest_runtimes
497 .iter()
498 .position_min_by_key(|task| task.since_spawn())
499 .expect("guarded by the comparison with nth_longest_yield_time");
500 self.longest_runtimes[to_replace] = task;
501
502 self.runtime_to_beat = self
503 .longest_runtimes
504 .iter()
505 .map(|task| task.since_spawn())
506 .min()
507 .expect("never empty");
508 }
509 }
510}
511
512#[doc(hidden)]
513pub static GLOBAL_THREAD_TIMINGS: spin::Mutex<Vec<GlobalThreadTimings>> =
514 spin::Mutex::new(Vec::new());
515
516fn upgraded_thread_timings() -> Vec<(ThreadId, Arc<GuardedTaskTimings>)> {
526 let global_thread_timings = GLOBAL_THREAD_TIMINGS.lock();
527 global_thread_timings
528 .iter()
529 .filter_map(|t| Some((t.thread_id, t.timings.upgrade()?)))
530 .collect()
531}
532
533thread_local! {
534 #[doc(hidden)]
535 pub static THREAD_TIMINGS: LazyCell<Arc<GuardedTaskTimings>> = LazyCell::new(|| {
536 let current_thread = std::thread::current();
537 let thread_name = current_thread.name();
538 let thread_id = current_thread.id();
539 let timings = ThreadTimings::new(thread_name.map(|e| e.to_string()), thread_id);
540 let timings = Arc::new(spin::Mutex::new(timings));
541
542 {
543 let timings = Arc::downgrade(&timings);
544 let global_timings = GlobalThreadTimings {
545 thread_id: std::thread::current().id(),
546 timings,
547 };
548 GLOBAL_THREAD_TIMINGS.lock().push(global_timings);
549 }
550
551 timings
552 });
553}
554
555#[doc(hidden)]
556pub struct ThreadTimings {
557 pub thread_name: Option<String>,
558 pub thread_id: ThreadId,
559 pub timings: TaskTimings,
560 pub running: Option<ActiveTiming>,
561 pub stats: TaskStatistics,
562 pub total_pushed: u64,
563}
564
565impl ThreadTimings {
566 pub fn new(thread_name: Option<String>, thread_id: ThreadId) -> Self {
567 ThreadTimings {
568 thread_name,
569 thread_id,
570 timings: TaskTimings::new(),
571 stats: TaskStatistics::default(),
572 total_pushed: 0,
573 running: None,
574 }
575 }
576
577 #[cfg(feature = "profiler")]
578 pub fn update_running_task(
579 &mut self,
580 spawned: SpawnTime,
581 location: &'static std::panic::Location<'_>,
582 ) {
583 let start = Instant::now();
584 self.running = Some(ActiveTiming {
585 spawned,
586 location,
587 start,
588 });
589 }
590 #[cfg(not(feature = "profiler"))]
591 pub fn update_running_task(&mut self, _: SpawnTime, _: &'static std::panic::Location<'_>) {}
592
593 #[cfg(feature = "profiler")]
594 pub fn save_task_timing(&mut self, ended: YieldTime) -> TaskTiming {
595 let ActiveTiming {
596 location,
597 start,
598 spawned,
599 } = self
600 .running
601 .take()
602 .expect("this function is only ever called after register_task_start");
603
604 let timing = TaskTiming {
605 location,
606 spawned,
607 start,
608 end: ended,
609 };
610 self.stats.add_yield_timing(timing);
611 self.stats.add_runtime(timing);
612
613 if trace_enabled() {
614 std::hint::cold_path(); if self.timings.len() >= MAX_TASK_TIMINGS {
616 self.timings.pop_front();
617 }
618 self.timings.push_back(timing);
619 self.total_pushed += 1;
620 }
621 timing
622 }
623 #[cfg(not(feature = "profiler"))]
624 pub fn save_task_timing(&mut self, _: YieldTime) {}
625
626 pub fn get_thread_task_timings(&self, includes: TasksIncluded) -> ThreadTaskTimings {
629 ThreadTaskTimings {
630 thread_name: self.thread_name.clone(),
631 thread_id: self.thread_id,
632 timings: self
633 .timings
634 .iter()
635 .cloned()
636 .chain(
637 self.running
638 .filter(|_| matches!(includes, TasksIncluded::CompletedAndRunning))
639 .map(|running| TaskTiming {
640 spawned: running.spawned,
641 location: running.location,
642 start: running.start,
643 end: YieldTime(Instant::now()),
644 }),
645 )
646 .collect(),
647 stats: self.stats.clone(),
648 total_pushed: self.total_pushed,
649 }
650 }
651}
652
653impl Drop for ThreadTimings {
654 fn drop(&mut self) {
655 let mut thread_timings = GLOBAL_THREAD_TIMINGS.lock();
656
657 let Some((index, _)) = thread_timings
658 .iter()
659 .enumerate()
660 .find(|(_, t)| t.thread_id == self.thread_id)
661 else {
662 return;
663 };
664 thread_timings.swap_remove(index);
665 }
666}
667
668#[doc(hidden)]
669pub fn update_running_task(spawned: SpawnTime, location: &'static std::panic::Location<'_>) {
670 #[cfg(feature = "profiler")]
671 journal::begin_foreground_turn();
672 THREAD_TIMINGS.with(|timings| {
673 timings.lock().update_running_task(spawned, location);
674 });
675}
676
677#[doc(hidden)]
678pub fn save_task_timing() {
679 let yielded_at = YieldTime(Instant::now());
680 #[cfg(feature = "profiler")]
681 {
682 let timing = THREAD_TIMINGS.with(|timings| timings.lock().save_task_timing(yielded_at));
683 journal::record_task_poll(timing);
684 }
685 #[cfg(not(feature = "profiler"))]
686 THREAD_TIMINGS.with(|timings| {
687 timings.lock().save_task_timing(yielded_at);
688 });
689}
690
691pub fn install_profiler_hooks() {
698 gpui_platform::profiler::set_task_profiler(update_running_task, save_task_timing);
699}
700
701#[doc(hidden)]
702pub fn get_current_thread_task_timings(include_running: TasksIncluded) -> ThreadTaskTimings {
703 THREAD_TIMINGS.with(|timings| timings.lock().get_thread_task_timings(include_running))
704}
705
706const TRACE_SETTING_ENABLED: u64 = 1 << 63;
707const TRACE_SCOPE_COUNT_MASK: u64 = TRACE_SETTING_ENABLED - 1;
708static TRACE_STATE: AtomicU64 = AtomicU64::new(0);
709
710pub fn set_trace_enabled(enabled: bool) -> bool {
718 let mut state = TRACE_STATE.load(Ordering::Acquire);
719 loop {
720 let was_enabled = state & TRACE_SETTING_ENABLED != 0;
721 if was_enabled == enabled {
722 return false;
723 }
724
725 let next_state = if enabled {
726 state | TRACE_SETTING_ENABLED
727 } else {
728 state & TRACE_SCOPE_COUNT_MASK
729 };
730 match TRACE_STATE.compare_exchange_weak(
731 state,
732 next_state,
733 Ordering::AcqRel,
734 Ordering::Acquire,
735 ) {
736 Ok(_) => {
737 if next_state == 0 {
738 clear_trace_buffers();
739 }
740 return true;
741 }
742 Err(updated_state) => state = updated_state,
743 }
744 }
745}
746
747#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
748pub(crate) struct TraceGuard;
749
750#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
751pub(crate) fn trace_scope() -> TraceGuard {
752 let incremented = TRACE_STATE.fetch_update(Ordering::AcqRel, Ordering::Acquire, |state| {
753 (state & TRACE_SCOPE_COUNT_MASK < TRACE_SCOPE_COUNT_MASK).then_some(state + 1)
754 });
755 assert!(incremented.is_ok(), "too many active profiler trace scopes");
756 TraceGuard
757}
758
759#[cfg(any(feature = "bench-support", all(test, feature = "profiler")))]
760impl Drop for TraceGuard {
761 fn drop(&mut self) {
762 let previous_state =
763 TRACE_STATE.fetch_update(Ordering::AcqRel, Ordering::Acquire, |state| {
764 (state & TRACE_SCOPE_COUNT_MASK > 0).then_some(state - 1)
765 });
766 match previous_state {
767 Ok(1) => clear_trace_buffers(),
768 Ok(_) => {}
769 Err(_) => debug_assert!(false, "profiler trace scope count underflowed"),
770 }
771 }
772}
773
774pub fn trace_enabled() -> bool {
776 TRACE_STATE.load(Ordering::Relaxed) != 0
777}
778
779fn clear_trace_buffers() {
780 for (_, timings) in upgraded_thread_timings() {
781 let mut timings = timings.lock();
782 timings.timings.clear();
783 timings.timings.shrink_to_fit();
784 timings.total_pushed = 0;
785 }
786 #[cfg(feature = "profiler")]
787 {
788 let mut frames = FRAME_TIMINGS.lock();
789 frames.timings.clear();
790 frames.timings.shrink_to_fit();
791 frames.total_pushed = 0;
792 }
793}
794
795#[cfg(feature = "profiler")]
797#[derive(Debug, Copy, Clone)]
798pub struct FrameTiming {
799 pub window_id: WindowId,
801 pub dirty_at: Option<Instant>,
804 pub invalidations: u64,
806 pub draw_start: Instant,
808 pub draw_end: Instant,
810}
811
812#[cfg(feature = "profiler")]
813impl FrameTiming {
814 pub fn draw_duration(&self) -> Duration {
816 self.draw_end.duration_since(self.draw_start)
817 }
818
819 pub fn dirty_to_draw_duration(&self) -> Option<Duration> {
822 self.dirty_at
823 .map(|dirty_at| self.draw_end.duration_since(dirty_at))
824 }
825}
826
827#[cfg(feature = "profiler")]
829#[derive(Debug, Copy, Clone)]
830pub struct PresentTiming {
831 pub window_id: WindowId,
833 pub present_start: Instant,
835 pub present_end: Instant,
837 pub animation_interval: Option<Duration>,
840}
841
842#[cfg(feature = "profiler")]
843impl PresentTiming {
844 pub fn present_duration(&self) -> Duration {
846 self.present_end.duration_since(self.present_start)
847 }
848}
849
850#[cfg(feature = "profiler")]
852#[derive(Debug, Copy, Clone)]
853pub enum FrameEvent {
854 Draw(FrameTiming),
856 Present(PresentTiming),
858}
859
860#[cfg(feature = "profiler")]
863#[derive(Clone)]
864pub struct FrameDurationSnapshot {
865 pub dirty_to_present_histogram: Histogram<u64>,
867 pub draw_duration_histogram: Histogram<u64>,
869 pub present_interval_histogram: Histogram<u64>,
872}
873
874#[cfg(feature = "profiler")]
877#[derive(Clone)]
878pub struct InputLatencySnapshot {
879 pub latency_histogram: Histogram<u64>,
881 pub events_per_frame_histogram: Histogram<u64>,
883 pub mid_draw_events_dropped: u64,
886}
887
888#[cfg(feature = "profiler")]
889enum WindowActivity {
890 Input {
891 started_at: Instant,
892 kind: &'static str,
893 },
894 Draw {
895 started_at: Instant,
896 },
897}
898
899#[cfg(feature = "profiler")]
905pub struct WindowProfiler {
906 window_id: WindowId,
907 active_activities: SmallVec<[WindowActivity; 4]>,
908 active_actions: SmallVec<[(&'static str, Instant); 2]>,
909 dirty_to_present_histogram: Histogram<u64>,
910 draw_duration_histogram: Histogram<u64>,
911 present_interval_histogram: Histogram<u64>,
912 first_input_at: Option<Instant>,
913 pending_input_count: u64,
914 input_latency_histogram: Histogram<u64>,
915 events_per_frame_histogram: Histogram<u64>,
916 mid_draw_events_dropped: u64,
917 last_present_at: Option<Instant>,
918 animating_at_last_present: bool,
919 pending_frame: Option<FrameTiming>,
920}
921
922#[cfg(feature = "profiler")]
923impl WindowProfiler {
924 pub fn new(window_id: WindowId) -> anyhow::Result<Self> {
926 let profiler = Self {
927 window_id,
928 active_activities: SmallVec::new(),
929 active_actions: SmallVec::new(),
930 dirty_to_present_histogram: Histogram::new(3).map_err(|error| {
931 anyhow::anyhow!("Failed to create dirty-to-present histogram: {error}")
932 })?,
933 draw_duration_histogram: Histogram::new(3).map_err(|error| {
934 anyhow::anyhow!("Failed to create draw duration histogram: {error}")
935 })?,
936 present_interval_histogram: Histogram::new(3).map_err(|error| {
937 anyhow::anyhow!("Failed to create present interval histogram: {error}")
938 })?,
939 first_input_at: None,
940 pending_input_count: 0,
941 input_latency_histogram: Histogram::new(3).map_err(|error| {
942 anyhow::anyhow!("Failed to create input latency histogram: {error}")
943 })?,
944 events_per_frame_histogram: Histogram::new(3).map_err(|error| {
945 anyhow::anyhow!("Failed to create events per frame histogram: {error}")
946 })?,
947 mid_draw_events_dropped: 0,
948 last_present_at: None,
949 animating_at_last_present: false,
950 pending_frame: None,
951 };
952 journal::record_frame_pending(window_id, Instant::now());
953 Ok(profiler)
954 }
955
956 pub fn begin_input(&mut self, kind: &'static str) {
959 journal::begin_foreground_turn();
960 self.active_activities.push(WindowActivity::Input {
961 started_at: Instant::now(),
962 kind,
963 });
964 }
965
966 pub fn end_input(&mut self, caused_invalidation: bool) {
968 let Some(WindowActivity::Input { started_at, kind }) = self.active_activities.pop() else {
969 debug_assert!(false, "input activity must be the current window activity");
970 journal::end_foreground_turn();
971 return;
972 };
973
974 journal::record_input(journal::InputTiming {
975 kind,
976 start: started_at,
977 end: Instant::now(),
978 caused_invalidation,
979 });
980 journal::end_foreground_turn();
981
982 if !caused_invalidation {
983 return;
984 }
985
986 let arrived_during_draw = self
987 .active_activities
988 .iter()
989 .any(|activity| matches!(activity, WindowActivity::Draw { .. }));
990 if arrived_during_draw {
991 self.mid_draw_events_dropped += 1;
992 } else {
993 self.first_input_at.get_or_insert(started_at);
994 self.pending_input_count += 1;
995 }
996 }
997
998 pub fn begin_action_handler(&mut self, action: &(dyn Action + 'static), cx: &mut App) {
1000 journal::begin_foreground_turn();
1001 let name = actions::update_running_action(action, cx);
1002 self.active_actions.push((name, Instant::now()));
1003 }
1004
1005 pub fn end_action_handler(&mut self) {
1007 actions::save_action_timing();
1011 let Some((name, start)) = self.active_actions.pop() else {
1012 debug_assert!(false, "action handler must be begun before it ends");
1013 journal::end_foreground_turn();
1014 return;
1015 };
1016 journal::record_action(ActionTiming {
1017 name,
1018 start,
1019 end: Instant::now(),
1020 });
1021 journal::end_foreground_turn();
1022 }
1023
1024 pub fn begin_draw(&mut self) {
1026 journal::begin_foreground_turn();
1027 let started_at = Instant::now();
1028 journal::record_frame_pending(self.window_id, started_at);
1029 self.active_activities
1030 .push(WindowActivity::Draw { started_at });
1031 }
1032
1033 pub fn end_draw(&mut self, dirty_at: Option<Instant>, invalidations: u64) -> Duration {
1035 let Some(WindowActivity::Draw {
1036 started_at: draw_start,
1037 }) = self.active_activities.pop()
1038 else {
1039 debug_assert!(false, "draw activity must be the current window activity");
1040 journal::end_foreground_turn();
1041 return Duration::ZERO;
1042 };
1043
1044 let draw_end = Instant::now();
1045 let frame_timing = FrameTiming {
1046 window_id: self.window_id,
1047 dirty_at,
1048 invalidations,
1049 draw_start,
1050 draw_end,
1051 };
1052 let draw_duration = frame_timing.draw_duration();
1053 self.record_draw_timing(frame_timing);
1054 journal::end_foreground_turn();
1055 draw_duration
1056 }
1057
1058 pub fn record_present(
1063 &mut self,
1064 present_start: Instant,
1065 present_end: Instant,
1066 window_active: bool,
1067 next_frame_scheduled: bool,
1068 ) {
1069 self.record_present_at(
1070 present_start,
1071 present_end,
1072 window_active,
1073 next_frame_scheduled,
1074 );
1075 }
1076
1077 pub fn input_latency_snapshot(&self) -> InputLatencySnapshot {
1079 InputLatencySnapshot {
1080 latency_histogram: self.input_latency_histogram.clone(),
1081 events_per_frame_histogram: self.events_per_frame_histogram.clone(),
1082 mid_draw_events_dropped: self.mid_draw_events_dropped,
1083 }
1084 }
1085
1086 pub fn frame_duration_snapshot(&self) -> FrameDurationSnapshot {
1088 FrameDurationSnapshot {
1089 dirty_to_present_histogram: self.dirty_to_present_histogram.clone(),
1090 draw_duration_histogram: self.draw_duration_histogram.clone(),
1091 present_interval_histogram: self.present_interval_histogram.clone(),
1092 }
1093 }
1094
1095 fn record_present_at(
1096 &mut self,
1097 present_start: Instant,
1098 present_end: Instant,
1099 window_active: bool,
1100 next_frame_scheduled: bool,
1101 ) {
1102 if let Some(first_input_at) = self.first_input_at.take() {
1103 let latency_nanos = present_end.duration_since(first_input_at).as_nanos() as u64;
1104 self.input_latency_histogram.record(latency_nanos).ok();
1105 }
1106 if self.pending_input_count > 0 {
1107 self.events_per_frame_histogram
1108 .record(self.pending_input_count)
1109 .ok();
1110 self.pending_input_count = 0;
1111 }
1112
1113 let frame = self.pending_frame.take();
1114 let animation_interval =
1115 if frame.is_some() && self.animating_at_last_present && window_active {
1116 self.last_present_at
1117 .map(|last_present_at| present_end.duration_since(last_present_at))
1118 } else {
1119 None
1120 };
1121 let present_timing = PresentTiming {
1122 window_id: self.window_id,
1123 present_start,
1124 present_end,
1125 animation_interval,
1126 };
1127 journal::record_present(present_timing, frame);
1128
1129 let Some(frame) = frame else {
1130 return;
1131 };
1132
1133 if let Some(dirty_at) = frame.dirty_at
1134 && let Err(error) = self
1135 .dirty_to_present_histogram
1136 .record(present_end.duration_since(dirty_at).as_nanos() as u64)
1137 {
1138 log::error!("failed to record dirty-to-present frame timing: {error}");
1139 }
1140
1141 if let Some(animation_interval) = animation_interval {
1142 self.present_interval_histogram
1143 .record(animation_interval.as_nanos() as u64)
1144 .ok();
1145 }
1146 record_frame_event(FrameEvent::Present(present_timing));
1147
1148 self.last_present_at = Some(present_end);
1149 self.animating_at_last_present = next_frame_scheduled && window_active;
1150 }
1151
1152 fn record_draw_timing(&mut self, timing: FrameTiming) {
1153 self.record_draw_duration(timing.draw_duration());
1154 self.pending_frame = Some(timing);
1155 record_frame_event(FrameEvent::Draw(timing));
1156 journal::record_draw(timing);
1157 }
1158
1159 fn record_draw_duration(&mut self, duration: Duration) {
1160 self.draw_duration_histogram
1161 .record(duration.as_nanos() as u64)
1162 .ok();
1163 }
1164}
1165
1166#[cfg(feature = "profiler")]
1167impl Drop for WindowProfiler {
1168 fn drop(&mut self) {
1169 journal::record_window_closed(self.window_id);
1170 }
1171}
1172
1173#[cfg(feature = "profiler")]
1175const MAX_FRAME_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<FrameEvent>();
1176
1177#[cfg(feature = "profiler")]
1178struct FrameTimings {
1179 timings: VecDeque<FrameEvent>,
1180 total_pushed: u64,
1181}
1182
1183#[cfg(feature = "profiler")]
1184static FRAME_TIMINGS: spin::Mutex<FrameTimings> = spin::Mutex::new(FrameTimings {
1185 timings: VecDeque::new(),
1186 total_pushed: 0,
1187});
1188
1189#[cfg(feature = "profiler")]
1193pub fn record_frame_event(event: FrameEvent) {
1194 if !trace_enabled() {
1195 return;
1196 }
1197 std::hint::cold_path(); let mut frames = FRAME_TIMINGS.lock();
1200 if frames.timings.len() >= MAX_FRAME_TIMINGS {
1201 frames.timings.pop_front();
1202 }
1203 frames.timings.push_back(event);
1204 frames.total_pushed += 1;
1205}
1206
1207#[cfg(feature = "profiler")]
1210pub struct FrameTimingCollector {
1211 cursor: u64,
1212}
1213
1214#[cfg(feature = "profiler")]
1215impl Default for FrameTimingCollector {
1216 fn default() -> Self {
1217 Self::new()
1218 }
1219}
1220
1221#[cfg(feature = "profiler")]
1222impl FrameTimingCollector {
1223 pub fn new() -> Self {
1225 Self {
1226 cursor: FRAME_TIMINGS.lock().total_pushed,
1227 }
1228 }
1229
1230 pub fn collect_unseen(&mut self) -> Vec<FrameEvent> {
1234 let frames = FRAME_TIMINGS.lock();
1235 let buffer_len = frames.timings.len() as u64;
1236 let buffer_start = frames.total_pushed.saturating_sub(buffer_len);
1237 let skip = self.cursor.saturating_sub(buffer_start) as usize;
1238 let unseen = frames
1239 .timings
1240 .iter()
1241 .skip(skip.min(frames.timings.len()))
1242 .copied()
1243 .collect();
1244 self.cursor = frames.total_pushed;
1245 unseen
1246 }
1247}
1248
1249#[cfg(all(test, any(feature = "profiler", feature = "bench-support")))]
1256pub(crate) fn trace_test_lock() -> std::sync::MutexGuard<'static, ()> {
1257 static TRACE_TEST_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(());
1258 TRACE_TEST_LOCK
1259 .lock()
1260 .unwrap_or_else(|poisoned| poisoned.into_inner())
1261}
1262
1263#[cfg(all(test, feature = "profiler"))]
1264mod tests {
1265 use super::*;
1266 use std::sync::MutexGuard;
1267
1268 #[test]
1269 fn records_draw_events_only_while_tracing() {
1270 let _trace_test_guard = TraceTestGuard::new();
1271 let window_id = WindowId::from(0xD0A0);
1272 let mut window_profiler =
1273 WindowProfiler::new(window_id).expect("window profiler should initialize");
1274 let dirty_at = Instant::now();
1275 let mut collector = FrameTimingCollector::new();
1276
1277 window_profiler.begin_draw();
1278 window_profiler.end_draw(Some(dirty_at), 3);
1279 assert!(
1280 collector
1281 .collect_unseen()
1282 .iter()
1283 .all(|event| !event_matches_window(*event, window_id))
1284 );
1285
1286 set_trace_enabled(true);
1287 let mut collector = FrameTimingCollector::new();
1288 window_profiler.begin_draw();
1289 window_profiler.end_draw(Some(dirty_at), 3);
1290
1291 let timing = collector
1292 .collect_unseen()
1293 .into_iter()
1294 .find_map(|event| match event {
1295 FrameEvent::Draw(timing) if timing.window_id == window_id => Some(timing),
1296 _ => None,
1297 })
1298 .expect("draw event should be recorded while tracing");
1299 assert_eq!(timing.dirty_at, Some(dirty_at));
1300 assert_eq!(timing.invalidations, 3);
1301 assert!(timing.draw_start >= dirty_at);
1302 }
1303
1304 #[test]
1305 fn records_present_events_for_newly_drawn_frames() {
1306 let _trace_test_guard = TraceTestGuard::new();
1307 set_trace_enabled(true);
1308 let window_id = WindowId::from(0xA11E);
1309 let mut window_profiler =
1310 WindowProfiler::new(window_id).expect("window profiler should initialize");
1311 let start = Instant::now();
1312 let mut collector = FrameTimingCollector::new();
1313
1314 record_test_draw(&mut window_profiler, start);
1315 window_profiler.record_present_at(start, start, true, true);
1316 record_test_draw(&mut window_profiler, start + FRAME);
1317 window_profiler.record_present_at(start + FRAME, start + FRAME, true, true);
1318 window_profiler.record_present_at(
1319 start + FRAME + FRAME / 2,
1320 start + FRAME + FRAME / 2,
1321 true,
1322 true,
1323 );
1324
1325 let present_timings = collector
1326 .collect_unseen()
1327 .into_iter()
1328 .filter_map(|event| match event {
1329 FrameEvent::Present(timing) if timing.window_id == window_id => Some(timing),
1330 _ => None,
1331 })
1332 .collect::<Vec<_>>();
1333 let [first_present, second_present] = present_timings.as_slice() else {
1334 panic!("expected exactly two present events, got {present_timings:?}");
1335 };
1336 assert_eq!(first_present.animation_interval, None);
1337 assert_eq!(second_present.animation_interval, Some(FRAME));
1338
1339 #[cfg(feature = "profiler")]
1340 {
1341 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
1342 assert!(
1343 window_profiler.present_interval_histogram.max()
1344 >= second_present
1345 .animation_interval
1346 .expect("second present should have an animation interval")
1347 .as_nanos() as u64
1348 );
1349 }
1350 }
1351
1352 #[test]
1353 fn disabling_tracing_clears_frame_events() {
1354 let _trace_test_guard = TraceTestGuard::new();
1355 set_trace_enabled(true);
1356 let window_id = WindowId::from(0xC1EA);
1357 let mut window_profiler =
1358 WindowProfiler::new(window_id).expect("window profiler should initialize");
1359 let mut collector = FrameTimingCollector::new();
1360
1361 window_profiler.begin_draw();
1362 window_profiler.end_draw(None, 0);
1363 assert!(
1364 FRAME_TIMINGS
1365 .lock()
1366 .timings
1367 .iter()
1368 .copied()
1369 .any(|event| event_matches_window(event, window_id))
1370 );
1371
1372 set_trace_enabled(false);
1373 assert!(
1374 collector
1375 .collect_unseen()
1376 .iter()
1377 .all(|event| !event_matches_window(*event, window_id))
1378 );
1379 }
1380
1381 #[cfg(feature = "profiler")]
1382 #[test]
1383 fn records_intervals_only_between_animation_frames() {
1384 let mut window_profiler =
1385 WindowProfiler::new(WindowId::from(1)).expect("window profiler should initialize");
1386 let start = Instant::now();
1387
1388 draw_and_present(&mut window_profiler, start, true, true);
1389 assert_eq!(window_profiler.present_interval_histogram.len(), 0);
1390
1391 draw_and_present(&mut window_profiler, start + FRAME, true, true);
1392 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
1393
1394 draw_and_present(&mut window_profiler, start + FRAME * 2, true, false);
1395 assert_eq!(window_profiler.present_interval_histogram.len(), 2);
1396
1397 draw_and_present(&mut window_profiler, start + FRAME * 100, true, true);
1398 assert_eq!(window_profiler.present_interval_histogram.len(), 2);
1399 }
1400
1401 #[cfg(feature = "profiler")]
1402 #[test]
1403 fn missed_frames_stretch_the_recorded_interval() {
1404 let mut window_profiler =
1405 WindowProfiler::new(WindowId::from(2)).expect("window profiler should initialize");
1406 let start = Instant::now();
1407
1408 draw_and_present(&mut window_profiler, start, true, true);
1409 draw_and_present(&mut window_profiler, start + FRAME * 5, true, true);
1410
1411 let recorded = window_profiler.present_interval_histogram.max();
1412 assert!(recorded >= (FRAME * 4).as_nanos() as u64);
1413 }
1414
1415 #[cfg(feature = "profiler")]
1416 #[test]
1417 fn ignores_re_presents_of_unchanged_frames() {
1418 let mut window_profiler =
1419 WindowProfiler::new(WindowId::from(3)).expect("window profiler should initialize");
1420 let start = Instant::now();
1421
1422 draw_and_present(&mut window_profiler, start, true, true);
1423 window_profiler.record_present_at(start + FRAME / 2, start + FRAME / 2, true, true);
1424 draw_and_present(&mut window_profiler, start + FRAME, true, true);
1425
1426 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
1427 assert!(
1428 window_profiler.present_interval_histogram.max() >= (FRAME * 3 / 4).as_nanos() as u64
1429 );
1430 }
1431
1432 #[cfg(feature = "profiler")]
1433 #[test]
1434 fn skips_intervals_for_inactive_windows() {
1435 let mut window_profiler =
1436 WindowProfiler::new(WindowId::from(4)).expect("window profiler should initialize");
1437 let start = Instant::now();
1438
1439 draw_and_present(&mut window_profiler, start, false, true);
1440 draw_and_present(&mut window_profiler, start + FRAME, false, true);
1441 assert_eq!(window_profiler.present_interval_histogram.len(), 0);
1442
1443 draw_and_present(&mut window_profiler, start + FRAME * 2, true, true);
1444 assert_eq!(window_profiler.present_interval_histogram.len(), 0);
1445
1446 draw_and_present(&mut window_profiler, start + FRAME * 3, true, true);
1447 assert_eq!(window_profiler.present_interval_histogram.len(), 1);
1448 }
1449
1450 #[test]
1451 fn records_dirty_to_present_durations() {
1452 let mut window_profiler =
1453 WindowProfiler::new(WindowId::from(8)).expect("window profiler should initialize");
1454 let draw_end = Instant::now();
1455 let present_end = draw_end + Duration::from_millis(6);
1456
1457 record_test_draw(&mut window_profiler, draw_end);
1458 window_profiler.record_present_at(present_end, present_end, true, false);
1459
1460 let snapshot = window_profiler.frame_duration_snapshot();
1461 let histogram = snapshot.dirty_to_present_histogram;
1462 assert_eq!(histogram.len(), 1);
1463 assert!(histogram.max() >= Duration::from_millis(10).as_nanos() as u64);
1464 }
1465
1466 #[cfg(feature = "profiler")]
1467 #[test]
1468 fn records_every_draw_duration() {
1469 let mut window_profiler =
1470 WindowProfiler::new(WindowId::from(5)).expect("window profiler should initialize");
1471
1472 window_profiler.record_draw_duration(Duration::from_millis(2));
1473 window_profiler.record_draw_duration(Duration::from_millis(40));
1474
1475 let snapshot = window_profiler.frame_duration_snapshot();
1476 assert_eq!(snapshot.draw_duration_histogram.len(), 2);
1477 assert!(snapshot.draw_duration_histogram.max() >= 39_000_000);
1478 }
1479
1480 #[test]
1481 fn records_input_latency_at_the_frame_presentation_timestamp() {
1482 let mut window_profiler =
1483 WindowProfiler::new(WindowId::from(6)).expect("window profiler should initialize");
1484 let first_input_at = Instant::now();
1485 let presented_at = first_input_at + Duration::from_millis(12);
1486
1487 begin_input_at(&mut window_profiler, first_input_at);
1488 window_profiler.end_input(true);
1489 begin_input_at(
1490 &mut window_profiler,
1491 first_input_at + Duration::from_millis(2),
1492 );
1493 window_profiler.end_input(true);
1494 record_test_draw(&mut window_profiler, presented_at);
1495 window_profiler.record_present_at(presented_at, presented_at, true, false);
1496
1497 let snapshot = window_profiler.input_latency_snapshot();
1498 assert_eq!(snapshot.latency_histogram.len(), 1);
1499 assert!(snapshot.latency_histogram.max() >= Duration::from_millis(12).as_nanos() as u64);
1500 assert_eq!(snapshot.events_per_frame_histogram.len(), 1);
1501 assert_eq!(snapshot.events_per_frame_histogram.max(), 2);
1502 assert_eq!(snapshot.mid_draw_events_dropped, 0);
1503 }
1504
1505 #[test]
1506 fn excludes_input_that_arrives_during_a_draw() {
1507 let mut window_profiler =
1508 WindowProfiler::new(WindowId::from(7)).expect("window profiler should initialize");
1509
1510 window_profiler.begin_draw();
1511 begin_input_at(&mut window_profiler, Instant::now());
1512 window_profiler.end_input(true);
1513 window_profiler.end_draw(None, 0);
1514
1515 let snapshot = window_profiler.input_latency_snapshot();
1516 assert!(snapshot.latency_histogram.is_empty());
1517 assert!(snapshot.events_per_frame_histogram.is_empty());
1518 assert_eq!(snapshot.mid_draw_events_dropped, 1);
1519 }
1520
1521 #[test]
1522 fn overlapping_trace_scopes_keep_tracing_enabled() {
1523 let _trace_test_guard = TraceTestGuard::new();
1524 let first_scope = trace_scope();
1525 let second_scope = trace_scope();
1526
1527 assert!(trace_enabled());
1528 drop(first_scope);
1529 assert!(trace_enabled());
1530 drop(second_scope);
1531 assert!(!trace_enabled());
1532 }
1533
1534 const FRAME: Duration = Duration::from_millis(16);
1535
1536 struct TraceTestGuard {
1537 was_enabled: bool,
1538 _lock: MutexGuard<'static, ()>,
1539 }
1540
1541 impl TraceTestGuard {
1542 fn new() -> Self {
1543 let lock = super::trace_test_lock();
1544 let was_enabled = trace_enabled();
1545 set_trace_enabled(false);
1546 Self {
1547 was_enabled,
1548 _lock: lock,
1549 }
1550 }
1551 }
1552
1553 impl Drop for TraceTestGuard {
1554 fn drop(&mut self) {
1555 set_trace_enabled(false);
1556 if self.was_enabled {
1557 set_trace_enabled(true);
1558 }
1559 }
1560 }
1561
1562 fn event_matches_window(event: FrameEvent, window_id: WindowId) -> bool {
1563 match event {
1564 FrameEvent::Draw(timing) => timing.window_id == window_id,
1565 FrameEvent::Present(timing) => timing.window_id == window_id,
1566 }
1567 }
1568
1569 fn begin_input_at(window_profiler: &mut WindowProfiler, started_at: Instant) {
1570 window_profiler
1571 .active_activities
1572 .push(WindowActivity::Input {
1573 started_at,
1574 kind: "test",
1575 });
1576 }
1577
1578 #[cfg(feature = "profiler")]
1579 fn draw_and_present(
1580 window_profiler: &mut WindowProfiler,
1581 presented_at: Instant,
1582 window_active: bool,
1583 next_frame_scheduled: bool,
1584 ) {
1585 record_test_draw(window_profiler, presented_at);
1586 window_profiler.record_present_at(
1587 presented_at,
1588 presented_at,
1589 window_active,
1590 next_frame_scheduled,
1591 );
1592 }
1593
1594 fn record_test_draw(window_profiler: &mut WindowProfiler, draw_end: Instant) {
1595 window_profiler.record_draw_timing(FrameTiming {
1596 window_id: window_profiler.window_id,
1597 dirty_at: Some(draw_end - Duration::from_millis(4)),
1598 invalidations: 1,
1599 draw_start: draw_end - Duration::from_millis(2),
1600 draw_end,
1601 });
1602 }
1603}