diff --git a/apps/lightcraft/src/main.rs b/apps/lightcraft/src/main.rs index bb713a2e..3e15c331 100644 --- a/apps/lightcraft/src/main.rs +++ b/apps/lightcraft/src/main.rs @@ -76,7 +76,8 @@ impl eframe::App for App { fn raw_input_hook(&mut self, _ctx: &egui::Context, raw: &mut egui::RawInput) { self.0.raw_input_hook(raw); } - fn ui(&mut self, ui: &mut egui::Ui, _frame: &mut eframe::Frame) { + fn ui(&mut self, ui: &mut egui::Ui, frame: &mut eframe::Frame) { + self.0.perf.host_frame_ms = frame.info().cpu_usage.map(|s| f64::from(s) * 1000.0); self.0.ui(ui); } fn on_exit(&mut self, _gl: Option<&eframe::glow::Context>) { diff --git a/crates/ui-egui/src/frame_rate.rs b/crates/ui-egui/src/frame_rate.rs new file mode 100644 index 00000000..7feefa55 --- /dev/null +++ b/crates/ui-egui/src/frame_rate.rs @@ -0,0 +1,230 @@ +//! Help ▸ Debug ▸ Show Frame Rate (`view.frameRate`; `LIGHTCRAFT_FPS=1` starts with it on): a +//! frame-rate display in the window's top-right corner, to watch how a slider drag or a zoom holds +//! up. It shows where a frame's time goes: the UI +//! thread's CPU time (layout, painting, texture uploads) and the rest of the frame interval, which +//! is waiting — for vsync, or for the GPU when render work is ahead of the window's frame. A +//! tick over the graph marks each frame in which a render arrived, so spikes can be put next to +//! 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; + +/// Frames kept for the graph (about two seconds at 120 Hz). +const KEEP: usize = 240; + +#[derive(Clone, Copy)] +struct Frame { + at: f64, + /// Seconds since the previous frame. + dt: f64, + /// The previous frame's CPU time on the UI thread, seconds. + cpu: f64, + /// Renders that arrived this frame. + renders: u64, + /// Of those, thrown away (superseded by a newer request). + discarded: u64, +} + +struct Hud { + last: Option, + completed: u64, + discarded: u64, + frames: VecDeque, +} + +static HUD: Mutex> = Mutex::new(None); + +fn mb(bytes: u64) -> f64 { + bytes as f64 / (1 << 20) as 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 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); + let worst = recent.iter().copied().max_by(|a, b| a.dt.total_cmp(&b.dt)); + let avg_fps = if recent.is_empty() { 0.0 } else { recent.len() as f64 / recent.iter().map(|f| f.dt).sum::().max(1e-6) }; + let slow = recent.iter().filter(|f| f.dt > 1.0 / 50.0).count(); + let renders_s: u64 = recent.iter().map(|f| f.renders).sum(); + let discarded_s: u64 = recent.iter().map(|f| f.discarded).sum(); + let window = app.renderer.textures.get(&Slot::Region); + let mem = lightcraft_engine::gpu::memory(); + // (`ready` first: `available` would wait for a device still being created) + let device = match lightcraft_engine::gpu::unavailable_reason() { + Some(why) => format!("off ({why})"), + None if lightcraft_engine::gpu::ready() && lightcraft_engine::gpu::available() => { + lightcraft_engine::gpu::adapter_name().unwrap_or_else(|| "on".into()) + } + 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) + ); + } + } + let lines = [ + format!("{fps_now:>4.0} fps avg {avg_fps:.0} {slow} frames > 20 ms in 1 s"), + match worst { + Some(w) => format!("worst {:.1} ms = CPU {:.1} + wait {:.1}", w.dt * 1e3, w.cpu * 1e3, (w.dt - w.cpu).max(0.0) * 1e3), + None => "worst –".to_string(), + }, + format!("UI CPU {:.1} ms (update {:.1})", app.perf.host_frame_ms.unwrap_or(0.0), app.perf.update_ms), + format!("render frame {:.1} ms", app.renderer.last_main_ms), + match window { + Some(t) => format!("render window {:.1} ms", t.ms), + None => "render window –".to_string(), + }, + format!("renders: {} queued, {} running, {renders_s}/s ({discarded_s} thrown away)", app.renderer.queued(), app.renderer.in_flight()), + format!("GPU: {device}"), + format!("GPU mem {:.0} MB (+{:.0} pooled)", mb(mem.allocated), mb(mem.pooled)), + ]; + + let screen = ctx.content_rect(); + let width = 300.0; + egui::Area::new(egui::Id::new("fps-hud")) + .order(egui::Order::Tooltip) + .fixed_pos(egui::pos2(screen.right() - width - 24.0, screen.top() + 56.0)) + .interactable(false) + .show(ctx, |ui| { + egui::Frame::new().fill(egui::Color32::from_black_alpha(210)).corner_radius(6.0).inner_margin(8.0).show(ui, |ui| { + ui.set_width(width); + ui.spacing_mut().item_spacing.y = 1.0; + for l in &lines { + ui.label(egui::RichText::new(l).monospace().size(11.0).color(egui::Color32::from_gray(230))); + } + ui.add_space(4.0); + graph(ui, &frames, width); + ui.label( + egui::RichText::new("bars: blue = UI CPU, orange/red = waiting · ticks = a render arrived · line = 60 fps") + .size(9.0) + .color(egui::Color32::from_gray(160)), + ); + }); + }); + // a rate the drag gets, not the idle one + ctx.request_repaint(); +} + +/// Frame intervals, 0 at the bottom and 50 ms at the top: the UI thread's CPU part in blue and +/// the waiting part above it (green within 60 fps, orange within 30, red beyond), with a tick +/// over each frame in which a render arrived. +fn graph(ui: &mut egui::Ui, frames: &[Frame], width: f32) { + let (rect, _) = ui.allocate_exact_size(egui::vec2(width, 70.0), egui::Sense::hover()); + let p = ui.painter_at(rect); + let plot = egui::Rect::from_min_max(egui::pos2(rect.left(), rect.top() + 6.0), rect.max); + let y = |ms: f64| plot.bottom() - (ms / 50.0).clamp(0.0, 1.0) as f32 * plot.height(); + let w = rect.width() / KEEP as f32; + let start = KEEP.saturating_sub(frames.len()); + for (i, f) in frames.iter().enumerate() { + let (ms, cpu) = (f.dt * 1e3, (f.cpu * 1e3).min(f.dt * 1e3)); + let x = rect.left() + (start + i) as f32 * w; + let bar = |from: f64, to: f64, c: egui::Color32| { + p.rect_filled(egui::Rect::from_min_max(egui::pos2(x, y(to)), egui::pos2(x + w.max(1.0), y(from))), 0.0, c); + }; + let wait = if ms > 33.4 { + egui::Color32::from_rgb(230, 80, 70) + } else if ms > 17.5 { + egui::Color32::from_rgb(235, 160, 60) + } else { + egui::Color32::from_rgb(110, 190, 110) + }; + bar(cpu, ms, wait); + bar(0.0, cpu, egui::Color32::from_rgb(90, 150, 240)); + if f.renders > 0 { + p.rect_filled( + egui::Rect::from_min_max(egui::pos2(x, rect.top()), egui::pos2(x + w.max(1.0), rect.top() + 4.0)), + 0.0, + egui::Color32::WHITE, + ); + } + } + p.hline(rect.x_range(), y(1000.0 / 60.0), egui::Stroke::new(1.0, egui::Color32::from_rgb(90, 200, 90))); + p.hline(rect.x_range(), y(1000.0 / 30.0), egui::Stroke::new(1.0, egui::Color32::from_rgb(200, 90, 80).gamma_multiply(0.6))); +} + +#[cfg(test)] +mod tests { + use std::time::Duration; + + use serde_json::json; + + use crate::headless::Headless; + use crate::menubar::{MenuNode, menu_bar}; + use crate::{LightcraftApp, Services}; + + const T: Duration = Duration::from_secs(20); + + fn set(h: &mut Headless, params: serde_json::Value) -> Option { + let r = h.request("engine.execute", json!({"command": "view.frameRate", "params": params}), T); + assert_eq!(r["ok"], true, "{r}"); + r["result"]["show"].as_bool() + } + + /// The Help ▸ Debug item for it, and its checkmark. + fn debug_item(app: &LightcraftApp) -> Option> { + let help = menu_bar(app).into_iter().find(|(t, _)| t == "Help").map(|(_, items)| items).unwrap_or_default(); + help.into_iter().find_map(|n| match n { + MenuNode::Submenu { label, children } if label == "Debug" => children.into_iter().find_map(|c| match c { + MenuNode::Item { id, checked, .. } if id == "view.frameRate" => Some(checked), + _ => None, + }), + _ => None, + }) + } + + /// Help ▸ Debug ▸ Show Frame Rate toggles the display (a checked menu item), `{show}` sets it, + /// and frames draw with it on. + #[test] + fn show_frame_rate_is_a_debug_toggle() { + 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); + let was = h.app.ui.frame_rate; + assert_eq!(debug_item(&h.app), Some(Some(was)), "Help ▸ Debug lists it, checked as it is"); + assert_eq!(set(&mut h, json!({})), Some(!was)); + assert_eq!(debug_item(&h.app), Some(Some(!was))); + // frames with the display on draw (and keep the window repainting) + assert_eq!(set(&mut h, json!({"show": true})), Some(true)); + for _ in 0..3 { + h.step(); + } + assert_eq!(set(&mut h, json!({"show": false})), Some(false)); + assert!(!h.app.ui.frame_rate); + } +} diff --git a/crates/ui-egui/src/lib.rs b/crates/ui-egui/src/lib.rs index 8958bab3..fdfa49ce 100644 --- a/crates/ui-egui/src/lib.rs +++ b/crates/ui-egui/src/lib.rs @@ -14,6 +14,7 @@ pub mod credits; pub mod date_picker; pub mod docking; pub mod export_task; +mod frame_rate; pub mod headless; pub mod i18n; pub mod icons; @@ -254,6 +255,9 @@ pub struct Perf { pub update_ms: f64, /// The slowest whole update since start. pub max_update_ms: f64, + /// The previous frame's whole time on this thread, painting (texture uploads) included, as + /// the host reports it (eframe's `cpu_usage`); `None` without a host report (headless). + pub host_frame_ms: Option, pub fps: f64, } @@ -1276,6 +1280,9 @@ impl LightcraftApp { /// Frame timings once layout is done (`t0`: when layout started). fn end_frame(&mut self, ctx: &egui::Context, t0: f64) { + if self.ui.frame_rate { + frame_rate::show(ctx, self); + } ctx.output(|o| { for c in &o.commands { if let egui::OutputCommand::CopyText(text) = c { diff --git a/crates/ui-egui/src/menubar.rs b/crates/ui-egui/src/menubar.rs index 7c3f86da..cdbe9e80 100644 --- a/crates/ui-egui/src/menubar.rs +++ b/crates/ui-egui/src/menubar.rs @@ -316,6 +316,7 @@ pub fn checked(app: &LightcraftApp, id: &str) -> Option { "view.leftPanel" => Some(u.left_panel), "view.faceBoxes" => Some(u.face_boxes), "view.filmstrip" => Some(u.filmstrip), + "view.frameRate" => Some(u.frame_rate), "view.histogram" => Some(u.histogram), "view.clipping" => Some(u.show_clipping), "view.visualizeHdr" => Some(u.hdr_visualize), diff --git a/crates/ui-egui/src/menus.rs b/crates/ui-egui/src/menus.rs index f5f2d93a..f1ee45f5 100644 --- a/crates/ui-egui/src/menus.rs +++ b/crates/ui-egui/src/menus.rs @@ -202,6 +202,8 @@ pub const UI_COMMANDS: &[UiCommand] = &[ ("app.about", "About LightCraft", None, "Help"), ("app.systemInfo", "System Info…", None, "Help"), ("app.openLogFolder", "Open Log Folder", None, "Help"), + // the frame-rate display (`frame_rate`): a debugging aid, never saved + ("view.frameRate", "Show Frame Rate", None, "Help>Debug"), ("app.whatsNew", "What's New", None, "Help"), ("dialog.cull", "Assisted Culling…", None, "Photo"), ("app.help", "LightCraft Help", Some("F1"), "Help"), @@ -673,6 +675,11 @@ pub fn run_ui_command(app: &mut LightcraftApp, id: &str, p: &Value) -> Option { + // {show?: bool} (toggles when omitted) + app.ui.frame_rate = p.get("show").and_then(Value::as_bool).unwrap_or(!app.ui.frame_rate); + Ok(json!({"show": app.ui.frame_rate})) + } "view.leftPanel" => { app.ui.left_panel = !app.ui.left_panel; Ok(Value::Null) diff --git a/crates/ui-egui/src/render.rs b/crates/ui-egui/src/render.rs index fd0f0e9b..18c4980e 100644 --- a/crates/ui-egui/src/render.rs +++ b/crates/ui-egui/src/render.rs @@ -195,6 +195,8 @@ pub struct Renderer { pub last_main_ms: f64, /// Jobs finished since start (for inspect/perf). pub completed: u64, + /// Finished jobs thrown away because a newer request for their slot had replaced them. + pub discarded: u64, /// Keep a CPU copy of every texture so the UI can be rasterized headlessly (set when the app /// is driven by the control channel). pub keep_pixels: bool, @@ -271,6 +273,7 @@ impl Renderer { live_hdr_histogram: None, last_main_ms: 0.0, completed: 0, + discarded: 0, keep_pixels: false, stages: HashMap::new(), quick_tried: HashMap::new(), @@ -725,6 +728,7 @@ impl Renderer { && self.shown_ids.get(&slot).is_none_or(|shown| r.request_id > *shown) && r.rendered.is_ok(); if !newer_draft { + self.discarded += 1; continue; } session.accept(&r); diff --git a/crates/ui-egui/src/state.rs b/crates/ui-egui/src/state.rs index 44d74919..2283b356 100644 --- a/crates/ui-egui/src/state.rs +++ b/crates/ui-egui/src/state.rs @@ -496,6 +496,10 @@ pub struct UiState { /// a later save succeeds). #[serde(skip)] pub unsaved_seen: bool, + /// Help ▸ Debug ▸ Show Frame Rate (`view.frameRate`): the frame-rate display + /// (`crate::frame_rate`). A debugging aid, never saved; `LIGHTCRAFT_FPS=1` starts with it on. + #[serde(skip)] + pub frame_rate: bool, pub view: ViewMode, pub left_panel: bool, pub right: RightPanel, @@ -1039,6 +1043,7 @@ impl Default for UiState { language: crate::i18n::default_language(), preview_build_seen: None, unsaved_seen: false, + frame_rate: std::env::var("LIGHTCRAFT_FPS").is_ok_and(|v| matches!(v.trim(), "1" | "on" | "true" | "yes")), luminance_map_restore: None, view: ViewMode::Detail, left_panel: false, diff --git a/docs/gpu-pipeline.md b/docs/gpu-pipeline.md index 4dbfa537..be22fb44 100644 --- a/docs/gpu-pipeline.md +++ b/docs/gpu-pipeline.md @@ -250,6 +250,13 @@ Remaining differences come from f32 vs f64 coordinate math, fast-math transcende Metal and running-sum order in the box filters — all far below one 8-bit step. ## Measurements +**In the app:** Help ▸ Debug ▸ Show Frame Rate (`view.frameRate`, `{show?}`; `LIGHTCRAFT_FPS=1` +starts with it on, never saved) draws frames per second, each frame's UI CPU time against its +time spent waiting (for vsync, or for the GPU), the latest whole-frame and zoom-window render +times, the render queue, renders thrown away as superseded, the GPU adapter and its memory, and a +graph of the last frames with a tick where a render arrived. Once a second it logs the same +numbers (`fps-hud:`), so a scripted drag (`ui.dragWidget`) can be measured from the log. + `render_bench` on `corpus/raw/arw-sony-a7m3-compressed.arw` (24 MP; loupe = 2560 px preview → 1920×1280), min of 7 runs, wall clock, on a heavily shared machine (load average 60–110 on 14 cores, so CPU numbers are pessimistic; the GPU numbers are less affected):