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