From c9013a871055ba5a1d4f53c2689efd475d2e9c9c Mon Sep 17 00:00:00 2001 From: Matthew James Sivak Date: Tue, 13 Oct 2026 09:16:06 +0200 Subject: [PATCH] Show Frame Rate: no spike after turning it back on, and one count per window Review of #1313: - Turning the display off and on again later counted the whole time it was off as one frame, so "worst" and the graph showed a huge red spike for the next second. The state is now dropped while the display is off (`frame_rate::forget`), and a gap of more than 2 s while it shows (window hidden, machine asleep) starts a fresh count instead of becoming a frame. - The state (`HUD`, `LOGGED`) was in process-wide statics, shared by every headless view in a test process. It now lives in the egui context's temp data, one per window. Tests: turning it back on after time off, a long pause while it shows, and two contexts keeping separate counts (the first two fail without the fix). Co-Authored-By: Claude Opus 5.5 --- crates/ui-egui/src/frame_rate.rs | 162 +++++++++++++++++++++++-------- crates/ui-egui/src/headless.rs | 2 +- crates/ui-egui/src/lib.rs | 2 + 3 files changed, 125 insertions(+), 41 deletions(-) diff --git a/crates/ui-egui/src/frame_rate.rs b/crates/ui-egui/src/frame_rate.rs index 7feefa555..74299b635 100644 --- a/crates/ui-egui/src/frame_rate.rs +++ b/crates/ui-egui/src/frame_rate.rs @@ -7,7 +7,6 @@ //! renders. While it shows, the window repaints continuously, so the rate is the one a drag gets. use std::collections::VecDeque; -use std::sync::Mutex; use crate::LightcraftApp; use crate::render::Slot; @@ -15,11 +14,15 @@ use crate::render::Slot; /// Frames kept for the graph (about two seconds at 120 Hz). const KEEP: usize = 240; +/// A gap between frames longer than this is a pause (window hidden or occluded, the machine +/// asleep), not a frame: the display starts counting again instead of showing it as a spike. +const PAUSE: f64 = 2.0; + #[derive(Clone, Copy)] -struct Frame { +pub(crate) struct Frame { at: f64, /// Seconds since the previous frame. - dt: f64, + pub(crate) dt: f64, /// The previous frame's CPU time on the UI thread, seconds. cpu: f64, /// Renders that arrived this frame. @@ -28,14 +31,61 @@ struct Frame { discarded: u64, } +/// The display's state, kept in the context's temp data (one per window or headless view) and +/// dropped while the display is off, so turning it back on starts a fresh count. +#[derive(Clone, Default)] struct Hud { last: Option, completed: u64, discarded: u64, frames: VecDeque, + /// When the numbers were last logged. + logged: Option, } -static HUD: Mutex> = Mutex::new(None); +fn hud_id() -> egui::Id { + egui::Id::new("fps-hud-state") +} + +/// The display is off: drop its state, so the time it was off never shows as one long frame. +pub(crate) fn forget(ctx: &egui::Context) { + ctx.data_mut(|d| d.remove::(hud_id())); +} + +/// Record a frame at `now` (`completed`/`discarded`: the renderer's running totals; `cpu`: the +/// previous frame's UI CPU time, seconds). Returns the frames kept for the display, and whether +/// the numbers are due in the log (once a second; A/B runs read them). +fn record(ctx: &egui::Context, now: f64, completed: u64, discarded: u64, cpu: f64) -> (Vec, bool) { + ctx.data_mut(|d| { + let hud = d.get_temp_mut_or_default::(hud_id()); + match hud.last { + Some(prev) if now - prev > PAUSE || now < prev => hud.frames.clear(), + Some(prev) => { + let renders = completed.saturating_sub(hud.completed); + let thrown = discarded.saturating_sub(hud.discarded); + hud.frames.push_back(Frame { at: now, dt: (now - prev).max(1e-6), cpu, renders, discarded: thrown }); + while hud.frames.len() > KEEP { + hud.frames.pop_front(); + } + } + None => {} + } + hud.last = Some(now); + hud.completed = completed; + hud.discarded = discarded; + let log = hud.logged.is_none_or(|t| now - t >= 1.0 || now < t); + if log { + hud.logged = Some(now); + } + (hud.frames.iter().copied().collect(), log) + }) +} + +/// The frames the display holds now (tests). +#[cfg(test)] +pub(crate) fn frames(ctx: &egui::Context) -> Vec { + ctx.data_mut(|d| d.get_temp::(hud_id())).map(|h| h.frames.into_iter().collect()).unwrap_or_default() +} fn mb(bytes: u64) -> f64 { bytes as f64 / (1 << 20) as f64 @@ -44,24 +94,8 @@ fn mb(bytes: u64) -> f64 { /// Count this frame and draw the display over everything. pub fn show(ctx: &egui::Context, app: &LightcraftApp) { let now = ctx.input(|i| i.time); - let completed = app.renderer.completed; - let discarded = app.renderer.discarded; - let mut guard = HUD.lock().unwrap_or_else(std::sync::PoisonError::into_inner); - let hud = guard.get_or_insert_with(|| Hud { last: None, completed, discarded, frames: VecDeque::new() }); - if let Some(prev) = hud.last { - let cpu = app.perf.host_frame_ms.unwrap_or(0.0) / 1e3; - let renders = completed.saturating_sub(hud.completed); - let thrown = discarded.saturating_sub(hud.discarded); - hud.frames.push_back(Frame { at: now, dt: (now - prev).max(1e-6), cpu, renders, discarded: thrown }); - while hud.frames.len() > KEEP { - hud.frames.pop_front(); - } - } - hud.last = Some(now); - hud.completed = completed; - hud.discarded = discarded; - let frames: Vec = hud.frames.iter().copied().collect(); - drop(guard); + let cpu = app.perf.host_frame_ms.unwrap_or(0.0) / 1e3; + let (frames, log) = record(ctx, now, app.renderer.completed, app.renderer.discarded, cpu); let recent: Vec<&Frame> = frames.iter().filter(|f| now - f.at <= 1.0).collect(); let fps_now = frames.last().map_or(0.0, |f| 1.0 / f.dt); @@ -80,24 +114,18 @@ pub fn show(ctx: &egui::Context, app: &LightcraftApp) { } None => "starting…".into(), }; - // once a second, the same numbers in the log (A/B runs read them) - static LOGGED: Mutex = Mutex::new(0.0); - { - let mut logged = LOGGED.lock().unwrap_or_else(std::sync::PoisonError::into_inner); - if now - *logged >= 1.0 { - *logged = now; - let (wdt, wcpu) = worst.map_or((0.0, 0.0), |w| (w.dt * 1e3, w.cpu * 1e3)); - let p95 = { - let mut d: Vec = recent.iter().map(|f| f.dt * 1e3).collect(); - d.sort_by(f64::total_cmp); - d.get(d.len().saturating_sub(1) * 95 / 100).copied().unwrap_or(0.0) - }; - log::info!( - "fps-hud: frames {} slow>20ms {slow} p95 {p95:.1} worst {wdt:.1} (cpu {wcpu:.1}) renders {renders_s} discarded {discarded_s} window {:.1} gpu {device}", - recent.len(), - window.map_or(0.0, |t| t.ms) - ); - } + if log { + let (wdt, wcpu) = worst.map_or((0.0, 0.0), |w| (w.dt * 1e3, w.cpu * 1e3)); + let p95 = { + let mut d: Vec = recent.iter().map(|f| f.dt * 1e3).collect(); + d.sort_by(f64::total_cmp); + d.get(d.len().saturating_sub(1) * 95 / 100).copied().unwrap_or(0.0) + }; + log::info!( + "fps-hud: frames {} slow>20ms {slow} p95 {p95:.1} worst {wdt:.1} (cpu {wcpu:.1}) renders {renders_s} discarded {discarded_s} window {:.1} gpu {device}", + recent.len(), + window.map_or(0.0, |t| t.ms) + ); } let lines = [ format!("{fps_now:>4.0} fps avg {avg_fps:.0} {slow} frames > 20 ms in 1 s"), @@ -227,4 +255,58 @@ mod tests { assert_eq!(set(&mut h, json!({"show": false})), Some(false)); assert!(!h.app.ui.frame_rate); } + + fn worst_ms(h: &Headless) -> f64 { + super::frames(&h.view.ctx).iter().map(|f| f.dt * 1e3).fold(0.0, f64::max) + } + + /// Turned off and on again later, the display starts a fresh count: the time it was off is not + /// one long frame (a red spike and a "worst" of the whole time off). + #[test] + fn turning_it_back_on_shows_no_spike_for_the_time_it_was_off() { + let app = LightcraftApp::new(lightcraft_engine::Session::with_demo(), Services { png: None, ..Default::default() }); + let mut h = Headless::new(app, [1200.0, 800.0], 1.0); + set(&mut h, json!({"show": true})); + for _ in 0..3 { + h.step(); + } + assert!(!super::frames(&h.view.ctx).is_empty(), "frames are counted while it shows"); + set(&mut h, json!({"show": false})); + h.step(); + h.time += 1.5; + set(&mut h, json!({"show": true})); + for _ in 0..3 { + h.step(); + } + assert!(worst_ms(&h) < 1000.0, "worst frame {} ms after turning it back on", worst_ms(&h)); + } + + /// A pause while it shows (window hidden, machine asleep) starts a fresh count too. + #[test] + fn a_long_pause_while_it_shows_is_not_a_frame() { + let app = LightcraftApp::new(lightcraft_engine::Session::with_demo(), Services { png: None, ..Default::default() }); + let mut h = Headless::new(app, [1200.0, 800.0], 1.0); + set(&mut h, json!({"show": true})); + for _ in 0..3 { + h.step(); + } + h.time += 30.0; + for _ in 0..3 { + h.step(); + } + assert!(worst_ms(&h) < 1000.0, "worst frame {} ms after a pause", worst_ms(&h)); + } + + /// Each window (egui context) keeps its own count. + #[test] + fn each_context_keeps_its_own_count() { + let (a, b) = (egui::Context::default(), egui::Context::default()); + for t in [0.0, 0.016, 0.033] { + super::record(&a, t, 0, 0, 0.0); + } + assert_eq!(super::frames(&a).len(), 2); + assert!(super::frames(&b).is_empty()); + let (frames, _) = super::record(&b, 100.0, 0, 0, 0.0); + assert!(frames.is_empty(), "a new context's first frame has no interval: {}", frames.len()); + } } diff --git a/crates/ui-egui/src/headless.rs b/crates/ui-egui/src/headless.rs index 6178990b0..67fadc9d5 100644 --- a/crates/ui-egui/src/headless.rs +++ b/crates/ui-egui/src/headless.rs @@ -234,7 +234,7 @@ pub struct Headless { /// Logical size (points) and scale. pub size: egui::Vec2, pub pixels_per_point: f32, - time: f64, + pub(crate) time: f64, frames: u64, pub(crate) events: Vec, control: Sender, diff --git a/crates/ui-egui/src/lib.rs b/crates/ui-egui/src/lib.rs index d16f0fc28..a1b8da873 100644 --- a/crates/ui-egui/src/lib.rs +++ b/crates/ui-egui/src/lib.rs @@ -1386,6 +1386,8 @@ impl LightcraftApp { fn end_frame(&mut self, ctx: &egui::Context, t0: f64) { if self.ui.frame_rate { frame_rate::show(ctx, self); + } else { + frame_rate::forget(ctx); } ctx.output(|o| { for c in &o.commands {