Merge PR #1421

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);
+}

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<String> = 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<u8> = 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] = [

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=<percent>` (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<String> = 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::<f32>().unwrap(), b.parse::<f32>().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<u64, (u32, Instant)> = 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<u64, (u32, Instant)>,
+            shown_key: &mut Option<u64>,
+            lat_frames: &mut Vec<f64>,
+            lat_ms: &mut Vec<f64>,
+            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));
+    }
+}

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<String> = 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());
+}

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]