Greg Pomerantz
2f4768f354
Three root causes, all fixed and verified on the Pixel 9 Pro: 1. Present phase (backend + renderer): VSYNC_LOCKED_RENDER defers the render to the vsync wake; RENDER_AHEAD presents the previous frame at the start of render() (phase = wake + ~1.1 ms) and holds the new frame one slot. Crash fix: a held wgpu frame must be PRESENTED, never merely dropped, before the next acquire (AlreadyAcquired panic at launch otherwise); discard_pending_frame presents too. 2. Full-res prefetch churn (src/lib.rs): the 8-slot full cache cycled through a ~20-cell viewport forever (137 decodes/20 s) and each eviction free()'d a 50 MB Vec on the UI thread (20-52 ms CPU spikes, ~7/s = the residual SLOWEV NonMain jank). Fix: 60 s tombstone cooldown on evicted paths (idle prefetch skips, urgent tap bypasses) + off-thread reaper for the freed blobs (insert: 21 ms -> 4 us). 3. (earlier) Skia final flush + Mailbox present mode (vendor, M3). Instrumentation (all behind --features perf): OTHR/INVK/INVK_TAG/FLCK lines for cross-thread closure timing and push-site tagging. Warm measured swipe, 8580-file grid: cadence median 8.33 ms (exact 120 Hz), p99 15.5 ms, 5/552 gaps >16.7 ms (0.9%, max 28.3 ms, zero >33 ms); PRES phase median ~994 us, zero late frames. Docs updated (docs/BUGS/scroll-jank-120hz.md, full scorecard + line reference). Also: vendored i-slint-core + wgpu-hal (vkshim interposition patch), vkshim profiling tooling, backend made a non-optional dep, debuggable flag for simpleperf (REMOVE before shipping).
153 lines
7.6 KiB
Markdown
153 lines
7.6 KiB
Markdown
# Scroll Jank Investigation & Fix (120Hz Android / Mali G715)
|
||
|
||
## Overview
|
||
|
||
During M3/M4 development, profiling on physical 120 Hz hardware
|
||
(Pixel 9 Pro, Mali G715, Android 17, 1280×2856, `falsePrerotation=1`)
|
||
revealed periodic mid-scroll frame gaps (17–55 ms against the 8.33 ms
|
||
budget). Stage-timestamp instrumentation (`STG`/`IT`/`FR`/`VK`/`PRES`/
|
||
`SCN`/`OTHR`/`FLCK`, all behind `--features perf`) isolated **three**
|
||
distinct root causes. All three are fixed; the app is verified on the
|
||
phone.
|
||
|
||
**Final scorecard (warm, measured 4.5 s mid-screen swipe, 8 580 files
|
||
grid):**
|
||
|
||
| metric | baseline (M3) | RENDER_AHEAD | + full-cache fix (final) |
|
||
|-------------------------------|---------------|--------------|--------------------------|
|
||
| frame cadence median | 8.67 ms (judder) | 8.34 ms | **8.33 ms (exact 120 Hz)** |
|
||
| cadence > 16.7 ms (2+ slots) | ~6 % | ~6 % | **0.9 % (5/552)** |
|
||
| worst gap in swipe | 55 ms | 292 ms¹ | **28.3 ms** |
|
||
| PRES phase median (vs vsync) | 6 509 µs | 1 992 µs | **~994 µs** |
|
||
| PRES > 8 330 µs (late) | 100 % | 0 % | **0 %** |
|
||
| slow `Event::Other` spikes | — | ~40 / 20 s | **2 (launch only)** |
|
||
|
||
¹ single outlier = app background/foreground transition.
|
||
|
||
---
|
||
|
||
## 1. Root cause #1 — phase: present landed after the compositor deadline
|
||
|
||
**Symptom:** every rendered frame was shown one vsync late (effective
|
||
~60 Hz + judder) even though each render only took 4–8 ms.
|
||
|
||
**Cause:** the render was triggered by input events at an arbitrary
|
||
phase inside the 8.33 ms slot; the present then landed past the
|
||
compositor's ~5.5 ms deadline, so the frame could only be scanned out
|
||
on the *next* slot.
|
||
|
||
**Fix (two parts, both in the vendored backend/renderer):**
|
||
|
||
1. **VSYNC_LOCKED_RENDER** (`vendor/i-slint-backend-android-activity-1.18.1/lib.rs`):
|
||
while animating (active animations *or* pointer active within 200 ms —
|
||
Slint has no fling physics, so a direct drag sets no animation),
|
||
input events only mark the window dirty; the render happens on the
|
||
next vsync **wake**, giving a deterministic present phase.
|
||
2. **RENDER_AHEAD** (`vendor/i-slint-renderer-skia/wgpu_30_surface.rs`):
|
||
present the frame prepared by the *previous* `render()` at the start
|
||
of the current one (phase = wake + ~1.1 ms), then prepare the next
|
||
frame without presenting. One slot of constant latency; the present
|
||
timing is fully decoupled from the render duration. Activated per
|
||
frame (`RENDER_AHEAD_ACTIVE`): only locked (animating) renders use
|
||
the hold-without-present pipeline; idle/model-update renders present
|
||
immediately.
|
||
|
||
**Crash fixed along the way — wgpu `AlreadyAcquired`:** wgpu's
|
||
`Presentation` tracks the acquired swapchain image independently of the
|
||
Rust `Arc`. The legacy (unlocked) path used to *drop* a held frame
|
||
without presenting it; the drop does not clear the Presentation, so the
|
||
next `get_current_texture` panicked with "Surface image is already
|
||
acquired" (killed the window at launch). **Rule: a held frame must be
|
||
PRESENTED, never merely dropped, before the next acquire.**
|
||
`discard_pending_frame()` (resize/reconfigure) therefore presents too —
|
||
the compositor absorbs the one-frame size change.
|
||
|
||
---
|
||
|
||
## 2. Root cause #2 — Skia final flush (fixed earlier, M3)
|
||
|
||
Slint's default Skia renderer issued a synchronous
|
||
`GrDirectContext::flush(None)` at the end of every frame; on Mali G715
|
||
that blocked the CPU 19–24 ms. Removed in vendored
|
||
`i-slint-renderer-skia/lib.rs` (see
|
||
`docs/BUGS/slint-skia-final-flush-jank.md`).
|
||
|
||
---
|
||
|
||
## 3. Root cause #3 — full-res prefetch churn: freeing 50 MB on the UI thread
|
||
|
||
**Symptom:** after #1 and #2, the gallery still showed ~40 CPU spikes
|
||
of 9–43 ms per 20 s (≈7/s) — `SLOWEV NonMain` with `cpu ≈ wall`, i.e.
|
||
pure CPU inside `window.process_event(Wake)`, `render=0`. Sltest (no
|
||
gallery code) does not show these, so the cause was app-side.
|
||
|
||
**Localization:** `OTHR` (timing of `Event::Other` closures drained in
|
||
`process_event` — the `invoke_from_event_loop` queue) + `INVK_TAG`
|
||
(push-site tags) showed **106 of 112 slow closures were the
|
||
full-load-arrival closure** (median 21 ms CPU), plus 9 `set_status`
|
||
mislabeled by off-by-one (all fullload on re-correlation).
|
||
|
||
**Mechanism (two compounding bugs in the M4.1 viewer prefetch):**
|
||
|
||
1. **Churn loop.** `prefetch_full` (drain tick) idly decodes full-res
|
||
images for visible cells, cached in an 8-slot / 64 Mpx LRU
|
||
(`FullCache`). The viewport holds ~20 cells ⇒ every insert evicts,
|
||
and the evicted path is visible again ⇒ immediately re-prefetched.
|
||
Steady state: decode → evict → re-decode forever — **137 full
|
||
decodes in 20 s** with the viewer closed.
|
||
2. **Eviction freed on the UI thread.** Each evicted entry is a
|
||
50 MB-class `Vec<u8>`. `FullCache::insert` evicted (and thus
|
||
`free()`d) the old blob synchronously on the UI thread: **20–52 ms
|
||
of CPU per eviction** (`FLCK ins_us`: median 21.4 ms when
|
||
evicting, 4 µs when not — perfect correlation with the OTHR
|
||
spikes).
|
||
|
||
**Fix (`src/lib.rs`):**
|
||
|
||
1. **Tombstone cooldown** — `full_evicted_recent` (path → time). Idle
|
||
prefetch skips paths evicted within `EVICT_COOLDOWN` (60 s); a tap
|
||
(`urgent`) clears the tombstone and proceeds. Churn drops from
|
||
137 decodes/20 s to ~11 (initial cache fill only).
|
||
2. **Off-thread reaper** — `FullCache::insert` now *returns* the
|
||
evicted `(path, rgba)` pairs; the UI thread moves the blobs (a
|
||
pointer swap) into `REAPER_TX`; a `nice`-style low-priority
|
||
`full-reaper` thread drops them at 500 ms cadence. Insert cost:
|
||
**median 4 µs** (was 21 ms).
|
||
3. Tombstones cleared on list reset / world teardown with the other
|
||
full-cache state.
|
||
|
||
**Verification:** `FLCK ins_us` median 4 µs / max 17 µs; OTHR slow
|
||
closures 122 → 2 (launch set_list warm-up only); SLOWEV > 8 ms: 40 → 3
|
||
in 20 s; swipe cadence as in the scorecard.
|
||
|
||
---
|
||
|
||
## 4. Residual (accepted / open)
|
||
|
||
- **~0.9 % two-slot gaps (16.8–17.7 ms)** and a single 28.3 ms gap in
|
||
a warm swipe. The 28.3 ms case is one 8.3 ms render with
|
||
`SKD = 4.5 ms` (`VK SKD max=57 ms` over the run) — Mali GPU cache
|
||
miss on freshly uploaded textures; renders otherwise 2–4 ms.
|
||
- Mali G715 sits at 150–419 MHz during scroll (low duty cycle; no root
|
||
to force the 940 MHz max). A faster clock would shrink SKD variance.
|
||
- `dumpsys gfxinfo` is blind to Slint's NativeActivity window;
|
||
Perfetto FrameTimeline cannot attribute app-side jank here — all
|
||
numbers in this doc come from the app-side perf log.
|
||
|
||
## 5. Instrumentation reference (all `--features perf`)
|
||
|
||
| line | source | meaning |
|
||
|--------|--------|---------|
|
||
| `IT` | backend event loop | per-iteration: poll/first-ev/timers/ev/render/anim + LV/Flickable/input/timeout/wake counters |
|
||
| `STG` | backend event loop | iteration summary (wake, poll, events, lastrender) |
|
||
| `FR` | window rendering notifier | per rendered frame: cumulative ms, draw µs, gap ms |
|
||
| `VSYNC`| vsync callback | frame time + monotonic |
|
||
| `PRES` | renderer surface | presented frame idx, monotonic, present µs (phase vs `VSYNC mon`) |
|
||
| `VK` | renderer (vkprobe) | per-stage µs: ACQ/CLR/SKD/SKF/ORD/PRE |
|
||
| `VKU` | `src/gputex.rs` | thumb texture upload: create µs + write µs |
|
||
| `SCN` | renderer (scn) | scene op census per frame |
|
||
| `SLOWEV` | backend | event > 5 ms with wall vs CPU time |
|
||
| `OTHR` | backend `process_event` | slow `invoke_from_event_loop` closure (wall + CPU) |
|
||
| `INVK` / `INVK_TAG` | backend / app | push site of every cross-thread closure |
|
||
| `FLCK` | app full-load closure | full-cache insert: size, LRU before/after, insert µs |
|