1use loam_console::{cmd, Console, ConsoleWriter};
2use loam_render::pass::{GpuTime, Section};
3use loam_time::frame_trace;
4use std::sync::Mutex;
5use std::time::Duration;
6
7#[cfg(feature = "egui")]
8mod overlay;
9#[cfg(feature = "egui")]
10pub use overlay::{PerfOverlay, MAX_WINDOW};
11
12fn fmt_dur(d: std::time::Duration) -> String {
13 let ns = d.as_nanos();
14 if ns < 1_000 {
15 format!("{ns}ns")
16 } else if ns < 1_000_000 {
17 format!("{:.1}us", ns as f64 / 1_000.0)
18 } else if ns < 1_000_000_000 {
19 format!("{:.2}ms", ns as f64 / 1_000_000.0)
20 } else {
21 format!("{:.2}s", ns as f64 / 1_000_000_000.0)
22 }
23}
24
25fn unscoped(frame: &frame_trace::FrameTrace) -> Option<Duration> {
27 let mut total = None;
28 let mut covered = Duration::ZERO;
29 for section in &frame.sections {
30 if section.name == "frame" {
31 total = Some(section.elapsed);
32 } else if crate::FRAME_LOOP_SECTIONS.contains(§ion.name) {
33 covered += section.elapsed;
34 }
35 }
36 total.map(|t| t.saturating_sub(covered))
37}
38
39fn unscoped_stats() -> Option<frame_trace::SectionStats> {
40 let mut samples: Vec<Duration> =
41 frame_trace::with_history(|history| history.iter().filter_map(unscoped).collect());
42 if samples.is_empty() {
43 return None;
44 }
45 samples.sort();
46 let n = samples.len();
47 Some(frame_trace::SectionStats {
48 name: "unscoped",
49 samples: n,
50 mean: samples.iter().sum::<Duration>() / n as u32,
51 p50: frame_trace::percentile(&samples, 50),
52 p95: frame_trace::percentile(&samples, 95),
53 p99: frame_trace::percentile(&samples, 99),
54 max: samples[n - 1],
55 })
56}
57
58fn summary_rows() -> Vec<frame_trace::SectionStats> {
59 let mut stats = frame_trace::aggregate();
60 if let Some(residual) = unscoped_stats() {
61 stats.push(residual);
62 stats.sort_by_key(|s| std::cmp::Reverse(s.p95));
63 }
64 stats
65}
66
67fn print_summary(out: &mut ConsoleWriter) {
68 let stats = summary_rows();
69 if stats.is_empty() {
70 out.line("trace: no frames in window (collect runs once the demo is rendering)");
71 return;
72 }
73 let history_len = frame_trace::with_history(|frames| frames.len());
74 out.line(format!(
75 "trace summary ({history_len} frames, sorted by p95 desc):"
76 ));
77 out.line(format!(
78 " {:<18} {:>6} {:>8} {:>8} {:>8} {:>8} {:>8}",
79 "section", "n", "mean", "p50", "p95", "p99", "max",
80 ));
81 for s in stats {
82 out.line(format!(
83 " {:<18} {:>6} {:>8} {:>8} {:>8} {:>8} {:>8}",
84 truncate(s.name, 18),
85 s.samples,
86 fmt_dur(s.mean),
87 fmt_dur(s.p50),
88 fmt_dur(s.p95),
89 fmt_dur(s.p99),
90 fmt_dur(s.max),
91 ));
92 }
93}
94
95#[derive(Default)]
96struct Presentation {
97 sections: Vec<Section>,
98 uploads: u64,
99}
100
101static PRESENTATION: Mutex<Option<Presentation>> = Mutex::new(None);
102
103fn presentation<R>(read: impl FnOnce(&mut Option<Presentation>) -> R) -> R {
104 let mut held = match PRESENTATION.lock() {
105 Ok(held) => held,
106 Err(poisoned) => poisoned.into_inner(),
107 };
108 read(&mut held)
109}
110
111pub(crate) fn record_presentation(sections: &[Section], uploads: u64) {
112 presentation(|held| {
113 let held = held.get_or_insert_with(Presentation::default);
114 held.sections.clear();
115 held.sections.extend_from_slice(sections);
116 held.uploads = uploads;
117 });
118}
119
120fn print_passes(out: &mut ConsoleWriter) {
121 presentation(|held| {
122 let Some(held) = held.as_ref() else {
123 out.line("trace: the presenter has not recorded a frame yet");
124 return;
125 };
126 out.line(format!(
127 "trace passes ({} sections, {} record uploads):",
128 held.sections.len(),
129 held.uploads,
130 ));
131 for section in &held.sections {
132 let gpu = match section.gpu {
133 GpuTime::Measured(elapsed) => fmt_dur(elapsed),
134 GpuTime::Unavailable => "unavailable".to_owned(),
135 };
136 out.line(format!(
137 " {:<18} cpu {:>10} gpu {:>12}",
138 truncate(section.name, 18),
139 fmt_dur(section.cpu),
140 gpu,
141 ));
142 }
143 });
144}
145
146fn truncate(s: &str, max: usize) -> String {
147 if s.chars().count() <= max {
148 s.to_owned()
149 } else if max == 0 {
150 String::new()
151 } else {
152 s.chars()
153 .take(max - 1)
154 .chain(std::iter::once('~'))
155 .collect()
156 }
157}
158
159fn print_last(out: &mut ConsoleWriter) {
160 let Some(frame) = frame_trace::last_frame() else {
161 out.line("trace: no frames in window yet");
162 return;
163 };
164 let total = frame.total();
165 out.line(format!(
166 "trace last-frame ({} sections, sum {}):",
167 frame.sections.len(),
168 fmt_dur(total),
169 ));
170 for section in &frame.sections {
171 let pct = if !total.is_zero() {
172 (section.elapsed.as_nanos() as f64 * 100.0) / total.as_nanos() as f64
173 } else {
174 0.0
175 };
176 out.line(format!(
177 " {:<18} {:>10} ({:>4.1}%)",
178 truncate(section.name, 18),
179 fmt_dur(section.elapsed),
180 pct,
181 ));
182 }
183}
184
185fn format_summary() -> String {
186 let mut out = ConsoleWriter::new();
187 print_summary(&mut out);
188 out.take_lines()
189 .into_iter()
190 .map(|line| line.text)
191 .collect::<Vec<_>>()
192 .join("\n")
193}
194
195pub fn register_command<Ctx: 'static>(console: &mut Console<Ctx>) {
196 console.register(
197 cmd(
198 "trace",
199 "show CPU per-section frame timings (collected by loam-time::frame_trace)",
200 |args, _ctx: &mut Ctx, out| {
201 match args.first().copied() {
202 None | Some("summary") => {
203 print_summary(out);
204 print_passes(out);
205 }
206 Some("last") => print_last(out),
207 Some("passes") => print_passes(out),
208 Some("dump") => {
209 let summary = format_summary();
210 tracing::info!("\n{summary}");
211 out.line("trace: dumped to browser console (open DevTools to copy)");
212 }
213 Some("clear") => {
214 frame_trace::clear_history();
215 out.line("trace: history cleared");
216 }
217 Some("cap") => {
218 let n = args
219 .get(1)
220 .copied()
221 .and_then(|s| s.parse::<usize>().ok());
222 match n {
223 Some(n) if n >= 1 => {
224 frame_trace::set_capacity(n);
225 out.line(format!("trace: capacity set to {n} frames"));
226 }
227 _ => {
228 out.line("usage: trace cap <N> (N >= 1)");
229 }
230 }
231 }
232 Some(other) => {
233 out.line(format!(
234 "trace: unknown subcommand '{other}' (try summary | last | passes | dump | clear | cap)"
235 ));
236 }
237 }
238 Ok(())
239 },
240 )
241 .with_args(&[&["summary", "last", "passes", "dump", "clear", "cap"]]),
242 );
243}
244
245#[cfg(test)]
246mod tests {
247 use super::*;
248
249 #[test]
250 fn truncate_preserves_short_names_and_marks_long_ones() {
251 assert_eq!(truncate("frame", 18), "frame");
252 assert_eq!(truncate("abcdefghijklmnopqr", 18).len(), 18);
253 let long = "supercalifragilisticexpialidocious";
254 let t = truncate(long, 18);
255 assert_eq!(t.len(), 18);
256 assert!(t.ends_with('~'));
257 assert_eq!(truncate("αβγδε", 3), "αβ~");
258 assert_eq!(truncate("frame", 0), "");
259 }
260
261 fn frame_of(sections: &[(&'static str, u64)]) -> frame_trace::FrameTrace {
262 frame_trace::FrameTrace {
263 sections: sections
264 .iter()
265 .map(|(name, us)| frame_trace::Section {
266 name,
267 elapsed: Duration::from_micros(*us),
268 })
269 .collect(),
270 ..Default::default()
271 }
272 }
273
274 #[test]
275 fn unscoped_ignores_sections_nested_inside_frame_loop_sections() {
276 let flat = frame_of(&[("frame", 4000), ("presentation", 130)]);
277 let nested = frame_of(&[("frame", 4000), ("presentation", 130), ("pp-sdf", 94)]);
278 assert_eq!(unscoped(&nested), unscoped(&flat));
279 }
280
281 #[test]
282 fn unscoped_ignores_the_sections_that_do_not_nest_in_the_frame() {
283 let frame = frame_of(&[
284 ("frame", 4000),
285 ("presentation", 130),
286 ("between-frames", 4130),
287 ("idle", 110),
288 ("gpu-total", 800),
289 ]);
290 assert_eq!(unscoped(&frame), Some(Duration::from_micros(3870)));
291 }
292
293 #[test]
294 fn unscoped_is_absent_for_a_frame_without_a_frame_section() {
295 let frame = frame_of(&[("presentation", 130), ("present", 40)]);
296 assert_eq!(unscoped(&frame), None);
297 }
298
299 #[test]
300 fn unscoped_saturates_at_zero_when_the_children_overrun_the_parent() {
301 let frame = frame_of(&[("frame", 100), ("presentation", 130)]);
302 assert_eq!(unscoped(&frame), Some(Duration::ZERO));
303 }
304}