120Hz: re-enable render-ahead under the corrected timing model

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

@@ -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).

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

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