Measurements only, no behavior change:
- vsync.rs: EW lines (every early-waker landing, EW_ON flag, off by default)
- lib.rs/stg.rs: IT lines gain dec (locked/saw_wake/pr_before/do_render) and
pcpu (CPU us inside poll_events — 2% = asleep in epoll, rules out CPU
spin/deschedule as the wake latency)
Findings (docs/BUGS/hypotheses-120hz.md, sltest baseline):
- Choreographer callback fires at edge+0.52ms (p90 0.65) — the 'late
Choreographer' model from earlier sessions was a mislabeled STG field
(poll block time, not callback latency). The pipeline actually works at
median: present at edge+~4ms, inside the 5.5ms deadline.
- sltest zero-jank definition measured: 98.8% of frames land in the next
display slot; residual = 0.5-0.7% drops + 0.7-0.9% doubles + 1.4ms
phase spread (p10-p90) = the visible micro-judder.
- Residual cost is VARIANCE, not median: per-frame render 3.5ms median
(SKD 1.07 + CLR 0.8 + PRE 1.0 + SKF/ORD 0.65) with spikes to 10.7ms
(SKD max 5.2, CLR max 3.2, PRE max 2.5). Spikes push presents past the
deadline (drops) and shake the phase (judder).
Next: classify spikes (CPU work vs GPU/driver block) via render-window
CPU splits, then kill the top source.
The Choreographer vsync callback reaches the UI thread only 2.5-6 ms
AFTER the vsync edge (measured on the phone). With a 2.5-5 ms Skia
render plus present, that left no phase margin inside the 8.3 ms slot:
51% of frames landed one slot late (judder) and ~4% two slots late
(hitches), on every build tested so far.
Attempted fixes, all measured and retired (see commit history):
- render-ahead hold (present previous frame at next render start):
the held present lands after the NEXT wake's 3.2-6 ms Choreographer
latency -> 52% one-slot late.
- present-at-end + present GATE (sleep on the UI thread to quantize
the present to the vsync grid): the gate sleep (2.5-4 ms) added to
the slot budget (wake 5.3 + core 3 + gate 3 + present 1 = 12.3 ms >
8.3 ms) -> cadence collapsed to 60 Hz.
Working fix (this commit):
- vsync.rs: an 'early waker' thread learns the vsync grid from the
callback's frame_time_nanos (vkprobe::note_vsync_edge) and wakes the
main looper ~0.8 ms BEFORE each edge while animating. Render start
moves from edge+2.5..6 to edge-0.8..+0.5, so the present lands at a
natural ~edge+3..5 ms phase with no UI-thread sleep.
- lib.rs: a render freshness guard (min gap = period - 1.5 ms) makes
the FIRST wake of each slot (early or the late Choreographer
fallback) render and rejects the second (double render = 60 Hz
collapse). Threshold sits between late-after-early (5.8 ms, reject)
and early-after-late (7.5 ms, accept).
- lib.rs: locked renders no longer consume pending_redraw (it carried
the motion invalidations; consuming it starved the follow-up
unlocked iteration -> 60 Hz collapse).
- stg.rs: IT lines now log the render decision (locked/saw_wake/
pr_before/do_render); vkprobe logs gate sleep (GATE_US, now 0).
Measured (phone, 8580-file grid, slow 4 s drags):
in-burst cadence: 8.29-8.44 ms median, p90 8.6-10.2 ms
(was 8.36 median / 10.2 p90 with 3.7-20% two-slot gaps)
in-burst >16.7 ms gaps: 0-2 per burst (was 3-13)
present-to-present: 27% exact one slot, 33% one-slot-late steady
state (imvisible), 3% f-jumps (Skia core 2.5-5 ms variance).
Residual judder lever: Skia core cost variance (next step).
Test hygiene reminders (HANDOFF 8.10): verify ResumedActivity, keep
the task clean (sz=1), record the perf-log byte offset before each
run (the file accumulates across process launches).
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).
Residual scroll jank at 120 Hz (suspected Slint event-loop bug) needs
per-frame + per-stage timing the logcat ring buffer can't hold. New
cargo feature `perf` (default OFF — all sites are cfg-gated, zero
overhead when off):
- FR: per-frame app-side render cost + frame gap, from the rendering
notifier (BeforeRendering/AfterRendering).
- STG: event-loop stage costs (wake/timers/events/poll/lastrender) from
timestamps instrumented into the pinned vendor copy of
i-slint-backend-android-activity (stg.rs; Cargo.toml now depends on
it directly + optional under `perf`).
- DECODE: per-thumbnail-job cost on the workers.
- All lines mirrored to /sdcard/Download/.gallery_perf.log (logcat
rotates too fast at ~120 lines/s).
Format + reading guide: docs/BUGS/scroll-jank-120hz.md.
