1use itertools::Itertools;
2use scheduler::{Instant, SpawnTime};
3use std::{
4 cell::LazyCell,
5 collections::{HashMap, VecDeque},
6 hash::{DefaultHasher, Hash, Hasher},
7 sync::{
8 Arc,
9 atomic::{AtomicBool, Ordering},
10 },
11 thread::ThreadId,
12 time::Duration,
13};
14
15mod actions;
16pub use actions::{ActionStatistics, ActionTiming, take_action_stats};
17pub(crate) use actions::{save_action_timing, update_running_action};
18
19use serde::{Deserialize, Serialize};
20
21use crate::{SharedString, TasksIncluded, WindowId};
22
23#[cfg(feature = "profiler")]
24#[doc(hidden)]
25pub fn get_all_timings(included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
26 ThreadTaskTimings::collect(upgraded_thread_timings(), included)
27}
28
29#[cfg(feature = "profiler")]
30#[doc(hidden)]
31pub fn get_current_thread_timings(included: TasksIncluded) -> gpui::ThreadTaskTimings {
32 gpui::profiler::get_current_thread_task_timings(included)
33}
34
35#[cfg(feature = "profiler")]
36#[doc(hidden)]
37pub fn take_all_stats(included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
38 ThreadTaskStatistics::collect_and_reset(upgraded_thread_timings(), included)
39}
40
41#[cfg(not(feature = "profiler"))]
42#[doc(hidden)]
43pub fn get_all_timings(_included: gpui::TasksIncluded) -> Vec<gpui::ThreadTaskTimings> {
44 Vec::new()
45}
46#[cfg(not(feature = "profiler"))]
47#[doc(hidden)]
48pub fn get_current_thread_timings(_included: TasksIncluded) -> gpui::ThreadTaskTimings {
49 gpui::ThreadTaskTimings {
50 thread_name: None,
51 thread_id: std::thread::current().id(),
52 timings: Vec::new(),
53 stats: TaskStatistics::default(),
54 total_pushed: 0,
55 }
56}
57#[cfg(not(feature = "profiler"))]
58#[doc(hidden)]
59pub fn take_all_stats(_included: TasksIncluded) -> Vec<gpui::ThreadTaskStatistics> {
60 Vec::new()
61}
62
63#[doc(hidden)]
64#[derive(Debug, Copy, Clone)]
65pub struct YieldTime(pub Instant);
66
67#[doc(hidden)]
68#[derive(Copy, Clone)]
69pub struct TaskTiming {
70 pub location: &'static core::panic::Location<'static>,
71 pub spawned: SpawnTime,
72 pub start: Instant,
73 pub end: YieldTime,
74}
75
76impl std::fmt::Debug for TaskTiming {
77 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
78 f.debug_struct("TaskTiming")
79 .field("location", &self.location)
80 .field("since_spawned", &self.spawned.0.elapsed())
81 .field("last_poll_duration", &self.poll_duration())
82 .field("total_runtime", &self.since_spawn())
83 .finish()
84 }
85}
86
87#[doc(hidden)]
88#[derive(Debug, Copy, Clone)]
89pub struct ActiveTiming {
90 pub location: &'static core::panic::Location<'static>,
91 pub spawned: SpawnTime,
92 pub start: Instant,
93}
94
95impl TaskTiming {
96 pub fn placeholder() -> Self {
98 let now = Instant::now();
99 Self {
100 location: std::panic::Location::caller(),
101 spawned: SpawnTime(now),
102 start: now,
103 end: YieldTime(now),
104 }
105 }
106
107 #[inline(always)]
108 pub fn poll_duration(&self) -> Duration {
109 self.end.0 - self.start
110 }
111
112 #[inline(always)]
113 fn since_spawn(&self) -> Duration {
114 self.end.0 - self.spawned.0
115 }
116}
117
118#[doc(hidden)]
119#[derive(Debug, Clone)]
120pub struct ThreadTaskTimings {
121 pub thread_name: Option<String>,
122 pub thread_id: ThreadId,
123 pub timings: Vec<TaskTiming>,
124 pub stats: TaskStatistics,
125 pub total_pushed: u64,
126}
127
128impl ThreadTaskTimings {
129 pub fn collect(
131 timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
132 included: TasksIncluded,
133 ) -> Vec<Self> {
134 timings
135 .into_iter()
136 .map(|(thread_id, timings)| {
137 let timings = timings.lock();
138 let thread_name = timings.thread_name.clone();
139 let total_pushed = timings.total_pushed;
140 let completed = &timings.timings;
141
142 let mut vec = Vec::with_capacity(completed.len() + 1); let (s1, s2) = completed.as_slices();
144 vec.extend_from_slice(s1);
145 vec.extend_from_slice(s2);
146 if let TasksIncluded::CompletedAndRunning = included
147 && let Some(running) = timings.running
148 {
149 vec.push(TaskTiming {
150 location: running.location,
151 spawned: running.spawned,
152 start: running.start,
153 end: YieldTime(Instant::now()),
154 })
155 }
156
157 ThreadTaskTimings {
158 thread_name,
159 thread_id,
160 timings: vec,
161 stats: timings.stats.clone(),
162 total_pushed,
163 }
164 })
165 .collect()
166 }
167}
168
169#[doc(hidden)]
170#[derive(Debug)]
171pub struct ThreadTaskStatistics {
172 pub thread_name: Option<String>,
173 pub thread_id: ThreadId,
174 pub stats: TaskStatistics,
175}
176
177impl ThreadTaskStatistics {
178 pub fn collect_and_reset(
179 timings: Vec<(ThreadId, Arc<GuardedTaskTimings>)>,
180 include_running: TasksIncluded,
181 ) -> Vec<Self> {
182 timings
183 .into_iter()
184 .map(|(thread_id, timings)| {
185 let mut timings = timings.lock();
186 let thread_name = timings.thread_name.clone();
187
188 let mut stats = std::mem::take(&mut timings.stats);
189 if let TasksIncluded::CompletedAndRunning = include_running
190 && let Some(ActiveTiming {
191 location,
192 spawned,
193 start,
194 }) = timings.running
195 {
196 let end = YieldTime(Instant::now());
197 let timing = TaskTiming {
198 location,
199 spawned,
200 start,
201 end,
202 };
203 stats.add_runtime(timing);
204 stats.add_yield_timing(timing);
205 }
206
207 Self {
208 thread_name,
209 thread_id,
210 stats,
211 }
212 })
213 .collect()
214 }
215}
216
217#[derive(Debug, Clone, Serialize, Deserialize)]
219pub struct SerializedLocation {
220 pub file: SharedString,
222 pub line: u32,
224 pub column: u32,
226}
227
228impl From<&core::panic::Location<'static>> for SerializedLocation {
229 fn from(value: &core::panic::Location<'static>) -> Self {
230 SerializedLocation {
231 file: value.file().into(),
232 line: value.line(),
233 column: value.column(),
234 }
235 }
236}
237
238#[derive(Debug, Clone, Serialize, Deserialize)]
240pub struct SerializedTaskTiming {
241 pub location: SerializedLocation,
243 pub start: u128,
245 pub duration: u128,
247}
248
249impl SerializedTaskTiming {
250 pub fn convert(anchor: Instant, timings: &[TaskTiming]) -> Vec<SerializedTaskTiming> {
256 let serialized = timings
257 .iter()
258 .map(|timing| {
259 let start = timing.start.duration_since(anchor).as_nanos();
260 let duration = timing.end.0.duration_since(timing.start).as_nanos();
261 SerializedTaskTiming {
262 location: timing.location.into(),
263 start,
264 duration,
265 }
266 })
267 .collect::<Vec<_>>();
268
269 serialized
270 }
271
272 pub fn from(anchor: Instant, timing: TaskTiming) -> SerializedTaskTiming {
274 let start = timing.start.duration_since(anchor).as_nanos();
275 let duration = timing.end.0.duration_since(timing.start).as_nanos();
276 SerializedTaskTiming {
277 location: timing.location.into(),
278 start,
279 duration,
280 }
281 }
282}
283
284#[derive(Debug, Clone, Serialize, Deserialize)]
286pub struct SerializedThreadTaskTimings {
287 pub thread_name: Option<String>,
289 pub thread_id: u64,
291 pub timings: Vec<SerializedTaskTiming>,
293}
294
295impl SerializedThreadTaskTimings {
296 pub fn convert(anchor: Instant, timings: ThreadTaskTimings) -> SerializedThreadTaskTimings {
302 let serialized_timings = SerializedTaskTiming::convert(anchor, &timings.timings);
303
304 let mut hasher = DefaultHasher::new();
305 timings.thread_id.hash(&mut hasher);
306 let thread_id = hasher.finish();
307
308 SerializedThreadTaskTimings {
309 thread_name: timings.thread_name,
310 thread_id,
311 timings: serialized_timings,
312 }
313 }
314}
315
316#[doc(hidden)]
317#[derive(Debug, Clone)]
318pub struct ThreadTimingsDelta {
319 pub thread_id: u64,
321 pub thread_name: Option<String>,
323 pub new_timings: Vec<SerializedTaskTiming>,
326}
327
328#[doc(hidden)]
330pub struct ProfilingCollector {
331 startup_time: Instant,
332 cursors: HashMap<ThreadId, u64>,
333}
334
335impl ProfilingCollector {
336 pub fn new(startup_time: Instant) -> Self {
337 Self {
338 startup_time,
339 cursors: HashMap::default(),
340 }
341 }
342
343 pub fn startup_time(&self) -> Instant {
344 self.startup_time
345 }
346
347 pub fn collect_unseen(
348 &mut self,
349 all_timings: Vec<ThreadTaskTimings>,
350 ) -> Vec<ThreadTimingsDelta> {
351 let mut deltas = Vec::with_capacity(all_timings.len());
352
353 for thread in all_timings {
354 let mut hasher = DefaultHasher::new();
355 thread.thread_id.hash(&mut hasher);
356 let hashed_id = hasher.finish();
357
358 let prev_cursor = self.cursors.get(&thread.thread_id).copied().unwrap_or(0);
359 let buffer_len = thread.timings.len() as u64;
360 let buffer_start = thread.total_pushed.saturating_sub(buffer_len);
361
362 let mut slice = if prev_cursor < buffer_start {
363 thread.timings.as_slice()
366 } else {
367 let skip = (prev_cursor - buffer_start) as usize;
368 &thread.timings[skip.min(thread.timings.len())..]
369 };
370
371 let cursor_advance = thread.total_pushed;
372 self.cursors.insert(thread.thread_id, cursor_advance);
373
374 if slice.is_empty() {
375 continue;
376 }
377
378 let new_timings = SerializedTaskTiming::convert(self.startup_time, slice);
379
380 deltas.push(ThreadTimingsDelta {
381 thread_id: hashed_id,
382 thread_name: thread.thread_name,
383 new_timings,
384 });
385 }
386
387 deltas
388 }
389
390 pub fn reset(&mut self) {
391 self.cursors.clear();
392 }
393}
394
395#[cfg(feature = "profiler")]
399const MAX_TASK_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<TaskTiming>();
400
401#[doc(hidden)]
402pub(crate) type TaskTimings = VecDeque<TaskTiming>;
403
404#[doc(hidden)]
405pub type GuardedTaskTimings = spin::Mutex<ThreadTimings>;
406
407#[doc(hidden)]
408pub struct GlobalThreadTimings {
409 pub thread_id: ThreadId,
410 pub timings: std::sync::Weak<GuardedTaskTimings>,
411}
412
413#[doc(hidden)]
414#[derive(Debug, Clone)]
415pub struct TaskStatistics {
416 pub poll_time_to_beat: Duration,
417 pub runtime_to_beat: Duration,
418 pub longest_poll_times: [TaskTiming; 5],
419 pub longest_runtimes: [TaskTiming; 5],
420}
421
422impl std::fmt::Display for TaskStatistics {
423 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
424 f.write_str("Tasks that blocked the longest before yielding\n")?;
425 for timing in self.longest_poll_times {
426 f.write_fmt(format_args!(
427 "{:<20} - {}:{}\n",
428 format!("{:?}", timing.poll_duration()),
429 timing.location.file(),
430 timing.location.column()
431 ))?;
432 }
433 f.write_str("Tasks that ran the longest\n")?;
434 for timing in self.longest_runtimes {
435 f.write_fmt(format_args!(
436 "{:<20} - {}:{}\n",
437 format!("{:?}", timing.since_spawn()),
438 timing.location.file(),
439 timing.location.column()
440 ))?;
441 }
442 Ok(())
443 }
444}
445
446impl Default for TaskStatistics {
447 fn default() -> Self {
448 Self {
449 poll_time_to_beat: Duration::from_micros(100),
452 runtime_to_beat: Duration::from_micros(100),
453 longest_poll_times: [TaskTiming::placeholder(); 5],
454 longest_runtimes: [TaskTiming::placeholder(); 5],
455 }
456 }
457}
458
459impl TaskStatistics {
460 #[inline(always)]
461 fn add_yield_timing(&mut self, task: TaskTiming) {
462 let yielded_after = task.poll_duration();
463 if yielded_after >= self.poll_time_to_beat {
464 std::hint::cold_path(); let to_replace = self
466 .longest_poll_times
467 .iter()
468 .position_min_by_key(|task| task.since_spawn())
469 .expect("guarded by the comparison with nth_longest_yield_time");
470 self.longest_poll_times[to_replace] = task;
471
472 self.poll_time_to_beat = self
473 .longest_poll_times
474 .iter()
475 .map(|task| task.since_spawn())
476 .min()
477 .expect("never empty");
478 }
479 }
480
481 #[inline(always)]
482 fn add_runtime(&mut self, task: TaskTiming) {
483 let runtime = task.since_spawn();
484 if runtime >= self.runtime_to_beat {
485 std::hint::cold_path(); let to_replace = self
487 .longest_runtimes
488 .iter()
489 .position_min_by_key(|task| task.since_spawn())
490 .expect("guarded by the comparison with nth_longest_yield_time");
491 self.longest_runtimes[to_replace] = task;
492
493 self.runtime_to_beat = self
494 .longest_runtimes
495 .iter()
496 .map(|task| task.since_spawn())
497 .min()
498 .expect("never empty");
499 }
500 }
501}
502
503#[doc(hidden)]
504pub static GLOBAL_THREAD_TIMINGS: spin::Mutex<Vec<GlobalThreadTimings>> =
505 spin::Mutex::new(Vec::new());
506
507fn upgraded_thread_timings() -> Vec<(ThreadId, Arc<GuardedTaskTimings>)> {
517 let global_thread_timings = GLOBAL_THREAD_TIMINGS.lock();
518 global_thread_timings
519 .iter()
520 .filter_map(|t| Some((t.thread_id, t.timings.upgrade()?)))
521 .collect()
522}
523
524thread_local! {
525 #[doc(hidden)]
526 pub static THREAD_TIMINGS: LazyCell<Arc<GuardedTaskTimings>> = LazyCell::new(|| {
527 let current_thread = std::thread::current();
528 let thread_name = current_thread.name();
529 let thread_id = current_thread.id();
530 let timings = ThreadTimings::new(thread_name.map(|e| e.to_string()), thread_id);
531 let timings = Arc::new(spin::Mutex::new(timings));
532
533 {
534 let timings = Arc::downgrade(&timings);
535 let global_timings = GlobalThreadTimings {
536 thread_id: std::thread::current().id(),
537 timings,
538 };
539 GLOBAL_THREAD_TIMINGS.lock().push(global_timings);
540 }
541
542 timings
543 });
544}
545
546#[doc(hidden)]
547pub struct ThreadTimings {
548 pub thread_name: Option<String>,
549 pub thread_id: ThreadId,
550 pub timings: TaskTimings,
551 pub running: Option<ActiveTiming>,
552 pub stats: TaskStatistics,
553 pub total_pushed: u64,
554}
555
556impl ThreadTimings {
557 pub fn new(thread_name: Option<String>, thread_id: ThreadId) -> Self {
558 ThreadTimings {
559 thread_name,
560 thread_id,
561 timings: TaskTimings::new(),
562 stats: TaskStatistics::default(),
563 total_pushed: 0,
564 running: None,
565 }
566 }
567
568 #[cfg(feature = "profiler")]
569 pub fn update_running_task(
570 &mut self,
571 spawned: SpawnTime,
572 location: &'static std::panic::Location<'_>,
573 ) {
574 let start = Instant::now();
575 self.running = Some(ActiveTiming {
576 spawned,
577 location,
578 start,
579 });
580 }
581 #[cfg(not(feature = "profiler"))]
582 pub fn update_running_task(&mut self, _: SpawnTime, _: &'static std::panic::Location<'_>) {}
583
584 #[cfg(feature = "profiler")]
585 pub fn save_task_timing(&mut self, ended: YieldTime) {
586 let ActiveTiming {
587 location,
588 start,
589 spawned,
590 } = self
591 .running
592 .take()
593 .expect("this function is only ever called after register_task_start");
594
595 let timing = TaskTiming {
596 location,
597 spawned,
598 start,
599 end: ended,
600 };
601 self.stats.add_yield_timing(timing);
602 self.stats.add_runtime(timing);
603
604 if trace_enabled() {
605 std::hint::cold_path(); if self.timings.len() >= MAX_TASK_TIMINGS {
607 self.timings.pop_front();
608 }
609 self.timings.push_back(timing);
610 self.total_pushed += 1;
611 }
612 }
613 #[cfg(not(feature = "profiler"))]
614 pub fn save_task_timing(&mut self, _: YieldTime) {}
615
616 pub fn get_thread_task_timings(&self, includes: TasksIncluded) -> ThreadTaskTimings {
619 ThreadTaskTimings {
620 thread_name: self.thread_name.clone(),
621 thread_id: self.thread_id,
622 timings: self
623 .timings
624 .iter()
625 .cloned()
626 .chain(
627 self.running
628 .filter(|_| matches!(includes, TasksIncluded::CompletedAndRunning))
629 .map(|running| TaskTiming {
630 spawned: running.spawned,
631 location: running.location,
632 start: running.start,
633 end: YieldTime(Instant::now()),
634 }),
635 )
636 .collect(),
637 stats: self.stats.clone(),
638 total_pushed: self.total_pushed,
639 }
640 }
641}
642
643impl Drop for ThreadTimings {
644 fn drop(&mut self) {
645 let mut thread_timings = GLOBAL_THREAD_TIMINGS.lock();
646
647 let Some((index, _)) = thread_timings
648 .iter()
649 .enumerate()
650 .find(|(_, t)| t.thread_id == self.thread_id)
651 else {
652 return;
653 };
654 thread_timings.swap_remove(index);
655 }
656}
657
658#[doc(hidden)]
659pub fn update_running_task(spawned: SpawnTime, location: &'static std::panic::Location<'_>) {
660 THREAD_TIMINGS.with(|timings| {
661 timings.lock().update_running_task(spawned, location);
662 });
663}
664
665#[doc(hidden)]
666pub fn save_task_timing() {
667 let yielded_at = YieldTime(Instant::now());
668 THREAD_TIMINGS.with(|timings| {
669 timings.lock().save_task_timing(yielded_at);
670 });
671}
672
673#[doc(hidden)]
674pub fn get_current_thread_task_timings(include_running: TasksIncluded) -> ThreadTaskTimings {
675 THREAD_TIMINGS.with(|timings| timings.lock().get_thread_task_timings(include_running))
676}
677
678static PROFILER_ENABLED: AtomicBool = AtomicBool::new(false);
679
680pub fn set_trace_enabled(enabled: bool) -> bool {
687 if PROFILER_ENABLED.swap(enabled, Ordering::AcqRel) == enabled {
688 return false;
689 }
690
691 if !enabled {
692 for (_, timings) in upgraded_thread_timings() {
693 let mut timings = timings.lock();
694 timings.timings.clear();
695 timings.timings.shrink_to_fit();
696 timings.total_pushed = 0;
697 }
698 }
699 true
700}
701
702pub fn trace_enabled() -> bool {
704 PROFILER_ENABLED.load(Ordering::Relaxed)
705}
706
707#[derive(Debug, Copy, Clone)]
709pub struct FrameTiming {
710 pub window_id: WindowId,
712 pub dirty_at: Option<Instant>,
715 pub invalidations: u64,
717 pub draw_start: Instant,
719 pub draw_end: Instant,
721}
722
723impl FrameTiming {
724 pub fn draw_duration(&self) -> Duration {
726 self.draw_end.duration_since(self.draw_start)
727 }
728
729 pub fn dirty_to_draw_duration(&self) -> Option<Duration> {
732 self.dirty_at
733 .map(|dirty_at| self.draw_end.duration_since(dirty_at))
734 }
735}
736
737const MAX_FRAME_TIMINGS: usize = (16 * 1024 * 1024) / core::mem::size_of::<FrameTiming>();
739
740struct FrameTimings {
741 timings: VecDeque<FrameTiming>,
742 total_pushed: u64,
743}
744
745static FRAME_TIMINGS: spin::Mutex<FrameTimings> = spin::Mutex::new(FrameTimings {
746 timings: VecDeque::new(),
747 total_pushed: 0,
748});
749
750static FRAME_TRACE_ENABLED: AtomicBool = AtomicBool::new(false);
751
752pub fn set_frame_trace_enabled(enabled: bool) -> bool {
758 if FRAME_TRACE_ENABLED.swap(enabled, Ordering::AcqRel) == enabled {
759 return false;
760 }
761
762 if !enabled {
763 let mut frames = FRAME_TIMINGS.lock();
764 frames.timings.clear();
765 frames.timings.shrink_to_fit();
766 frames.total_pushed = 0;
767 }
768 true
769}
770
771pub fn frame_trace_enabled() -> bool {
773 FRAME_TRACE_ENABLED.load(Ordering::Relaxed)
774}
775
776pub fn record_frame_timing(timing: FrameTiming) {
780 if !frame_trace_enabled() {
781 return;
782 }
783 std::hint::cold_path(); let mut frames = FRAME_TIMINGS.lock();
786 if frames.timings.len() >= MAX_FRAME_TIMINGS {
787 frames.timings.pop_front();
788 }
789 frames.timings.push_back(timing);
790 frames.total_pushed += 1;
791}
792
793pub struct FrameTimingCollector {
796 cursor: u64,
797}
798
799impl Default for FrameTimingCollector {
800 fn default() -> Self {
801 Self::new()
802 }
803}
804
805impl FrameTimingCollector {
806 pub fn new() -> Self {
808 Self {
809 cursor: FRAME_TIMINGS.lock().total_pushed,
810 }
811 }
812
813 pub fn collect_unseen(&mut self) -> Vec<FrameTiming> {
817 let frames = FRAME_TIMINGS.lock();
818 let buffer_len = frames.timings.len() as u64;
819 let buffer_start = frames.total_pushed.saturating_sub(buffer_len);
820 let skip = self.cursor.saturating_sub(buffer_start) as usize;
821 let unseen = frames
822 .timings
823 .iter()
824 .skip(skip.min(frames.timings.len()))
825 .copied()
826 .collect();
827 self.cursor = frames.total_pushed;
828 unseen
829 }
830}