mirror of
https://github.com/storytold/lightcraft.git
synced 2026-11-02 06:27:53 -06:00
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 <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Opus 5.5
parent
8d2e9b70aa
commit
c9013a8710
@@ -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<f64>,
|
||||
completed: u64,
|
||||
discarded: u64,
|
||||
frames: VecDeque<Frame>,
|
||||
/// When the numbers were last logged.
|
||||
logged: Option<f64>,
|
||||
}
|
||||
|
||||
static HUD: Mutex<Option<Hud>> = 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>(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<Frame>, bool) {
|
||||
ctx.data_mut(|d| {
|
||||
let hud = d.get_temp_mut_or_default::<Hud>(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<Frame> {
|
||||
ctx.data_mut(|d| d.get_temp::<Hud>(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<Frame> = 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<f64> = 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<f64> = 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<f64> = 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());
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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<egui::Event>,
|
||||
control: Sender<ControlRequest>,
|
||||
|
||||
@@ -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 {
|
||||
|
||||
Reference in New Issue
Block a user