brep_app/perf.rs
1//! Where a frame's milliseconds go — the ONE per-frame timing record.
2//!
3//! A dropped frame rate and a frozen UI are the same fact on wasm: the app is
4//! single-threaded, so every millisecond spent between two `ui()` calls is a
5//! millisecond the browser cannot deliver a pointer event in. "Slow" is
6//! therefore not one number but a split, and the split is what names the owner:
7//! encode-and-submit time is the renderer's, publish time is the state
8//! registry's, and the gap between them is egui's.
9//!
10//! Measured with [`web_time::Instant`], which is `performance.now()` on wasm and
11//! the monotonic clock natively, so both shells report the same quantity.
12//!
13//! # Why a static, and why accumulate
14//!
15//! The phases are timed in three different modules (`app`, `viewport`,
16//! `viewport::blit`) that do not share a `&mut` path, so the record lives here
17//! as a static — the same shape [`crate::automation::registry`] uses, for the
18//! same reason. A phase may be entered SEVERAL times in one frame (the registry
19//! publishes from three places); each entry accumulates, and `tick` — called
20//! once at the top of the frame — banks the frame's totals into the rolling
21//! window. So every reported phase is "ms per frame", never "ms per call".
22//!
23//! `dt` is wall time between successive `tick`s: the frame PERIOD, including
24//! whatever the browser did between our frames. It is the number a user feels;
25//! the phases explain it.
26
27use std::sync::{Mutex, MutexGuard};
28use web_time::Instant;
29
30/// Frames kept in the rolling window (~2 s at 60 fps).
31const WINDOW: usize = 120;
32
33/// The timed phases, in report order. `Ui` brackets the whole of
34/// `BrepApp::ui`; the rest are nested inside it and do not sum to it — the
35/// remainder is egui's own layout, painting and tessellation.
36///
37/// The reported key for `Ui` is `"ui"`, NOT `"frame"`: a command reply carries
38/// its own `frame` (the frame NUMBER) at the top level, and a phase of that
39/// name would be overwritten by it in the merged result.
40#[derive(Clone, Copy, PartialEq, Eq, Debug)]
41pub enum Phase {
42 /// The whole `BrepApp::ui` body.
43 Ui,
44 /// The `__brep*` state-registry publish blocks.
45 Publish,
46 /// `RenderCore::sync_scene`.
47 Sync,
48 /// `EngineState::fit_camera_and_overlay` (rebuilds the widget overlay).
49 Fit,
50 /// `EngineState::ensure_overlays_current`.
51 Overlays,
52 /// `RenderCore::render_to_view` — encode + submit. On the GL/WebGL2 backend
53 /// the driver replays the command buffer synchronously inside submit, so
54 /// this is very nearly the whole GPU cost; on WebGPU/Vulkan it is encode
55 /// only and the GPU work shows up in `dt` instead.
56 Draw,
57}
58
59const PHASES: usize = 6;
60
61const NAMES: [&str; PHASES] = ["ui", "publish", "sync", "fit", "overlays", "draw"];
62
63fn slot(phase: Phase) -> usize {
64 match phase {
65 Phase::Ui => 0,
66 Phase::Publish => 1,
67 Phase::Sync => 2,
68 Phase::Fit => 3,
69 Phase::Overlays => 4,
70 Phase::Draw => 5,
71 }
72}
73
74/// A fixed-capacity rolling window of per-frame milliseconds.
75struct Ring {
76 samples: [f32; WINDOW],
77 len: usize,
78 next: usize,
79}
80
81impl Ring {
82 const fn new() -> Self {
83 Self { samples: [0.0; WINDOW], len: 0, next: 0 }
84 }
85
86 fn push(&mut self, ms: f32) {
87 self.samples[self.next] = ms;
88 self.next = (self.next + 1) % WINDOW;
89 self.len = (self.len + 1).min(WINDOW);
90 }
91
92 fn stats(&self) -> Stats {
93 if self.len == 0 {
94 return Stats::default();
95 }
96 let live = &self.samples[..self.len];
97 let sum: f32 = live.iter().sum();
98 let mut sorted: Vec<f32> = live.to_vec();
99 sorted.sort_by(|a, b| a.partial_cmp(b).unwrap_or(std::cmp::Ordering::Equal));
100 // p95 by nearest-rank, so a 120-frame window reports its 114th slowest.
101 let rank = ((self.len as f32 * 0.95).ceil() as usize).clamp(1, self.len) - 1;
102 Stats {
103 avg: sum / self.len as f32,
104 p95: sorted[rank],
105 max: sorted[self.len - 1],
106 }
107 }
108}
109
110#[derive(Default, Clone, Copy)]
111struct Stats {
112 avg: f32,
113 p95: f32,
114 max: f32,
115}
116
117struct Perf {
118 /// Banked per-frame totals, one ring per phase.
119 rings: [Ring; PHASES],
120 /// Frame period (wall time between `tick`s).
121 dt: Ring,
122 /// This frame's running totals, banked by the next `tick`.
123 pending: [f32; PHASES],
124 /// When the current frame started, for `dt`.
125 last_tick: Option<Instant>,
126 /// Frames banked since startup.
127 frames: u64,
128}
129
130static PERF: Mutex<Perf> = Mutex::new(Perf {
131 rings: [Ring::new(), Ring::new(), Ring::new(), Ring::new(), Ring::new(), Ring::new()],
132 dt: Ring::new(),
133 pending: [0.0; PHASES],
134 last_tick: None,
135 frames: 0,
136});
137
138fn lock() -> MutexGuard<'static, Perf> {
139 PERF.lock().unwrap_or_else(|p| p.into_inner())
140}
141
142/// Open the current frame: bank the previous frame's phase totals and record
143/// its period. Call ONCE, at the top of `BrepApp::ui`.
144pub fn tick() {
145 let now = Instant::now();
146 let mut perf = lock();
147 if let Some(last) = perf.last_tick {
148 let dt = now.duration_since(last).as_secs_f32() * 1000.0;
149 perf.dt.push(dt);
150 let pending = perf.pending;
151 for (index, ms) in pending.iter().enumerate() {
152 perf.rings[index].push(*ms);
153 }
154 perf.frames += 1;
155 }
156 perf.pending = [0.0; PHASES];
157 perf.last_tick = Some(now);
158}
159
160/// Time a block into `phase`; the span ends when the guard drops. Several spans
161/// of the same phase in one frame ADD UP — the window holds ms per frame.
162#[must_use = "the span ends when the guard drops; bind it to a name"]
163pub fn span(phase: Phase) -> Span {
164 Span { phase, start: Instant::now() }
165}
166
167pub struct Span {
168 phase: Phase,
169 start: Instant,
170}
171
172impl Drop for Span {
173 fn drop(&mut self) {
174 let ms = self.start.elapsed().as_secs_f32() * 1000.0;
175 let mut perf = lock();
176 perf.pending[slot(self.phase)] += ms;
177 }
178}
179
180/// The rolling window as JSON: the `__brepPerf` blob and the Info-window rows
181/// read this one value, so they cannot disagree.
182///
183/// `{"frames":N,"window":120,"dt":{"avg":..,"p95":..,"max":..},"frame":{..},…}`
184/// — every number in milliseconds.
185pub fn json() -> String {
186 let perf = lock();
187 let mut out = String::with_capacity(320);
188 out.push_str("{\"frames\":");
189 out.push_str(&perf.frames.to_string());
190 out.push_str(",\"window\":");
191 out.push_str(&perf.dt.len.to_string());
192 let push = |out: &mut String, name: &str, stats: Stats| {
193 out.push_str(",\"");
194 out.push_str(name);
195 out.push_str("\":{\"avg\":");
196 out.push_str(&format!("{:.3}", stats.avg));
197 out.push_str(",\"p95\":");
198 out.push_str(&format!("{:.3}", stats.p95));
199 out.push_str(",\"max\":");
200 out.push_str(&format!("{:.3}", stats.max));
201 out.push('}');
202 };
203 out.push_str(",\"staleFrames\":");
204 out.push_str(&STALE_FRAMES.load(std::sync::atomic::Ordering::Relaxed).to_string());
205 push(&mut out, "dt", perf.dt.stats());
206 for (index, name) in NAMES.iter().enumerate() {
207 push(&mut out, name, perf.rings[index].stats());
208 }
209 out.push('}');
210 out
211}
212
213/// Frames the viewport did not render although their render inputs had
214/// changed (automation builds; see `Viewport::check_stale_frame`). Never reset:
215/// the MCP test runner reads it before and after each script.
216static STALE_FRAMES: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0);
217
218pub fn note_stale_frame() {
219 STALE_FRAMES.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
220}
221
222/// Drop every sample, keeping the frame counter's meaning ("frames banked")
223/// intact only for the new window. A measurement resets, then spins, then
224/// reads — otherwise the idle frames before the spin dominate the average.
225pub fn reset() {
226 let mut perf = lock();
227 for ring in perf.rings.iter_mut() {
228 *ring = Ring::new();
229 }
230 perf.dt = Ring::new();
231 perf.pending = [0.0; PHASES];
232 perf.frames = 0;
233 perf.last_tick = None;
234}