From 8f06b853768faee9f30a5aefe7040f802de4b414 Mon Sep 17 00:00:00 2001 From: Greg Pomerantz Date: Fri, 30 Oct 2026 12:12:44 -0400 Subject: [PATCH] 120Hz: re-enable render-ahead under the corrected timing model MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 'callback arrives 3-6 ms late' model that invalidated render-ahead in earlier sessions was a mislabeled STG field: the Choreographer callback actually fires at edge+0.5 ms (measured from the VSYNC ftn/mon pair). With the wake ON the edge, the held frame presented at render START lands at edge+~1.5 ms (constant phase, 4 ms of deadline margin), and render spikes (5-10 ms, the measured cause of the residual 1% drops + 1.5 ms phase spread) only stretch the PREPARE phase of the frame held for the NEXT slot — spikes stop delaying visible frames. - lib.rs: RENDER_AHEAD_ACTIVE = locked again (was false) - lib.rs/stg.rs: IT lines gain rcpu (CPU us inside do_render) — spike classifier: rcpu≈render ⇒ Skia/driver CPU work; rcpu≪render ⇒ blocked on GPU/driver - hypotheses-120hz.md: model correction + sltest baseline + results Emulator behavior verified: scroll, settle (transition flush), mid-drag pause/resume (no black window), no AlreadyAcquired panics, held-frame presents at 0.6-2.1 ms. Phone cadence measurement pending (phone out for user use ~2h). --- docs/BUGS/hypotheses-120hz.md | 52 ++++++++++++++++++- .../lib.rs | 47 +++++++++-------- .../stg.rs | 5 +- 3 files changed, 78 insertions(+), 26 deletions(-) diff --git a/docs/BUGS/hypotheses-120hz.md b/docs/BUGS/hypotheses-120hz.md index 54687f3..da0292e 100644 --- a/docs/BUGS/hypotheses-120hz.md +++ b/docs/BUGS/hypotheses-120hz.md @@ -39,4 +39,54 @@ A "burst" = consecutive presents with gaps < 20 ms; evaluate inside bursts only. dismiss 16KB dialog (sltest is debuggable), record log byte offsets. ## Results -(append below) + +### 2026-07-09 — sltest baseline + model correction (builds slt1-slt3) + +- **H6 RULED OUT / FIXED**: sltest's blocking FileLogger replaced with a + non-blocking drain-thread logger. No crash, no behavior change beyond + log I/O coming off the render path. +- **MODEL CORRECTION (major)**: the "Choreographer callback arrives 2.5-6 ms + after the edge" belief from earlier sessions was WRONG — it came from the + STG `wake=` field, which actually measures the poll's block time (first + event), not callback latency. Measured from the VSYNC line itself + (ftn = vsync edge, mon = callback ran): **callback delivery = edge+0.52 ms + median, p90 0.65, max 1.8 ms** (sltest, phone). The callback fires ON the + edge. +- **H5 RULED OUT for the poll phase**: `pcpu` (CPU time inside + poll_events) = 2% of wall — the UI thread sleeps in epoll normally; it is + not spinning or descheduled while waiting. The wake→poll path is healthy: + poll start ≈ edge−2.3, byte at edge+0.5, return at edge+0.5, render 2.3-4.3 + ms, present ≈ edge+3-4 ms — INSIDE the 5.5 ms deadline at the median. + (The early-waker's edge−0.8 wake is redundant with the on-edge + Choreographer wake — both are fine; the waker stays as fallback.) +- **Baseline zero-jank metrics (sltest, phone, 991 transitions)**: + DROPPED 0.71%, WASTED 0.91%, phase p10-p90 = 2.64-4.13 ms (1.5 ms + spread), 12.5% consecutive phase jumps >1 ms. Median behavior is correct; + the visible judder is the variance. +- **H2/H3 CONFIRMED (residual cause)**: per-frame render = 3.5 ms median + but spikes to 10.7 ms. Stage breakdown (sltest, phone): SKD (Skia draw) + 1.07 ms median / 5.2 max; CLR (wgpu clear submit) 0.8 / 3.2; PRE 1.0 / 2.5; + SKF 0.3; ORD 0.35. Spikes push presents past the deadline (the drops) and + shake the phase (the judder). GPU submit overhead (2.45 ms median) exceeds + the actual scene draw (1.07 ms) — four wgpu submits per frame. +- **Next (implemented, phone-measurement pending)**: RENDER-AHEAD + re-enabled under the corrected model. With the wake on the edge, the held + frame is presented at the START of the render (edge+~1.5 ms, constant + phase, 4 ms margin) and a spike only stretches the PREPARE phase of the + frame held for the next slot — spikes stop delaying visible frames. + Behavior verified on the emulator (scroll, settle, mid-drag pause/resume, + no AlreadyAcquired, no black window). The phone is the only remaining + test: expect drops → ~0 and phase spread → <0.5 ms IF spikes were the + cause; `rcpu` (CPU time inside do_render) classifies any residual spikes + (CPU work vs GPU/driver block). +- **Emulator caveat**: the emulated Choreographer fires 9-10 ms late and the + SF pipeline is slow — the emulator cannot reproduce or validate 120 Hz + cadence; it is for behavior verification only. Phone remains the test + target. + +### Pending when the phone is back +1. Install slt3+ (render-ahead + rcpu), clean task, 2×4 s drags. +2. Run sltslot.py: target DROPPED=0, WASTED=0, phase spread <0.5 ms. +3. If residual: classify spikes via rcpu (≈render ⇒ CPU/Skia; ≪render ⇒ + GPU/driver block), then attack the top stage (CLR submit back-pressure vs + SKD Skia stalls vs PRE present cost). diff --git a/vendor/i-slint-backend-android-activity-1.18.1/lib.rs b/vendor/i-slint-backend-android-activity-1.18.1/lib.rs index 5a7a840..7d6f6c3 100644 --- a/vendor/i-slint-backend-android-activity-1.18.1/lib.rs +++ b/vendor/i-slint-backend-android-activity-1.18.1/lib.rs @@ -266,6 +266,7 @@ impl i_slint_core::platform::Platform for AndroidPlatform { break; } let mut render_us = 0u64; + let mut __render_cpu = 0u64; // Jank-hunt / 120Hz: vsync-locked rendering (the native-Android // model). While animating, input events only MARK the window dirty; // the render happens on the next vsync WAKE, so every present @@ -333,37 +334,36 @@ impl i_slint_core::platform::Platform for AndroidPlatform { // deadline: a 1.4 ms margin that missed 52% of frames // (one slot late) during real slow scrolls. Presenting at // the END of the render instead still left 51% one slot - // late (the wake-arrival latency 2.4–6 ms + render 3–9 ms - // make the present phase random). The actual fix is the - // PRESENT GATE: the render still runs on the vsync wake - // (locked pacing kept), but `Queue::present` sleeps to a - // fixed vsync-grid phase (next edge + 1.5 ms, from the - // Choreographer frameTimeNanos), so cadence is exactly one - // period. See `vkprobe::present_gate` and - // docs/BUGS/scroll-jank-120hz.md §9. + // late — under the model THEN believed (callback 3-6 ms + // late). That model was WRONG: the callback fires at + // edge+0.5 ms (measured, VSYNC mon−ftn). See + // docs/BUGS/hypotheses-120hz.md. + // + // RENDER-AHEAD (re-enabled under the corrected model): the + // wake arrives ON the edge, so the held frame — presented + // at the START of this render — lands at edge+~1.5 ms: + // constant phase, ~4 ms of deadline margin, and render + // SPIKES (Skia 5-10 ms) stop delaying visible frames: a + // spike only stretches the PREPARE phase of the frame held + // for the NEXT slot (presented at the NEXT edge+1.5 ms, + // same phase). Cost: one slot of constant latency + // (imperceptible). i_slint_renderer_skia::wgpu_30_surface::vkprobe::RENDER_AHEAD_ACTIVE - .store(false, std::sync::atomic::Ordering::Relaxed); - // PRESENT GATE: quantize the present to the vsync grid while - // animating (drag/fling) — including the follow-up UNLOCKED - // renders (see the do_render note above), so every present - // in the burst lands on the same grid phase. One-off - // redraws (taps, model updates) stay ungated for minimum - // latency. - // PRESENT GATE: DISABLED. Sleeping on the UI thread to - // quantize the present proved counterproductive — every ms - // of gate sleep adds to the slot budget (wake 5.3 + core 3 - // + gate 3 + present 1 = 12.3 ms > 8.3 ms slot → 60 Hz - // collapse, measured). The early waker (vsync.rs) instead - // moves the RENDER START to the vsync edge, so the present - // lands at a constant natural phase (~edge+3 ms) with no - // sleep at all. The gate code stays for reference. + .store(locked, std::sync::atomic::Ordering::Relaxed); + // PRESENT GATE: DISABLED (UI-thread sleep ate the slot + // budget — history in hypotheses-120hz.md). Reference only. i_slint_renderer_skia::wgpu_30_surface::vkprobe::PRESENT_GATE_ON .store(false, std::sync::atomic::Ordering::Relaxed); stg::S_RENDER_START.store(t2, std::sync::atomic::Ordering::Relaxed); + // Spike classifier (hypotheses-120hz.md): CPU time inside + // do_render. rcpu≈render ⇒ Skia/wgpu CPU work; rcpu≪render ⇒ + // blocked on the GPU/driver (queue back-pressure, fences). + let __rc0 = stg::thread_cpu_us(); self.window.do_render()?; let t3 = stg::now_us(); stg::S_RENDER_END.store(t3, std::sync::atomic::Ordering::Relaxed); render_us = t3 - t2; + __render_cpu = stg::thread_cpu_us().saturating_sub(__rc0); } else { stg::S_RENDER_END.store(0, std::sync::atomic::Ordering::Relaxed); } @@ -397,6 +397,7 @@ impl i_slint_core::platform::Platform for AndroidPlatform { stg::wake_snapshot(), (locked, saw_wake, pr_before, do_render), __poll_cpu, + __render_cpu, ); } } diff --git a/vendor/i-slint-backend-android-activity-1.18.1/stg.rs b/vendor/i-slint-backend-android-activity-1.18.1/stg.rs index bba363f..8753325 100644 --- a/vendor/i-slint-backend-android-activity-1.18.1/stg.rs +++ b/vendor/i-slint-backend-android-activity-1.18.1/stg.rs @@ -243,6 +243,7 @@ pub fn log_iter( wk: (u64, u64, u64), dec: (bool, bool, bool, bool), poll_cpu_us: u64, + render_cpu_us: u64, ) { // Jank-hunt fix: emit through the log facade (nblog) instead of a private // BufWriter — two independent buffers appending to the same file made IT @@ -251,10 +252,10 @@ pub fn log_iter( let live_rows = i_slint_core::model::repeater::LV_LIVE_ROWS .load(std::sync::atomic::Ordering::Relaxed); log::info!( - "IT {} poll={}us nev={} fe={}us timers={}us ev={}us render={}us anim={} to={}ms lv1={}/{} e={}/{}/{} ent={}/{} lv2={}/{} flk={}/{} inb={}/{} toc={}/{}/{} wk={}/{}/{} live={} dec={}/{}/{}/{} pcpu={}us", + "IT {} poll={}us nev={} fe={}us timers={}us ev={}us render={}us anim={} to={}ms lv1={}/{} e={}/{}/{} ent={}/{} lv2={}/{} flk={}/{} inb={}/{} toc={}/{}/{} wk={}/{}/{} live={} dec={}/{}/{}/{} pcpu={}us rcpu={}us", start_us, poll_us, nev, first_ev_us, timer_us, event_us, render_us, animating as u8, timeout_ms, lv1.0, lv1.1, lv1.2, lv1.3, lv1.4, lv1.5, lv1.6, lv2.0, lv2.1, flk.0, flk.1, inp.0, inp.2, tocls.0, tocls.1, tocls.2, wk.0, wk.1, wk.2, live_rows, - dec.0 as u8, dec.1 as u8, dec.2 as u8, dec.3 as u8, poll_cpu_us + dec.0 as u8, dec.1 as u8, dec.2 as u8, dec.3 as u8, poll_cpu_us, render_cpu_us ); }