From 1c70b24c748134fd171ab3c208eaeb55ff3a3e82 Mon Sep 17 00:00:00 2001 From: dev-null-undefined Date: Tue, 13 Oct 2026 02:21:46 +0200 Subject: [PATCH] M5.7: perf harnesses for slider latency, zoom windows and photo loading (examples only) - drag_latency (ui-egui example): the whole app driven headless at 60 frames a second; per develop control, the latency of each drag tick until its draft is the loupe (or, with ZOOM, the zoom window) texture, the ticks never shown, the UI thread's frame time and the time to the full-quality render after release. - drag_tick_bench (engine example): the UI-thread work of one drag tick outside the render. - render_bench: ONLY=window (a 1:1 zoom window cut from the original: first window, pan, slider changes; GPU_ONLY=1, DUMP=file for pixel A/B), ONLY=load / load1 / jpeg (+ LOADONLY=1): the steps of opening a photo. The window rows carry no colon in their names, so `cargo xtask bench` records each of them (parser test). - open_timeline (ui-egui example): opening raws in Detail through the real app logic, headless with the GPU. Co-Authored-By: Claude --- crates/engine/examples/drag_tick_bench.rs | 42 ++++ crates/engine/examples/render_bench.rs | 139 ++++++++++++- crates/ui-egui/examples/drag_latency.rs | 229 ++++++++++++++++++++++ crates/ui-egui/examples/open_timeline.rs | 74 +++++++ xtask/src/bench.rs | 7 +- 5 files changed, 487 insertions(+), 4 deletions(-) create mode 100644 crates/engine/examples/drag_tick_bench.rs create mode 100644 crates/ui-egui/examples/drag_latency.rs create mode 100644 crates/ui-egui/examples/open_timeline.rs diff --git a/crates/engine/examples/drag_tick_bench.rs b/crates/engine/examples/drag_tick_bench.rs new file mode 100644 index 000000000..c45cb6857 --- /dev/null +++ b/crates/engine/examples/drag_tick_bench.rs @@ -0,0 +1,42 @@ +//! UI-thread work one slider-drag tick costs outside the render: `develop.set` inside an +//! interaction, the filmstrip's `visible()` after the catalog revision moved, and the settings +//! hash the loupe takes every frame. `cargo run --release -p lightcraft-engine --example +//! drag_tick_bench -- [photos]` (default 20000). +#![allow(clippy::unwrap_used, clippy::expect_used)] + +use lightcraft_catalog::{Op, Photo, PhotoId, Source}; +use lightcraft_engine::Session; +use serde_json::json; +use std::time::Instant; + +fn main() { + let n: u64 = std::env::args().nth(1).and_then(|a| a.parse().ok()).unwrap_or(20_000); + let mut s = Session::new(); + for i in 1..=n { + let mut p = Photo::new(PhotoId(i), Source::File { path: format!("/x/{i}.ARW") }, &format!("{i}.ARW"), "ARW", 9984, 6656, "2026-01-01"); + p.captured = Some(format!("2025-{:02}-{:02}T10:{:02}:00", 1 + i % 12, 1 + i % 28, i % 60)); + s.catalog.apply(Op::AddPhoto { photo: Box::new(p) }).unwrap(); + } + s.execute("library.select", &json!({"ids": [1]})).unwrap(); + let ms = |t: Instant| t.elapsed().as_secs_f64() * 1e3; + s.visible_cloned(); + s.execute("develop.beginInteraction", &json!({"label": "Exposure"})).unwrap(); + let ticks = 30; + let (mut set, mut vis, mut hash) = (0.0, 0.0, 0.0); + for k in 0..ticks { + let t = Instant::now(); + s.execute("develop.set", &json!({"control": "light.exposure", "value": k as f64 / 30.0})).unwrap(); + set += ms(t); + let t = Instant::now(); + let v = s.visible_cloned(); + vis += ms(t); + assert_eq!(v.len() as u64, n); + let d = s.develop_of(PhotoId(1)).unwrap(); + let t = Instant::now(); + std::hint::black_box(d.hash64()); + hash += ms(t); + } + s.execute("develop.endInteraction", &json!({})).unwrap(); + let f = ticks as f64; + println!("{n} photos, per tick: develop.set {:.3} ms, visible() {:.3} ms, settings hash64 {:.3} ms", set / f, vis / f, hash / f); +} diff --git a/crates/engine/examples/render_bench.rs b/crates/engine/examples/render_bench.rs index 6a473a2de..3d7dbc445 100644 --- a/crates/engine/examples/render_bench.rs +++ b/crates/engine/examples/render_bench.rs @@ -9,7 +9,15 @@ //! export of each (decode + render + encode). Prints minimum wall-clock and minimum process CPU //! time: on a shared machine the CPU time shows the work done, wall-clock also the wait for cores. //! Each scenario runs on the CPU pipeline and, when a GPU adapter exists, on `lightcraft-gpu` -//! (second column; `LIGHTCRAFT_GPU=0` for the CPU only). +//! (second column; `LIGHTCRAFT_GPU=0` for the CPU only, `GPU_ONLY=1` for the GPU only). +//! +//! `ONLY=window`: a 1:1 zoom window cut from the full-size original (the loupe's `Slot::Region`): +//! the first window of a photo, a pan, and exposure / draft / NR changes with a warm stage cache; +//! `DUMP=file` writes the GPU window's RGBA bytes, for pixel A/B comparisons between builds. +//! Opening a photo, per file: `ONLY=source` (decode steps), `ONLY=load` (what the app's loaders +//! cost: file read, decode, binning, embedded stand-ins, `load_bytes(2560)`, the fs loader), +//! `ONLY=load1` (decode checksum + `load_bytes(2560)`; `LOADONLY=1`: only that, for a profiler), +//! `ONLY=jpeg` (a JPEG decoded to fit 256–2560 px boxes). use std::sync::Arc; use std::time::Instant; @@ -88,6 +96,63 @@ fn main() { let n: usize = std::env::var("N").ok().and_then(|v| v.parse().ok()).unwrap_or(5); let only = std::env::var("ONLY").unwrap_or_default(); let run = |name: &str| only.is_empty() || only.split(',').any(|o| name.contains(o)); + if only == "jpeg" { + // a JPEG (e.g. an embedded preview pulled out with exiftool) decoded to fit a few boxes + for path in &args { + let bytes = std::fs::read(path).expect("read"); + for edge in [256u32, 512, 1600, 2560] { + let o = lightcraft_codecs::DecodeOptions::fit(edge, edge); + let d = lightcraft_codecs::decode(&bytes, o).expect("decode"); + println!( + " {path} fit {edge}: {}×{} {}", + d.image.width, + d.image.height, + best(n, || drop(lightcraft_codecs::decode(&bytes, o).expect("decode"))) + ); + } + } + return; + } + if only == "load" || only == "load1" { + // opening a photo in the loupe, step by step: what the app's loaders cost (per file) + for path in &args { + let bytes = std::fs::read(path).expect("read"); + println!("{path}"); + if std::env::var("LOADONLY").is_ok() { + // only the preview load (for a profiler) + println!(" {:<36} {}", "load_bytes(2560):", best(n, || drop(lightcraft_engine::files::load_bytes(&bytes, 2560).expect("load")))); + continue; + } + println!(" {:<36} {}", "file read:", best(n, || drop(std::fs::read(path).expect("read")))); + println!(" {:<36} {}", "raw decode:", best(n, || drop(lightcraft_raw::decode(&bytes).expect("decode")))); + let mut raw = lightcraft_raw::decode(&bytes).expect("decode"); + if let lightcraft_raw::RawData::U16(d) = &raw.data { + let sum = d.iter().enumerate().fold(0u64, |a, (i, &v)| a.wrapping_mul(31).wrapping_add(v as u64 ^ i as u64)); + println!(" decode checksum: {sum:016x}"); + } + if only == "load1" { + println!(" {:<36} {}", "load_bytes(2560):", best(n, || drop(lightcraft_engine::files::load_bytes(&bytes, 2560).expect("load")))); + continue; + } + raw.opcodes.list3.retain(|op| !op.is_lens_correction()); + if let Some(k) = lightcraft_engine::files::bin_factor(&raw, 2560) { + println!(" {:<36} {}", format!("binned ×{k} masked:"), best(n, || drop(raw.develop_binned_masked(k, 0.99)))); + } + for edge in [2560usize, 1600] { + println!( + " {:<36} {}", + format!("embedded srgb, whole file ({edge}):"), + best(n, || drop(lightcraft_engine::files::embedded_preview_srgb(&bytes, edge))) + ); + let quick = lightcraft_engine::files::fs_preview_loader(); + println!(" {:<36} {}", format!("fs_preview_loader ({edge}):"), best(n, || drop(quick(path, edge)))); + } + println!(" {:<36} {}", "load_bytes(2560):", best(n, || drop(lightcraft_engine::files::load_bytes(&bytes, 2560).expect("load")))); + let (loader, _) = lightcraft_engine::files::fs_hooks(); + println!(" {:<36} {}", "fs loader (2560, read+load):", best(n, || drop(loader(path, 2560).expect("load")))); + } + return; + } if only == "source" { // opening a photo: where the time goes before the first sharp loupe (per file) for path in &args { @@ -152,10 +217,16 @@ fn main() { Some(a) => println!("gpu: {a} (device + kernels: {:.0} ms)", t.elapsed().as_secs_f64() * 1e3), None => println!("gpu: none"), } - let backends: &[bool] = if gpu { &[false, true] } else { &[false] }; + // `GPU_ONLY=1`: skip the CPU column (profiling the GPU path) + let backends: &[bool] = match (gpu, std::env::var_os("GPU_ONLY").is_some()) { + (true, true) => &[true], + (true, false) => &[false, true], + _ => &[false], + }; let row = |name: &str, f: &mut dyn FnMut(bool)| { let cols: Vec = backends.iter().map(|&g| format!("{}", best(n, || f(g)))).collect(); - println!("{name:<38} cpu: {}{}", cols[0], cols.get(1).map(|g| format!(" | gpu: {g}")).unwrap_or_default()); + let first = if backends[0] { "gpu" } else { "cpu" }; + println!("{name:<38} {first}: {}{}", cols[0], cols.get(1).map(|g| format!(" | gpu: {g}")).unwrap_or_default()); }; let preview = Arc::new(fit(&full, 2560, 2560, Filter::Box)); let s = typical(); @@ -214,6 +285,68 @@ fn main() { drop(develop(&preview, &info, &t, &view, Some(&caches[g as usize]), g)); }); } + if run("window") { + // a 1:1 zoom window (the loupe's `Slot::Region`): visible 1920×1200 + margin, snapped to the + // 256 px grid, cut from the full-resolution original (`ui-egui` `region::window_for`) + use lightcraft_pipeline::PixelWindow; + let (fw, fh) = (full.width, full.height); + let win = |cx: usize, cy: usize| { + let snap = |v: usize| v / 256 * 256; + let (x, y) = (snap(cx.saturating_sub(960 + 512)), snap(cy.saturating_sub(600 + 512))); + PixelWindow { x, y, w: 3072.min(fw - x), h: 2304.min(fh - y) } + }; + let at = |w: PixelWindow, q: Quality| RenderRequest { window: Some(w), quality: q, ..RenderRequest::fit(fw, fh) }; + let w0 = win(fw / 2, fh / 2); + println!("window {}×{} at ({}, {}) of {fw}×{fh}", w0.w, w0.h, w0.x, w0.y); + // first window of a photo: nothing cached (the GPU uploads the original: `shared_source`) + row("window first (upload original):", &mut |g| { + lightcraft_engine::gpu::trim_pool(0); + drop(develop(&full, &info, &s, &at(w0, Quality::Full), Some(&StageCache::default()), g)) + }); + let wc = [StageCache::default(), StageCache::default()]; + for g in backends { + drop(develop(&full, &info, &s, &at(w0, Quality::Full), Some(&wc[*g as usize]), *g)); + } + let mut step = 0usize; + row("window pan (new window, warm src):", &mut |g| { + step += 1; + let w = win(fw / 2 + 512 * (step % 4 + 1), fh / 2); + drop(develop(&full, &info, &s, &at(w, Quality::Full), Some(&wc[g as usize]), g)) + }); + for g in backends { + drop(develop(&full, &info, &s, &at(w0, Quality::Full), Some(&wc[*g as usize]), *g)); + } + row("window exposure change (warm):", &mut |g| { + let mut t = s.clone(); + k += 1.0; + t.light.exposure = 0.3 + k * 0.01; + drop(develop(&full, &info, &t, &at(w0, Quality::Full), Some(&wc[g as usize]), g)); + }); + row("window draft exposure drag (warm):", &mut |g| { + let mut t = s.clone(); + k += 1.0; + t.light.exposure = 0.3 + k * 0.01; + drop(develop(&full, &info, &t, &at(w0, Quality::Draft), Some(&wc[g as usize]), g)); + }); + row("window NR change (warm):", &mut |g| { + let mut t = s.clone(); + k += 1.0; + t.detail.nr_luminance = 30.0 + k % 50.0; + drop(develop(&full, &info, &t, &at(w0, Quality::Full), Some(&wc[g as usize]), g)); + }); + // `DUMP=file`: the GPU window's raw RGBA bytes (A/B pixel comparisons between builds) + if let (true, Some(path)) = (gpu, std::env::var_os("DUMP")) { + let g = develop(&full, &info, &s, &at(w0, Quality::Full), Some(&StageCache::default()), true).image; + let bytes: Vec = g.data.iter().flatten().copied().collect(); + std::fs::write(path, bytes).expect("dump"); + } + if gpu && std::env::var_os("GPU_ONLY").is_none() { + let c = develop(&full, &info, &s, &at(w0, Quality::Full), None, false).image; + let g = develop(&full, &info, &s, &at(w0, Quality::Full), None, true).image; + let (max, mean) = diff(&c, &g); + println!("gpu vs cpu, window: max {max} LSB, mean {mean:.4} LSB"); + } + } if run("finish") { // per-pixel stage cost by feature (warm cache: exposure changes only) let variants: [(&str, fn(&mut DevelopSettings)); 6] = [ diff --git a/crates/ui-egui/examples/drag_latency.rs b/crates/ui-egui/examples/drag_latency.rs new file mode 100644 index 000000000..322abd828 --- /dev/null +++ b/crates/ui-egui/examples/drag_latency.rs @@ -0,0 +1,229 @@ +//! Slider-drag latency through the whole app: the real session, renderer, job pool and GPU (when +//! there is one), driven by a headless host at 60 frames a second, as a window with vsync would be. +//! +//! `cargo run --release -p lightcraft-ui-egui --example drag_latency -- LIBRARY_DIR PHOTO [CONTROL…]` +//! Env: `SIZE=1920x1200` (points), `SCALE=1`, `TICKS=30`, `GPU=0` for the CPU pipeline. +//! +//! Per control: a drag of `TICKS` value changes, one per frame; for each tick the frames (and ms) +//! until its draft became the loupe texture, how many ticks were never shown, the UI thread's +//! frame time, and after release the time until the full-quality render is the texture. (A window +//! presents the texture one frame later: add ~16.7 ms for photons.) +#![allow(clippy::unwrap_used, clippy::expect_used)] + +use std::collections::HashMap; +use std::time::{Duration, Instant}; + +use lightcraft_engine::Session; +use lightcraft_ui_egui::headless::Headless; +use lightcraft_ui_egui::render::Slot; +use lightcraft_ui_egui::{LightcraftApp, Services}; +use serde_json::json; + +const FRAME: Duration = Duration::from_micros(16_667); + +const CONTROLS: &[(&str, f64, f64)] = &[ + ("light.exposure", 0.0, 1.0), + ("light.contrast", 0.0, 50.0), + ("light.highlights", 0.0, -60.0), + ("light.shadows", 0.0, 60.0), + ("light.whites", 0.0, 40.0), + ("light.blacks", 0.0, -40.0), + ("wb.temp", 5000.0, 6500.0), + ("wb.tint", 0.0, 20.0), + ("color.vibrance", 0.0, 40.0), + ("color.saturation", 0.0, 30.0), + ("curve.shadows", 0.0, 30.0), + ("mixer.orange.hue", 0.0, 30.0), + ("mixer.blue.sat", 0.0, -40.0), + ("grading.shadows.sat", 0.0, 30.0), + ("calibration.redHue", 0.0, 30.0), + ("effects.texture", 0.0, 40.0), + ("effects.clarity", 0.0, 40.0), + ("effects.dehaze", 0.0, 30.0), + ("vignette.amount", 0.0, -40.0), + ("grain.amount", 0.0, 30.0), + ("detail.sharpenAmount", 40.0, 90.0), + ("detail.nrLuminance", 0.0, 40.0), + ("detail.nrColor", 25.0, 60.0), + ("optics.distortion", 0.0, 30.0), + ("optics.vignetting", 0.0, 50.0), + ("optics.defringePurple", 0.0, 5.0), + ("geometry.vertical", 0.0, 20.0), +]; + +/// Step one frame at the 60 Hz cadence that started at `t0`. +fn frame(h: &mut Headless, t0: Instant, n: &mut u32) -> f64 { + *n += 1; + let due = t0 + FRAME * *n; + if let Some(d) = due.checked_duration_since(Instant::now()) { + std::thread::sleep(d); + } + let t = Instant::now(); + h.step(); + t.elapsed().as_secs_f64() * 1e3 +} + +/// The view slot measured: the zoom window with `ZOOM=` (set after opening), else the loupe. +fn watch() -> Slot { + if ZOOMED.load(std::sync::atomic::Ordering::Relaxed) { Slot::Region } else { Slot::Main } +} + +static ZOOMED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); + +fn settle(h: &mut Headless, id: lightcraft_catalog::PhotoId) { + let t = Instant::now(); + while t.elapsed() < Duration::from_secs(120) { + h.step(); + let r = &h.app.renderer; + let done = r.textures.get(&watch()).is_some_and(|t| t.photo == id && Some(t.key) == r.wanted(watch())) && !r.is_pending(watch()); + if done && !h.busy() { + return; + } + std::thread::sleep(Duration::from_millis(2)); + } + eprintln!("settle: timed out"); +} + +fn pct(v: &mut [f64], p: f64) -> f64 { + if v.is_empty() { + return f64::NAN; + } + v.sort_by(|a, b| a.total_cmp(b)); + v[((v.len() - 1) as f64 * p).round() as usize] +} + +fn main() { + let args: Vec = std::env::args().skip(1).collect(); + let (lib, file) = (args.first().expect("LIBRARY_DIR"), args.get(1).expect("PHOTO")); + let only: Vec<&str> = args[2..].iter().map(String::as_str).collect(); + let env = |k: &str, d: &str| std::env::var(k).unwrap_or_else(|_| d.to_string()); + let (w, hgt) = env("SIZE", "1920x1200").split_once('x').map(|(a, b)| (a.parse::().unwrap(), b.parse::().unwrap())).unwrap(); + let scale: f32 = env("SCALE", "1").parse().unwrap(); + let ticks: u32 = env("TICKS", "30").parse().unwrap(); + let gpu = env("GPU", "1") != "0"; + + let mut s = Session::new().with_fs().with_system_clock(); + s.open_library(lib, false).unwrap(); + let r = s.execute("library.import", &json!({"paths": [file]})).unwrap(); + let id = r["imported"].as_array().and_then(|a| a.first()).and_then(|v| v.as_u64()).map(lightcraft_catalog::PhotoId).unwrap_or_else(|| { + // already in the library + let name = std::path::Path::new(file).file_name().unwrap().to_string_lossy().to_string(); + s.catalog.photos().find(|p| p.file_name == name).map(|p| p.id).expect("photo in library") + }); + s.execute("library.select", &json!({"ids": [id.0]})).unwrap(); + let mut app = LightcraftApp::new(s, Services::default()); + app.ui.settings.gpu = gpu; + let mut h = Headless::new(app, [w, hgt], scale); + let t = Duration::from_secs(60); + h.request("ui.set", json!({"view": "detail", "right": "edit", "filmstrip": true}), t); + let t_open = Instant::now(); + settle(&mut h, id); + if let Ok(z) = std::env::var("ZOOM") { + let pct: f64 = z.parse().unwrap(); + h.app.run("view.navigate", json!({"zoom": {"percent": pct}, "pan": [0.5, 0.5]})).unwrap(); + for _ in 0..5 { + h.step(); + } + ZOOMED.store(true, std::sync::atomic::Ordering::Relaxed); + let t = Instant::now(); + settle(&mut h, id); + eprintln!("zoomed to {pct} % in {:.0} ms", t.elapsed().as_secs_f64() * 1e3); + } + let tex = h.app.renderer.textures.get(&watch()).map(|t| t.size); + eprintln!("opened in {:.0} ms, loupe texture {tex:?}, gpu {gpu}", t_open.elapsed().as_secs_f64() * 1e3); + + println!("control,shown/ticks,lat_frames_med,lat_ms_med,lat_ms_p90,lat_ms_max,frame_ms_med,frame_ms_max,final_ms,draft_px,final_px"); + // the controls named (in that order, repeats allowed), else all of them + let list: Vec<(&str, f64, f64)> = + if only.is_empty() { CONTROLS.to_vec() } else { only.iter().filter_map(|n| CONTROLS.iter().find(|c| c.0 == *n).copied()).collect() }; + for (control, a, b) in list { + let mut asked: HashMap = HashMap::new(); + let mut lat_frames = Vec::new(); + let mut lat_ms = Vec::new(); + let mut frame_ms = Vec::new(); + let mut shown_key = h.app.renderer.textures.get(&watch()).map(|t| t.key); + let mut draft_px = None; + let t0 = Instant::now(); + let mut n = 0u32; + h.app.run("develop.beginInteraction", json!({"label": control})).unwrap(); + #[allow(clippy::too_many_arguments)] + fn observe( + h: &Headless, + n: u32, + asked: &HashMap, + shown_key: &mut Option, + lat_frames: &mut Vec, + lat_ms: &mut Vec, + draft_px: &mut Option<[usize; 2]>, + ) { + let r = &h.app.renderer; + if let Some(tex) = r.textures.get(&watch()) + && Some(tex.key) != *shown_key + { + *shown_key = Some(tex.key); + if let Some((k, at)) = asked.get(&tex.key) { + lat_frames.push((n - k) as f64); + lat_ms.push(at.elapsed().as_secs_f64() * 1e3); + *draft_px = Some(tex.size); + } + } + } + for i in 1..=ticks { + let v = a + (b - a) * i as f64 / ticks as f64; + // the event arrives at the start of the frame (as input does) + let due = t0 + FRAME * (n + 1); + if let Some(d) = due.checked_duration_since(Instant::now()) { + std::thread::sleep(d); + } + let start = Instant::now(); + h.app.run("develop.set", json!({"control": control, "value": v})).unwrap(); + n += 1; + h.step(); + frame_ms.push(start.elapsed().as_secs_f64() * 1e3); + if let Some(k) = h.app.renderer.wanted(watch()) { + asked.entry(k).or_insert((n, start)); + } + observe(&h, n, &asked, &mut shown_key, &mut lat_frames, &mut lat_ms, &mut draft_px); + } + // release + let due = t0 + FRAME * (n + 1); + if let Some(d) = due.checked_duration_since(Instant::now()) { + std::thread::sleep(d); + } + let release = Instant::now(); + h.app.run("develop.endInteraction", json!({})).unwrap(); + let mut final_ms = f64::NAN; + let mut final_px = None; + while release.elapsed() < Duration::from_secs(60) { + let fm = frame(&mut h, t0, &mut n); + frame_ms.push(fm); + observe(&h, n, &asked, &mut shown_key, &mut lat_frames, &mut lat_ms, &mut draft_px); + let r = &h.app.renderer; + if h.app.session.interaction.is_none() + && let Some(tex) = r.textures.get(&watch()) + && Some(tex.key) == r.wanted(watch()) + && !r.is_pending(watch()) + { + final_ms = release.elapsed().as_secs_f64() * 1e3; + final_px = Some(tex.size); + break; + } + } + let shown = lat_ms.len(); + let fmax = frame_ms.iter().cloned().fold(0.0, f64::max); + let lmax = lat_ms.iter().cloned().fold(0.0, f64::max); + println!( + "{control},{shown}/{ticks},{:.0},{:.1},{:.1},{lmax:.1},{:.1},{fmax:.1},{final_ms:.1},{:?},{:?}", + pct(&mut lat_frames, 0.5), + pct(&mut lat_ms, 0.5), + pct(&mut lat_ms, 0.9), + pct(&mut frame_ms, 0.5), + draft_px.unwrap_or([0, 0]), + final_px.unwrap_or([0, 0]), + ); + // back to where it was (one undo step), settled + h.app.run("develop.set", json!({"control": control, "value": a})).unwrap(); + settle(&mut h, id); + std::thread::sleep(Duration::from_millis(200)); + } +} diff --git a/crates/ui-egui/examples/open_timeline.rs b/crates/ui-egui/examples/open_timeline.rs new file mode 100644 index 000000000..730092420 --- /dev/null +++ b/crates/ui-egui/examples/open_timeline.rs @@ -0,0 +1,74 @@ +//! Opening raw photos in the loupe, timed through the real app logic, headless (no compositor, so no frame +//! throttling) but with the GPU on: import FILES into an in-memory library, open the first in Detail, then step to +//! the next one once its neighbour prefetch is done and once more at once. +//! `cargo run --release -p lightcraft-ui-egui --example open_timeline -- a.ARW b.ARW c.ARW` +//! (`LIGHTCRAFT_PROFILE=1` adds the engine's stage timings; every line carries ms since start on stderr). +use lightcraft_engine::Session; +use lightcraft_ui_egui::{LightcraftApp, Services, headless::Headless}; +use serde_json::{Value, json}; +use std::time::{Duration, Instant}; + +fn main() { + let files: Vec = std::env::args().skip(1).collect(); + let t0 = Instant::now(); + let ms = move || t0.elapsed().as_secs_f64() * 1e3; + let mut s = Session::new().with_fs(); + let r = s.execute("library.import", &json!({"paths": files})).expect("import"); + eprintln!("{:9.1} imported {}", ms(), r["imported"]); + let mut h = Headless::new(LightcraftApp::new(s, Services::default()), [1600.0, 1000.0], 1.0); + let req = |h: &mut Headless, m: &str, p: Value| h.request(m, p, Duration::from_secs(60)); + let cmd = |h: &mut Headless, c: &str| req(h, "engine.execute", json!({"command": c}))["result"].clone(); + cmd(&mut h, "view.photoGrid"); + h.settle(Duration::from_secs(60)); + cmd(&mut h, "library.selectNone"); + let r = cmd(&mut h, "library.next"); + eprintln!("{:9.1} first: {r}", ms()); + let first = r["active"].as_u64().unwrap_or(1); + h.settle(Duration::from_secs(60)); + let gpu = req(&mut h, "ui.inspect", json!({}))["result"]["perf"]["gpu"].clone(); + eprintln!("{:9.1} grid settled, gpu {gpu}", ms()); + // what the loupe shows, every frame, until `photo` is rendered for good + let watch = |h: &mut Headless, label: &str, photo: u64| { + let start = ms(); + let mut last = String::new(); + loop { + let i = req(h, "ui.inspect", json!({}))["result"].clone(); + let l = &i["loupe"]; + let state = format!("photo={} source={} pending={}", l["photo"], l["source"], l["pending"]); + if state != last { + eprintln!( + "{:9.1} [{label}] +{:7.1} ms {state} (queue {}, in flight {})", + ms(), + ms() - start, + i["perf"]["renderQueue"], + i["perf"]["rendersInFlight"] + ); + last = state; + } + let done = l["photo"].as_u64() == Some(photo) && matches!(l["source"].as_str(), Some("render" | "cached")) && l["pending"] == false; + if done || ms() - start > 30_000.0 { + return ms() - start; + } + } + }; + eprintln!("{:9.1} open {first}", ms()); + cmd(&mut h, "view.detail"); + let open = watch(&mut h, "open", first); + let t = ms(); + h.settle(Duration::from_secs(60)); + eprintln!("{:9.1} neighbours prefetched after {:.0} ms", ms(), ms() - t); + // step towards the side that has photos (the sort may put the first one last) + let mut dir = "library.next"; + let mut r = cmd(&mut h, dir); + if r["active"].as_u64() == Some(first) { + dir = "library.previous"; + r = cmd(&mut h, dir); + } + eprintln!("{:9.1} {dir}: {r}", ms()); + let n1 = r["active"].as_u64().unwrap_or(0); + let step1 = watch(&mut h, "next (prefetched)", n1); + let n2 = cmd(&mut h, dir)["active"].as_u64().unwrap_or(0); + let step2 = watch(&mut h, "next at once", n2); + h.settle(Duration::from_secs(60)); + eprintln!("{:9.1} summary: open {open:.0} ms, next prefetched {step1:.0} ms, next at once {step2:.0} ms", ms()); +} diff --git a/xtask/src/bench.rs b/xtask/src/bench.rs index 7f94f37fb..9c4d2bd3e 100644 --- a/xtask/src/bench.rs +++ b/xtask/src/bench.rs @@ -135,6 +135,8 @@ mod tests { gpu vs cpu, loupe 1920×1280 typical: max 1 LSB, mean 0.0001 LSB loupe draft 1152×768 cold: cpu: 379.5 ms wall, 139.5 ms cpu | gpu: 19.9 ms wall, 17.2 ms cpu export JPEG encode: 63.9 ms wall, 278.0 ms cpu +window 3072×2304 at (3328, 2048) of 9984×6656 +window pan (new window, warm src): cpu: 912.0 ms wall, 2210.5 ms cpu | gpu: 37.5 ms wall, 8.7 ms cpu "; #[test] @@ -143,7 +145,10 @@ export JPEG encode: 63.9 ms wall, 278.0 ms cpu assert_eq!(m["loupe draft 1152×768 cold/cpu/wall"], 379.5); assert_eq!(m["loupe draft 1152×768 cold/gpu/cpu"], 17.2); assert_eq!(m["export JPEG encode/cpu/cpu"], 278.0); - assert_eq!(m.len(), 6, "{m:?}"); + // (a comma in the name is no column separator) + assert_eq!(m["window pan (new window, warm src)/cpu/cpu"], 2210.5); + assert_eq!(m["window pan (new window, warm src)/gpu/wall"], 37.5); + assert_eq!(m.len(), 10, "{m:?}"); } #[test]