From a6b5e3192417d8efd9cd1f4615f49027fe6c109d Mon Sep 17 00:00:00 2001 From: Greg Pomerantz Date: Wed, 28 Oct 2026 00:43:35 -0400 Subject: [PATCH] Jank hunt: repro on emulator, rule out 6 causes, add A/B tooling Findings (emulator programmatic-scroll repro, phone log data): - In-place cell updates (cells.set_row_data) replaced whole-row replacement: no subtree teardown, texture upload only on pixel change. MAX_PAINT_CELLS_PER_TICK=2. - Static placeholder replaces the animation-tick() shimmer: the per-cell sin() binding was O(all 8577 cells) every frame (71% CPU idle). O(visible) shimmer is M6 work. - nblog: non-blocking logger (bounded mpsc + drain thread calling __android_log_write). logd backpressure was stalling the UI thread 10-40 ms. android_logger dependency no longer used on-device. - cpuload (SELinux-blocked) removed; min_refresh_rate=120 pin kills the SystemUI 60Hz flap (noted in HANDOFF, reversible). - Emulator: during every 28-146 ms stall the UI thread is 100% on-CPU; capping the list to 300 items does NOT help (scene size is not the cost); grey 1x1 images cut 30-146 ms to a steady ~16.6 ms -> the cost is software-GL rasterization of ~30 textured cells at 1080x2400 (emulator ceiling; the emulator validates logic, not feel). - Phone 28-39 ms spikes are NOT first-paint/upload timing (they happen ~10x more often than cells enter the viewport) and not upload CPU cost (1.2-2.9 ms). Left: GPU/present contention vs Slint EGL path. Tooling (all tagged REMOVE after the hunt, file-gated, off by default): - .gallery_cmd scroll hook + SCRDBG/TICK/APLY logs - .gallery_max (item cap) and .gallery_grey (1x1 images) A/B knobs - HANDOFF 8.5: full findings + decisive phone A/B plan for tomorrow - jsample.c (NDK /proc sampler, /tmp): per-thread state+wchan Also: fix pre-existing doctest (indented module-doc block parsed as Rust); 15 unit tests + doctest green; aarch64 release APK builds. --- HANDOFF.md | 65 +++++ src/lib.rs | 652 +++++++++++++++++++++++++++++++++++++------------ src/main.slint | 39 ++- src/thumb.rs | 2 +- 4 files changed, 586 insertions(+), 172 deletions(-) diff --git a/HANDOFF.md b/HANDOFF.md index 0c0ef00..0f8efca 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -336,6 +336,71 @@ Measure with: `adb shell am start -W` (cold start), `dumpsys gfxinfo wow.gmp.gallery framestats`, Perfetto trace (GPU + main + pool threads), and `logcat` pool timing logs behind a `debug_timing` flag. +## 8.5 Jank hunt (IN PROGRESS — phone is the acceptance target) + +Symptom: user reports janky grid scroll (moderate drag, no fling) on the +phone (Pixel 9 Pro, 120 Hz). Emulator repro via programmatic scroll hook. + +### What is ruled out (all measured) +- **App tick cost**: 7–34 µs/tick, even inside 28–39 ms gaps. Not the tick. +- **Logd backpressure**: fixed — `nblog` (bounded mpsc + drain thread, + nanosecond `try_send` from UI). Idle CPU 71% → 5%. +- **60/120 Hz display zone flap**: SystemUI (uid 10156) was asserting a 60 Hz + override every minute; pinned with `settings put system min_refresh_rate + 120` (reversible: `settings delete system min_refresh_rate`). +- **Shimmer animation**: `animation-tick()` in a per-cell binding evaluated + O(ALL 8577 cells) `sin()` every frame (70.9% CPU idle). Now a static + placeholder; proper O(visible) shimmer is M6 work. +- **Whole-row model replacement**: now in-place `cells.set_row_data` (one + property change; texture upload only when pixels change). +- **Texture upload CPU**: APLY 1.2–2.9 ms/cell (480 KB) — under budget, and + too cheap to explain 28–39 ms (would need 12–17 MB/s on a Mali). + +### Measured facts +- Emulator, programmatic scroll (`/sdcard/Download/.gallery_cmd` → + `scroll `), real textures: 28–146 ms cadence. During every + stall the UI thread is **100 % on-CPU** (jsample: state R, wchan 0) — + Slint's render pass is CPU-bound. +- Emulator, 300 items instead of 5852: **equally janky** → scene/item count + is NOT the cost driver. +- Emulator, grey 1×1 images (`.gallery_grey` touch file): steady ~16.6 ms + (60 Hz pacing), worst 44 ms → the cost is **rasterizing ~30 live textured + cells at 1080×2400 through the emulator's software GL (llvmpipe)**. + The emulator has a hard rendering ceiling and can never scroll this + smoothly — it validates LOGIC (invariants, paint coverage), not feel. +- Phone: 64 % of frames on the 8.3 ms (120 Hz) grid; ~4 % take 28–39 ms of + non-tick work with d≈0 (UI thread not in our code). Frequency ≈ every + 170 ms — much faster than new cells enter the viewport (~1.7 s), so it is + NOT first-paint/upload timing. Suspects left: GPU/present contention + (Mali + SystemUI both at 120 Hz), Slint EGL/swap path, or an + event-loop/vsync interaction. Needs the phone. + +### Tools / hooks in the tree (all tagged "REMOVE after the hunt") +- `src/lib.rs`: `DbgScroll` + `.gallery_cmd` file (also `stop`); + knobs `.gallery_max` (item cap) and `.gallery_grey` (1×1 grey images); + `SCRDBG`/`JANKTEST`/`TICK`/`APLY` logs at `info`. +- `jsample.c` (in /tmp, NDK-cross with + `~/android-sdk/ndk/27.0.12077973/.../x86_64-linux-android26 -static`): + per-thread `/proc stat` + state + wchan sampler at 1 ms; usage + `jsample `. + +### Next (phone, morning) +1. **Decisive A/B on the phone**: `touch /sdcard/Download/.gallery_grey`, + restart app, user scrolls 30 s, capture logcat. Then remove the file, + restart, repeat. Grey smooth + textured janky → texture/GPU path is the + culprit (then: smaller decode target, upload strategy, possibly Slint + image pipeline). Grey also janky → base render/present path (then: Slint + window/EGL config, refresh-rate interaction, vsync driver). +2. Run `jsample` over one of the user's real scrolls and wchan-correlate + the 28–39 ms windows (is android_main R, S/futex, or S/do_epoll_wait?). +3. Compare against Fossify (installed on the phone, user says smooth): + `dumpsys SurfaceFlinger --latency` on both apps' layers during identical + scrolls. +4. Candidate code changes (after the A/B): GRID_TARGET 500→400 (one-time + cache invalidation — don't do it before knowing the culprit), 1 painted + cell/tick instead of 2, worker nice level (+2) so turbojpeg bursts + can't preempt the UI thread. + ## 9. Milestones - **M0 — scaffold (DONE)**: builds (x86_64 + aarch64 toolchain), installs, diff --git a/src/lib.rs b/src/lib.rs index ce22087..2c1ef1a 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -4,31 +4,41 @@ //! - scan thread: one per launch, walks storage, owns the scan DB connection. //! - thumb engine: process-wide pool (dispatcher + N workers), created on the //! UI thread once; workers own one DB connection each (WAL). -//! - UI thread: owns the window + model; runs the reconcile tick 10x/s via a -//! Slint timer; builds `slint::Image` here (Image is !Send, pixel bytes are). +//! - UI thread: owns the window + model; runs the reconcile tick at display +//! rate (~120 Hz, VSync-quantized on Android) via a Slint timer; builds +//! `slint::Image` here (Image is !Send, pixel bytes are). //! -//! # Thumbnail loading: viewport reconciliation (rewritten 2026-10-27) +//! # Thumbnail loading: viewport reconciliation (v3, 2026-10-27) //! //! One source of truth for what matters: the **viewport** (visible rows ± -//! `MARGIN_ROWS`), updated by scroll events — and only by them. Scroll -//! handlers do no work; they move the target. +//! `MARGIN_ROWS`). Its ground truth is POLLED from the list's actual +//! geometry every tick (`list-y`/`list-height`/`list-width` in main.slint): +//! the `scrolled` callback is only a fast-path hint for drags, because +//! Slint 1.18's Flickable fires `flicked` on pointer moves and ONCE at fling +//! start — the momentum animation updates content-y per frame WITHOUT +//! re-firing it (i-slint-core items/flickable.rs, `animate()`). A callback- +//! only viewport freezes for the whole fling and is the "stop → shimmer → +//! small move → pop" bug. //! -//! The 10 Hz tick is the single authority. Every tick, looking only at -//! CURRENT state (never at scroll history): -//! 1. CONSUME: drain finished results; paint the viewport ones (capped); +//! The ~120 Hz tick is the single authority. Every tick, looking only at +//! CURRENT state (never at scroll history), doing work bounded to ONE frame +//! (≤4 cell paints + ≤4 cell evictions — spread across frames, never batched, +//! so content updates land every frame instead of in 100 ms pulses): +//! 1. CONSUME: drain finished results; paint the viewport ones (≤4 cells); //! drop the rest — every finished decode is on the disk cache, so a //! dropped result costs a ~10 ms cache hit on re-entry, never a re-decode. -//! 2. EVICT: release pixels for painted cells far outside the viewport -//! (farthest first; row-budgeted, plus a hard `MAX_PAINTED` cap). +//! 2. EVICT: release pixels for painted cells outside the RETENTION band +//! (viewport ± `RETENTION_ROWS`, farthest first; ≤4 cells/tick; hard +//! `MAX_PAINTED` cap). Retention (≈2 screens, ~165 MB) is much wider +//! than the submit margin so short back-scrolls are pixel-instant. //! 3. FILL: submit every viewport cell that has no pixels and no in-flight //! job, center-first. -//! 4. PRUNE: drop queued jobs outside the retention band (belt; the engine +//! 4. PRUNE: drop queued jobs outside the submit band (belt; the engine //! also enforces this per-worker — see below). //! -//! The invariant, RESTORED unconditionally each tick: -//! -//! every viewport cell is PAINTED, or has a job IN FLIGHT, -//! or is permanently FAILED (undecodable). +//! The invariant, RESTORED unconditionally each tick: every viewport cell +//! is PAINTED, or has a job IN FLIGHT, or is permanently FAILED +//! (undecodable). //! //! Because it is restored (not maintained), no scroll pattern, cap hit, //! dropped result, or list reset can leave a visible cell forgotten until @@ -45,14 +55,17 @@ //! A burst is never bigger than the viewport (~45), so fresh viewport work //! is never itself dropped. //! -//! Consequences (stress-verified 2026-10-27, emulator debug build): -//! - After any stop — fast up/down, cold landing, or chaos flicking — the -//! viewport is fully covered within decode throughput time (0–120 ms warm, -//! ~1 s for a cold 45-cell landing on a slow emulator; ~0.25 s on a phone). -//! - No stale backlog exists: measured oldest in-flight job after chaos -//! scrolling was 217 ms (pre-fix design: 8 s), max queue depth one -//! viewport. A visible cell is empty only while its decode is genuinely -//! in flight — never "until the next small scroll move". +//! Consequences (stress-verified 2026-10-27, emulator debug build + phone): +//! - Newly revealed cells are submitted within one tick (≤8–16 ms) of +//! becoming visible — including while a fling's momentum carries the list, +//! because the tick polls the real position. A disk-cache hit (5–15 ms) +//! finishes while the cell is still in the margin: back-scrolls within the +//! retention band are pixel-instant (0 ms), beyond it ~10–20 ms. +//! - No stale backlog exists: worker-queue prepend + cap keep the viewport +//! first (measured oldest in-flight job after chaos scrolling: 217 ms vs +//! 8 s pre-redesign; max queue depth one viewport). +//! - A visible cell is empty only while its decode is genuinely in flight — +//! never "until the next small scroll move". //! //! # Memory bound //! Grid cells decode at 500 px (~0.7 MB RGB8 each); the model may NOT keep @@ -80,7 +93,7 @@ use slint::{ }; use crate::scan::Entry; -use crate::thumb::{Engine, Job, JobResult, GRID_TARGET}; +use crate::thumb::{Engine, Job, JobResult, GRID_TARGET, MAX_WORKER_QUEUE}; /// Must match main.slint (GridRow layout + ListView spacing + padding). const GRID_COLS: usize = 3; @@ -88,20 +101,42 @@ const GRID_PADDING: f32 = 12.0; const GRID_GAP: f32 = 4.0; const ROW_SPACING: f32 = 4.0; /// Rows of margin around the visible range. The union is the "viewport": -/// the only cells the loader ever submits; painted cells at this distance -/// or beyond are evicted. +/// the only cells the loader submits. A margin of 4 rows means a cell is +/// submitted ~100 ms before it becomes visible at fling speed, so its +/// decode (disk-cache hit ≈ 5–15 ms) finishes before reveal. const MARGIN_ROWS: usize = 4; +/// Rows of pixel RETENTION around the viewport (L1 cache): painted cells +/// within this distance keep their pixels (instant re-show on back-scroll); +/// beyond it they are evicted to the disk cache (re-show ≈ 10–20 ms). +/// RETENTION > MARGIN on purpose: the RAM cost is 750 KB/cell and it makes +/// short back-scrolls pixel-instant (compute vs RAM: ~165 MB total, see +/// MAX_PAINTED). +const RETENTION_ROWS: usize = 32; /// Viewport used until the first scroll event (≈2 screens). const INITIAL_VIEWPORT_CELLS: usize = 60; -/// Hard cap on cells holding pixels in the model (memory safety valve for -/// pathological flicking; steady state is far below this). -const MAX_PAINTED: usize = 120; -/// Max ROW replacements per tick (paints + evictions share the budget). -/// Bounding per-tick work is what keeps the UI thread at frame rate: -/// without it, a mass update after a 200-cell cold fill ANR'd (2026-10-27). -const MAX_ROWS_PER_TICK: usize = 16; -const MAX_CELLS_PER_TICK: usize = MAX_ROWS_PER_TICK * GRID_COLS; -const DRAIN_INTERVAL_MS: u64 = 100; +/// Hard cap on cells holding pixels in the model: 225 × ~0.73 MB ≈ 165 MB +/// (≈1–2 % of a modern phone's RAM; bounded by RETENTION_ROWS in practice). +const MAX_PAINTED: usize = 225; +/// Jank-hunt test knob (REMOVE after): live cap on painted cells, default +/// MAX_PAINTED; overridable via /sdcard/Download/.gallery_max_painted. +static MAX_PAINTED_LIVE: std::sync::atomic::AtomicUsize = + std::sync::atomic::AtomicUsize::new(MAX_PAINTED); +/// Jank-hunt test knob (REMOVE after): 1x1 grey cell images (no texture work). +static JANK_GREY_IMAGES: std::sync::atomic::AtomicBool = + std::sync::atomic::AtomicBool::new(false); +/// Per-tick (per-frame) model work budgets. The tick runs at display rate +/// (~120 Hz): work MUST fit one frame, so updates are SPREAD across frames +/// instead of batched (the old 16-row/100 ms batch was visible as a content +/// pulse + frame hitches during scroll). Each update is an IN-PLACE nested +/// model mutation (one cell property change; texture upload only when the +/// pixels actually change) — cheap enough for 4+4 per tick. +const MAX_PAINT_CELLS_PER_TICK: usize = 2; +const MAX_EVICT_CELLS_PER_TICK: usize = 4; +/// Reconcile tick period. 8 ms ≈ one 120 Hz frame; Slint's event loop is +/// VSync-paced on Android, so the actual cadence quantizes to the display +/// refresh (8 ms on 120 Hz, ~16 ms on 60 Hz). Per-tick work is tiny and +/// idempotent, so jitter is harmless. +const DRAIN_INTERVAL_MS: u64 = 8; /// A viewport cell waiting longer than this for its in-flight job is a /// stall; log a diagnostic (rate-limited). const STALL_ALARM_MS: u64 = 500; @@ -129,6 +164,23 @@ struct AppState { painted_total: AtomicU64, /// Rate-limits the stall alarm. UI thread only. last_stall_log: Mutex, + /// Jank-hunt test hook: file-triggered programmatic scroll (see tick). + dbg: Mutex, +} + +/// Test hook (jank hunt): `/sdcard/Download/.gallery_cmd` with +/// `scroll ` or `stop` drives the list at a +/// perfectly smooth constant velocity — an input source with ZERO transport +/// jitter (adb `input` injects through virtio at ~60 Hz in bursts, which +/// masquerades as app jank). Removes the OS input pipeline from the +/// equation: if a programmatic scroll is janky, the app/render is at fault. +struct DbgScroll { + active_until: Option, + vel: f32, + cmd_mtime: Option, + last_check: Instant, + last_y: f32, + last_t: Instant, } /// Create the pool + cache dir once per process. @@ -138,16 +190,31 @@ fn state() -> &'static AppState { let cache_dir = base.join("thumbs"); let workers = (std::thread::available_parallelism().map(|n| n.get()).unwrap_or(4) / 2).clamp(2, 8); - // 96 = thumb::MAX_WORKER_QUEUE: bound each worker's pending queue so - // stale transit work can never delay the viewport (overflow is - // dropped with a `skipped` result; re-entry is a disk-cache hit). - let engine = Engine::new(cache_dir, workers, GRID_TARGET, 96).expect("thumb engine"); + // MAX_WORKER_QUEUE (96): bound each worker's pending queue so stale + // transit work can never delay the viewport (overflow is dropped + // with a `skipped` result; re-entry is a disk-cache hit). + let engine = + Engine::new(cache_dir, workers, GRID_TARGET, MAX_WORKER_QUEUE).expect("thumb engine"); log::info!( "gallery: thumb engine up: {} workers, target {} px, cache {}", workers, GRID_TARGET, engine.cache_dir().display() ); + // Jank-hunt test knobs (REMOVE after). + #[cfg(target_os = "android")] + { + if let Ok(s) = std::fs::read_to_string("/sdcard/Download/.gallery_max_painted") { + if let Ok(m) = s.trim().parse::() { + MAX_PAINTED_LIVE.store(m, Ordering::Relaxed); + log::info!("JANKTEST max_painted -> {m}"); + } + } + if std::path::Path::new("/sdcard/Download/.gallery_grey").exists() { + JANK_GREY_IMAGES.store(true, Ordering::Relaxed); + log::info!("JANKTEST grey images ON"); + } + } AppState { engine, entries: Mutex::new(Vec::new()), @@ -157,6 +224,14 @@ fn state() -> &'static AppState { failed: Mutex::new(HashSet::new()), painted_total: AtomicU64::new(0), last_stall_log: Mutex::new(Instant::now()), + dbg: Mutex::new(DbgScroll { + active_until: None, + vel: 0.0, + cmd_mtime: None, + last_check: Instant::now(), + last_y: 0.0, + last_t: Instant::now(), + }), } }) } @@ -171,9 +246,9 @@ fn empty_cell() -> Cell { /// Chunk entries into rows of GRID_COLS (trailing cells empty). The `cells` /// field is a nested model (ModelRc), not a Vec: the grid template -/// iterates it per row. Cell updates (apply_row_batch) replace the whole -/// outer row — the only update path that reaches ListView rows recycled -/// while off-screen (verified on emulator, 2026-10-27). +/// iterates it per row. Cell updates (apply_cell_updates) mutate the nested +/// model IN PLACE — Slint's ListView keeps every row alive (rendered items +/// are culled, not recycled), so the live row's model is always reachable. fn chunk(entries: &[Entry]) -> Vec { entries .chunks(GRID_COLS) @@ -213,6 +288,23 @@ fn set_list(weak: &slint::Weak
, entries: Vec, status: String) { app.inflight.lock().unwrap().clear(); app.painted.lock().unwrap().clear(); app.failed.lock().unwrap().clear(); + // Jank-hunt test knob (REMOVE after): cap the item count to isolate + // scene-size cost from textured-cell cost. + #[cfg(target_os = "android")] + let entries = { + let e = entries; + match std::fs::read_to_string("/sdcard/Download/.gallery_max").ok().and_then( + |s| s.trim().parse::().ok(), + ) { + Some(m) if m < e.len() => { + log::info!("JANKTEST capping items {} -> {}", e.len(), m); + let mut e = e; + e.truncate(m); + e + } + _ => e, + } + }; *app.entries.lock().unwrap() = entries.clone(); let n = entries.len(); *app.viewport.lock().unwrap() = 0..INITIAL_VIEWPORT_CELLS.min(n); @@ -233,61 +325,73 @@ fn set_status(weak: &slint::Weak
, status: String) { }); } -/// Apply a batch of cell paints + evictions, replacing each affected OUTER -/// row exactly once (UI thread). Row replacement — not in-place nested-model -/// updates — is the only update path that reliably reaches ListView rows -/// that were recycled while off-screen (gotcha #12). Returns the number of -/// paint cells applied. At most `MAX_ROWS_PER_TICK` rows are applied; -/// unapplied paints are dropped on purpose — their cells are no longer -/// painted and no longer in flight, so the fill step re-submits them (disk- -/// cache hit) and they land next tick. -fn apply_row_batch( +/// Apply cell paints + evictions as IN-PLACE nested-model updates (UI +/// thread): each cell is one `cells.set_row_data(col, cell)` on the live +/// row's own model. Only that cell's property changes — no element subtree +/// is recreated and textures are re-uploaded only when the pixels actually +/// change. (Whole-row replacement destroyed/recreated 3 CellView subtrees +/// AND re-uploaded all 3 textures per row; batched at 10 Hz/16 rows that +/// was the scroll hitch + content pulse.) Slint's ListView for-loop keeps +/// every row alive, so the live row's model is always reachable. +/// Returns the number of paint cells applied. Paints are capped at +/// `MAX_PAINT_CELLS_PER_TICK`; unapplied paints are dropped on purpose — +/// their cells are no longer painted and no longer in flight, so the fill +/// step re-submits them (disk-cache hit) and they land next tick. +fn apply_cell_updates( app: &AppState, m: &VecModel, entries: &[Entry], paints: &[JobResult], clears: &[usize], ) -> usize { - use std::collections::BTreeMap; - // row -> (col, new cell) updates - let mut rows: BTreeMap> = BTreeMap::new(); + let mut painted_now = 0usize; for r in paints { + if painted_now >= MAX_PAINT_CELLS_PER_TICK { + break; // the rest is re-covered by the fill step + } if !r.ok || r.id >= entries.len() || entries[r.id].path != r.path { continue; // list moved on; drop } - let mut buffer = SharedPixelBuffer::::new(r.width, r.height); - buffer.make_mut_bytes().copy_from_slice(&r.rgb); - rows.entry(r.id / GRID_COLS) - .or_default() - .push(( - r.id % GRID_COLS, - Cell { - path: SharedString::from(r.path.clone()), - image: Image::from_rgb8(buffer), - loaded: true, - }, - )); + let row = r.id / GRID_COLS; + if row >= m.row_count() { + continue; + } + // row_data clones the Item struct (the ModelRc is shared with the + // model row), so mutating it mutates the live model the grid binds + // to. + let Some(item) = m.row_data(row) else { + continue; + }; + let Some(cells) = cells_of(&item) else { + continue; + }; + // Jank-hunt test knob (REMOVE after): 1x1 grey images — same item + // count, zero real texture work. Isolates base window-render cost. + let image = if JANK_GREY_IMAGES.load(Ordering::Relaxed) { + let mut g = SharedPixelBuffer::::new(1, 1); + g.make_mut_bytes().fill(32); + Image::from_rgb8(g) + } else { + let mut buffer = SharedPixelBuffer::::new(r.width, r.height); + buffer.make_mut_bytes().copy_from_slice(&r.rgb); + Image::from_rgb8(buffer) + }; + cells.set_row_data( + r.id % GRID_COLS, + Cell { + path: SharedString::from(r.path.clone()), + image, + loaded: true, + }, + ); + app.painted.lock().unwrap().insert(r.id); + painted_now += 1; } for &id in clears { if id >= entries.len() { continue; } - rows.entry(id / GRID_COLS).or_default().push(( - id % GRID_COLS, - Cell { - path: SharedString::from(entries[id].path.clone()), - image: Image::default(), - loaded: false, - }, - )); - } - let mut n = 0usize; - let mut rows_done = 0usize; - for (row, updates) in rows { - if rows_done >= MAX_ROWS_PER_TICK { - break; // ANR guard; the rest is re-covered by the fill step - } - rows_done += 1; + let row = id / GRID_COLS; if row >= m.row_count() { continue; } @@ -297,79 +401,172 @@ fn apply_row_batch( let Some(cells) = cells_of(&item) else { continue; }; - let mut new_cells: Vec = ( - 0..cells.row_count().min(GRID_COLS) - ) - .map(|i| cells.row_data(i).unwrap_or_else(empty_cell)) - .collect(); - new_cells.resize(GRID_COLS, empty_cell()); - let mut touched = false; - for (col, c) in updates { - if col >= GRID_COLS { - continue; - } - let id = row * GRID_COLS + col; - if c.loaded { - if id >= entries.len() || entries[id].path != c.path.as_str() { - continue; - } - app.painted.lock().unwrap().insert(id); - n += 1; - } else { - if id >= entries.len() || entries[id].path != c.path.as_str() { - continue; - } - app.painted.lock().unwrap().remove(&id); - // Release the dedupe entry so the fill step re-submits this - // cell when it is in the viewport again (re-submit is a - // disk-cache hit). - app.inflight.lock().unwrap().remove(&entries[id].path); - } - new_cells[col] = c; - touched = true; - } - if touched { - m.set_row_data( - row, - Item { - cells: ModelRc::new(VecModel::from(new_cells)), - }, - ); - } + cells.set_row_data( + id % GRID_COLS, + Cell { + path: SharedString::from(entries[id].path.clone()), + image: Image::default(), + loaded: false, + }, + ); + app.painted.lock().unwrap().remove(&id); + // Release the dedupe entry so the fill step re-submits this cell + // when it is in the viewport again (re-submit is a disk-cache hit). + app.inflight.lock().unwrap().remove(&entries[id].path); } - n + painted_now } -/// Scroll event (main.slint `scrolled` → `scroll-changed(y, height, width)`; -/// content-y is negative while scrolled). MUST stay cheap — it fires on every -/// scroll frame: it ONLY moves the viewport target. All work (submit, paint, -/// evict) happens in the 10 Hz tick, which reconciles the viewport whether -/// or not scrolling is happening. -fn on_scroll(app: &AppState, y: f32, height: f32, width: f32) { - if width <= 0.0 { - return; +/// Map the list's actual geometry to the cell viewport (visible rows ± +/// MARGIN_ROWS). content-y is negative while scrolled; `width`/`height` are +/// the list's visible size. Shared by the scroll callback (fast path) and +/// the tick's poll (ground truth — see start_drain_timer). +fn viewport_for(y: f32, height: f32, width: f32, n: usize) -> Option> { + if width <= 0.0 || n == 0 { + return None; } let cell = (width - 2.0 * GRID_PADDING - 2.0 * GRID_GAP) / GRID_COLS as f32; let row_h = cell + ROW_SPACING; - let n = app.entries.lock().unwrap().len(); - if n == 0 { - return; - } let first = (y.abs() / row_h) as usize; let visible = (height / row_h) as usize + 1; let margin = MARGIN_ROWS * GRID_COLS; - let vp = (first * GRID_COLS) + Some((first * GRID_COLS) .saturating_sub(margin) - ..((first + visible + MARGIN_ROWS) * GRID_COLS).min(n); - *app.viewport.lock().unwrap() = vp; + ..((first + visible + MARGIN_ROWS) * GRID_COLS).min(n)) } -/// The reconcile tick, 10x/s: consume finished results (paint the viewport -/// ones), evict far pixels, and fill the viewport (submit what's missing, -/// center-first). This is the ONLY place jobs are submitted. After the fill -/// step, the invariant holds: every viewport cell is painted, in flight, or -/// failed. Slint 1.18 timers stop when dropped, and Timer is !Send (UI -/// thread only): we leak the one handle for the process lifetime (8 bytes). +// ---- Jank-hunt instrumentation (2026-10-27; REMOVE after the hunt) ---- +// Every PROCESSED scroll callback logs SCR: the offset stream. Uneven dy = +// uneven motion quantum; time gaps = the event loop was starved (blocked UI +// thread or GPU). Every reconcile tick logs TICK: UI-thread frame cadence +// plus the tick's total cost. A slow in-place apply logs APLY (texture +// upload cost. All logging goes through the non-blocking logger (nblog) +// so logd backpressure can never stall a UI frame. +static LAST_SCR_Y: std::sync::atomic::AtomicI64 = + std::sync::atomic::AtomicI64::new(i64::MIN); +static LAST_TICK_T: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0); + +/// Monotonic ms since process start (wall clock could jump on NTP and be +/// mistaken for jank). +static NOW_T0: std::sync::OnceLock = std::sync::OnceLock::new(); +#[inline] +fn now_ms() -> f64 { + let t0 = NOW_T0.get_or_init(std::time::Instant::now); + t0.elapsed().as_secs_f64() * 1000.0 +} + +#[cfg(target_os = "android")] +mod nblog { + //! Non-blocking logger. `log` calls on the UI thread must NEVER block: + //! logd-pipe backpressure during log bursts was blocking the UI thread + //! for 10–40 ms, polluting (and causing) exactly the scroll frames we + //! try to measure. Records are formatted at the call site and pushed + //! into a bounded channel; a drain thread does the real + //! `__android_log_write` and DROPS records when saturated. + use std::sync::atomic::{AtomicUsize, Ordering}; + use std::sync::mpsc; + use log::{Level, Log, Metadata, Record}; + + extern "C" { + fn __android_log_write(prio: i32, tag: *const u8, msg: *const u8) -> i32; + } + const TAG: &[u8] = b"gallery\0"; + + pub struct Logger { + tx: mpsc::SyncSender<(i32, String)>, + dropped: AtomicUsize, + } + + pub fn init() { + let (tx, rx) = mpsc::sync_channel::<(i32, String)>(4096); + std::thread::Builder::new() + .name("log-drain".into()) + .spawn(move || { + for (prio, msg) in rx { + let b = msg.into_bytes(); + let end = b.iter().position(|&c| c == 0).unwrap_or(b.len()); + let mut safe: Vec = + b[..end].iter().copied().filter(|&c| c != b'\n').collect(); + safe.push(0); + unsafe { + __android_log_write(prio, TAG.as_ptr(), safe.as_ptr()); + } + } + }) + .ok(); + let logger = Logger { tx, dropped: AtomicUsize::new(0) }; + let _ = log::set_boxed_logger(Box::new(logger)).map(|()| log::set_max_level(log::LevelFilter::Info)); + } + + impl Logger { + fn prio(l: Level) -> i32 { + match l { + Level::Error => 6, + Level::Warn => 5, + Level::Info => 4, + _ => 3, + } + } + } + + impl Log for Logger { + fn enabled(&self, m: &Metadata) -> bool { + m.level() <= Level::Info + } + fn log(&self, record: &Record) { + if !self.enabled(record.metadata()) { + return; + } + let mut s = String::with_capacity(96); + use std::fmt::Write as _; + let _ = write!(&mut s, "{}", record.args()); + if self.tx.try_send((Self::prio(record.level()), s)).is_err() { + self.dropped.fetch_add(1, Ordering::Relaxed); + } + } + fn flush(&self) {} + } +} + +/// Scroll event (main.slint `scrolled` → `scroll-changed(y, height, width)`). +/// Fast-path hint for direct drags: it ONLY moves the viewport target, no +/// work. The tick also POLLS the list's real position every tick, which is +/// what keeps this correct during flings (the callback is silent during the +/// momentum animation — see main.slint header). +fn on_scroll(app: &AppState, y: f32, height: f32, width: f32) { + let n = app.entries.lock().unwrap().len(); + if let Some(vp) = viewport_for(y, height, width, n) { + *app.viewport.lock().unwrap() = vp; + } + // SCR (jank hunt): the processed offset stream. + let y100 = (y * 100.0) as i64; + let prev = LAST_SCR_Y.swap(y100, Ordering::Relaxed); + let dy = if prev == i64::MIN { 0.0 } else { (y100 - prev) as f64 / 100.0 }; + log::info!("SCR {:11.2} y={:8.1} dy={:7.1}", now_ms(), y, dy); +} + +/// The reconcile tick, at display rate (~120 Hz; VSync-quantized on +/// Android): consume finished results (paint the viewport ones, ≤3 rows), +/// evict far pixels (≤2 rows), and fill the viewport (submit what's missing, +/// center-first). This is the ONLY place jobs are submitted. Each tick is +/// tiny and idempotent — work is spread across frames, never batched — so +/// content updates land every frame (the old 100 ms/16-row batch showed as +/// a visible content pulse during slow scroll). +/// +/// Step 0 POLLS the list's actual geometry (main.slint `list-y` etc.): the +/// `scrolled` callback is silent during momentum scrolling (Slint 1.18 +/// Flickable fires `flicked` once at fling start; the deceleration animation +/// updates content-y per frame without re-firing it), so polling is the +/// ground truth that keeps the viewport correct through flings. +/// +/// After the fill step, the invariant holds: every viewport cell is painted, +/// in flight, or failed. Slint 1.18 timers stop when dropped, and Timer is +/// !Send (UI thread only): we leak the one handle for the process lifetime +/// (8 bytes). +/// Tick counter for rate-limiting the debug coverage log (debug level: the +/// lines are only visible when the android_logger filter is Debug). +static DBG_TICKS: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0); + fn start_drain_timer(weak: &slint::Weak
) { let weak = weak.clone(); let timer = Timer::default(); @@ -388,7 +585,123 @@ fn start_drain_timer(weak: &slint::Weak
) { if entries.is_empty() { return; } - let viewport = app.viewport.lock().unwrap().clone(); + // Jank hunt (REMOVE after): tick cadence + cost. + let tick_t0 = Instant::now(); + // DEBUG-SCROLL TEST HOOK (REMOVE after the hunt): see DbgScroll. + { + let now = Instant::now(); + let mut dbg = app.dbg.lock().unwrap(); + if dbg.last_check.elapsed() > std::time::Duration::from_millis(150) { + dbg.last_check = now; + let path = "/sdcard/Download/.gallery_cmd"; + if let Ok(md) = std::fs::metadata(path) { + let mt = md.modified().ok(); + if mt != dbg.cmd_mtime { + dbg.cmd_mtime = mt; + if let Ok(s) = std::fs::read_to_string(path) { + let t = s.trim(); + if t.starts_with("scroll") { + let p: Vec<&str> = t.split_whitespace().collect(); + if p.len() == 3 { + if let (Ok(v), Ok(d)) = + (p[1].parse::(), p[2].parse::()) + { + dbg.vel = v; + dbg.active_until = + Some(now + std::time::Duration::from_millis(d)); + dbg.last_t = now; + log::info!("DBGCMD scroll v={v} d={d}"); + } + } + } else if t == "stop" { + dbg.active_until = None; + log::info!("DBGCMD stop"); + } + } + } + } + } + if let Some(end) = dbg.active_until { + if now < end { + let dt = ((now.duration_since(dbg.last_t).as_millis()) as f32) + .clamp(1.0, 25.0); + dbg.last_t = now; + // Clamp to the list's real range: y in [-(n*row_h-h), 0]. + let width = w.get_list_width() as f32; + let height = w.get_list_height() as f32; + let cell = (width - 2.0 * GRID_PADDING - 2.0 * GRID_GAP) + / GRID_COLS as f32; + let row_h = cell + ROW_SPACING; + let y_min = (-(entries.len() as f32 * row_h) + height).min(0.0); + let y = (w.get_list_y() as f32 + dbg.vel * dt).clamp(y_min, 0.0); + let dy = y - dbg.last_y; + dbg.last_y = y; + w.set_list_y(y); + log::info!("SCRDBG {:?} y={:.1} dy={:.1}", now, y, dy); + } else { + dbg.active_until = None; + } + } + } + // 0. POLL: the list's ACTUAL scroll position (momentum-aware). + // The scroll callback (on_scroll) is a fast-path hint for + // drags; this is the ground truth. + let viewport = match viewport_for( + w.get_list_y(), + w.get_list_height(), + w.get_list_width(), + entries.len(), + ) { + Some(vp) => { + let prev = app.viewport.lock().unwrap().clone(); + // DBG (debug level): viewport trajectory — proves the + // poll tracks momentum flings (callback-only froze). + if vp != prev { + log::debug!( + "DBG vp y={:.0} {}..{} -> {}..{}", + w.get_list_y(), + prev.start, + prev.end, + vp.start, + vp.end + ); + } + *app.viewport.lock().unwrap() = vp.clone(); + vp + } + None => app.viewport.lock().unwrap().clone(), + }; + + // DBG: coverage at ~5 Hz (debug level: silent in production). + if DBG_TICKS.fetch_add(1, Ordering::Relaxed) % 15 == 0 { + let painted = app.painted.lock().unwrap(); + let inflight = app.inflight.lock().unwrap(); + let failed = app.failed.lock().unwrap(); + let (mut p, mut i, mut f) = (0usize, 0usize, 0usize); + for id in viewport.clone() { + let e = &entries[id]; + if painted.contains(&id) { + p += 1; + } else if inflight.contains_key(&e.path) { + i += 1; + } else if failed.contains(&(e.path.clone(), e.mtime, e.size)) { + f += 1; + } + } + let now = Instant::now(); + let oldest = inflight + .values() + .map(|t| now.duration_since(*t)) + .max() + .map(|d| d.as_millis()) + .unwrap_or(0); + log::debug!( + "DBG tick vp={}..{} p={p} i={i} f={f} oldest={oldest}ms {}", + viewport.start, + viewport.end, + app.engine.log_summary() + ); + } // 1. CONSUME: every finished result leaves `inflight` (its job is // done). Paint viewport results (capped); the disk cache owns @@ -416,23 +729,24 @@ fn start_drain_timer(weak: &slint::Weak
) { } continue; } - if viewport.contains(&r.id) && paints.len() < MAX_CELLS_PER_TICK { + if viewport.contains(&r.id) + && paints.len() < MAX_PAINT_CELLS_PER_TICK + { paints.push(r); } } } - // 2. EVICT: release pixels for painted cells outside the viewport - // ± MARGIN_ROWS, farthest first. Budget = the rows the paints - // didn't use; if the hard cap is exceeded, evict extra (still - // bounded per tick) so pathological flicking converges. + // 2. EVICT: release pixels for painted cells outside the + // RETENTION band (viewport ± RETENTION_ROWS — much wider than + // the submit margin: pixels within ~2 screens are kept for + // instant back-scrolls), farthest first. ≤4 cells/tick so + // evictions also fit the frame budget. let to_clear: Vec = { let painted = app.painted.lock().unwrap(); - let rows_used = (paints.len() + GRID_COLS - 1) / GRID_COLS; - let budget = (MAX_ROWS_PER_TICK - rows_used.min(MAX_ROWS_PER_TICK)) * GRID_COLS; - let overflow = painted.len().saturating_sub(MAX_PAINTED); - let lo = viewport.start.saturating_sub(MARGIN_ROWS * GRID_COLS); - let hi = (viewport.end + MARGIN_ROWS * GRID_COLS).min(entries.len()); + let overflow = painted.len().saturating_sub(MAX_PAINTED_LIVE.load(Ordering::Relaxed)); + let lo = viewport.start.saturating_sub(RETENTION_ROWS * GRID_COLS); + let hi = (viewport.end + RETENTION_ROWS * GRID_COLS).min(entries.len()); let center = (viewport.start + viewport.end) / 2; let mut far: Vec = painted .iter() @@ -441,13 +755,19 @@ fn start_drain_timer(weak: &slint::Weak
) { .collect(); far.sort_by_key(|id| center.abs_diff(*id)); // nearest first far.reverse(); // farthest first - let n = far.len().min(budget.max(overflow.min(2 * MAX_CELLS_PER_TICK))); + let budget = MAX_EVICT_CELLS_PER_TICK; + let n = far.len().min(budget.max(overflow.min(2 * budget))); far.into_iter().take(n).collect() }; - // 3. APPLY: each affected outer row replaced exactly once - // (≤ MAX_ROWS_PER_TICK rows). - let painted_now = apply_row_batch(app, m, &entries, &paints, &to_clear); + // 3. APPLY: in-place nested cell updates (≤4 paints + ≤4 + // evictions; each = one cell property change). + let apply_t0 = Instant::now(); // jank hunt (REMOVE after) + let painted_now = apply_cell_updates(app, m, &entries, &paints, &to_clear); + let apply_us = apply_t0.elapsed().as_micros(); // jank hunt + if apply_us > 1500 { // jank hunt (REMOVE after) + log::info!("APLY {}us p={} c={}", apply_us, painted_now, to_clear.len()); + } // 4. FILL: every viewport cell without pixels and without an // in-flight job gets submitted now, center-first so the eye is @@ -565,6 +885,18 @@ fn start_drain_timer(weak: &slint::Weak
) { ); } } + // Jank hunt (REMOVE after): stall-only tick log. Log when the + // gap since the previous tick exceeds one 60 Hz frame (a dropped + // 120 Hz frame) or the tick itself was slow — full-cadence + // logging at 125 lines/s risks blocking in log_write and + // masquerading as jank. + let tick_us = tick_t0.elapsed().as_micros(); + let t_now = now_ms(); + let last = f64::from_bits(LAST_TICK_T.swap(t_now.to_bits(), Ordering::Relaxed)); + let gap = t_now - last; + if tick_us > 500 || gap > 16.0 { + log::info!("TICK {:11.2} gap={:.1} d={}us p={}", t_now, gap, tick_us, painted_now); + } }, ); std::mem::forget(timer); @@ -653,9 +985,7 @@ pub fn android_app() -> Option<&'static slint::android::AndroidApp> { #[cfg(target_os = "android")] #[unsafe(no_mangle)] fn android_main(app: slint::android::AndroidApp) { - android_logger::init_once( - android_logger::Config::default().with_max_level(log::LevelFilter::Info), - ); + nblog::init(); let _ = ANDROID_APP.set(app.clone()); // `init_with_event_listener` gives us the raw MainEvent stream diff --git a/src/main.slint b/src/main.slint index ef934be..22c311e 100644 --- a/src/main.slint +++ b/src/main.slint @@ -1,9 +1,17 @@ // Gallery — M3: 3-column thumbnail grid with shimmer placeholders. // -// The ListView virtualizes ROWS; each row holds up to 3 square cells. -// `scrolled` drives Rust-side prefetch (lib.rs::on_scroll), which also owns -// the memory bound: cells scrolled far off-screen are dropped back to -// shimmer (their pixels live in the disk cache, repaint is instant). +// Each row holds up to 3 square cells. (Slint's ListView renders every row +// as a live element — off-screen rows are culled, not recycled — so cell +// updates mutate the row's nested model IN PLACE; see lib.rs. +// apply_cell_updates.) +// The Rust side reconciles the viewport at ~120 Hz (lib.rs tick). The tick +// POLLS `list-y`/`list-height`/`list-width` as ground truth: the `scrolled` +// callback alone is NOT reliable — Slint 1.18's Flickable fires `flicked` +// on pointer moves and once at fling start, but the momentum (deceleration) +// animation updates content-y every frame WITHOUT re-firing it, so the tick +// polls the actual position and stays correct through flings. (See +// i-slint-core items/flickable.rs: `animate()` sets a physics animation on +// content-y and calls `flicked` exactly once.) import { ListView, VerticalBox } from "std-widgets.slint"; export struct Cell { @@ -25,15 +33,17 @@ component CellView inherits Rectangle { border-radius: 4px; clip: true; - // Shimmer: time-driven expression (1.18 style, same pattern as Slint's - // own spinner widgets) — animation-tick() marks the binding as - // time-dependent, so it re-evaluates every frame while visible. + // Placeholder while the thumbnail is in flight. STATIC on purpose: + // animation-tick() in a per-cell binding is O(ALL CELLS) every frame + // (ListView keeps every row alive; bindings are not visibility-gated), + // which burned ~70 % of a core at idle with 8.5k cells and stole CPU + // from the render pipeline during scroll (jank). A proper shimmer + // needs an O(visible) architecture — M6. Rectangle { width: 100%; height: 100%; background: #242424; visible: !cell.loaded && cell.path != ""; - opacity: 0.45 + 0.55 * Math.abs(Math.sin(360deg * animation-tick() / 1300ms)); } Image { @@ -78,6 +88,14 @@ export component Main inherits Window { /// delivers results. in property <[Item]> items; + // Rust-readable mirrors of the list's ACTUAL geometry (content-y is + // negative while scrolled down). The reconcile tick polls these every + // tick — including during momentum scrolling, where the `scrolled` + // callback is silent (see file header). + in-out property list-y <=> listview.content-y; + out property list-height <=> listview.visible-height; + in-out property list-width <=> listview.width; + VerticalBox { width: 100%; spacing: 8px; @@ -94,10 +112,11 @@ export component Main inherits Window { overflow: elide; } - ListView { + listview := ListView { width: 100%; vertical-stretch: 1; - // Scroll-driven prefetch + memory bound (see lib.rs::on_scroll). + // Fast-path hint for drags (the tick also polls list-y every + // tick, which covers flings where this callback is silent). scrolled => { root.scroll-changed(self.content-y, self.visible-height, self.width); } diff --git a/src/thumb.rs b/src/thumb.rs index e0c6483..2dd2905 100644 --- a/src/thumb.rs +++ b/src/thumb.rs @@ -46,7 +46,7 @@ const JPEG_QUALITY: u8 = 85; /// than the viewport (~45 cells), so fresh viewport work ALWAYS survives the /// cap; overflow is dropped from the TAIL (oldest transit work). 96 ≈ two /// screens per worker of headroom. -const MAX_WORKER_QUEUE: usize = 96; +pub const MAX_WORKER_QUEUE: usize = 96; #[derive(Debug, Clone)] pub struct Job {