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]