120Hz hunt: EW wake probe + poll/render CPU-time splits; sltest baseline

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.
This commit is contained in:
Greg Pomerantz 2026-10-30 11:59:39 -04:00
parent 7c2d0f354e
commit c72bfa481d
5 changed files with 65 additions and 2 deletions

View File

@ -0,0 +1,42 @@
# 120 Hz zero-jank campaign — hypothesis log
Target: sltest (minimal 100-row grid, no textures) on the phone's Mali G715.
Definition of ZERO JANK (measured from PRES mon= + VSYNC ftn= lines):
1. no display-slot skip: for consecutive presents, slot_index(n+1) == slot_index(n)+1 (100%)
2. no same-slot double: two presents never land in the same display slot
3. phase stable: present phase within its slot varies < 0.5 ms
Test: 2x `input swipe 640 1900 640 900 4000` (slow drags) + fling, ~10 s.
A "burst" = consecutive presents with gaps < 20 ms; evaluate inside bursts only.
## Hypotheses (order = priority)
- H6 [sltest confound]: sltest FileLogger is blocking (flush per line) on the
render path (PRES/STG/IT at ~240 lines/s).
FIX: non-blocking drain-thread logger. TEST: rebuild, re-measure baseline.
- H1: early waker misses edges (thread descheduled / nanosleep jitter) →
render starts late (edge+5 late wake wins) → present phase bimodal.
TEST: render-start phase histogram vs edges; early-wake hit rate.
- H2: Skia render core variance → present phase jitter.
TEST: VK SKD distribution in sltest (trivial scene, expect <1.5 ms).
- H3: wgpu/Mali submit+present latency variance (CLR/SKF/ORD/PRE).
TEST: VK PRE / CLR / SKF distributions in sltest.
- H4: event-loop overhead (timers, change tracker, spin iterations) eats the
slot budget.
TEST: IT poll/timers/ev/fe distributions; iters/s during scroll.
- H5: CPU scheduling of the UI thread (deschedule mid-slot, core migration,
frequency).
TEST: wall vs CPU split for the render window (vkprobe thread_cpu_ns).
- H7 [method confound]: adb `input swipe` motion is bursty (~20-60 Hz) →
grid movement itself is non-uniform regardless of render cadence.
TEST: pointer-location overlay + user finger, later.
## Rules
- One hypothesis per build; keep the change minimal; measure before/after
with the identical test; record numbers here.
- A hypothesis is RULED OUT only when the measurement it predicts is absent
(not "the fix didn't help").
- Phone hygiene before each run: clean task (sz=1), ResumedActivity,
dismiss 16KB dialog (sltest is debuggable), record log byte offsets.
## Results
(append below)

View File

@ -201,6 +201,11 @@ impl i_slint_core::platform::Platform for AndroidPlatform {
// push the present past the ~5.5 ms compositor deadline → every // push the present past the ~5.5 ms compositor deadline → every
// frame shown one vsync late → effective 60 Hz + judder). // frame shown one vsync late → effective 60 Hz + judder).
let mut saw_wake = false; let mut saw_wake = false;
// H5 (hypotheses-120hz.md): CPU time inside poll_events. wall≫cpu
// ⇒ the UI thread slept/descheduled while the wake byte was
// pending (epoll not woken, or the thread lost the CPU); wall≈cpu
// ⇒ the loop spun inside ALooper.
let __cpu_p0 = stg::thread_cpu_us();
self.app.poll_events(timeout, |e| { self.app.poll_events(timeout, |e| {
if matches!(e, PollEvent::Wake) { if matches!(e, PollEvent::Wake) {
saw_wake = true; saw_wake = true;
@ -248,6 +253,7 @@ impl i_slint_core::platform::Platform for AndroidPlatform {
} }
}); });
let t_poll1 = stg::now_us(); let t_poll1 = stg::now_us();
let __poll_cpu = stg::thread_cpu_us().saturating_sub(__cpu_p0);
let lv1 = stg::lv_snapshot(); let lv1 = stg::lv_snapshot();
// Unconditionally update timers and animations on every event-loop wakeup // Unconditionally update timers and animations on every event-loop wakeup
@ -390,6 +396,7 @@ impl i_slint_core::platform::Platform for AndroidPlatform {
stg::timeout_snapshot(), stg::timeout_snapshot(),
stg::wake_snapshot(), stg::wake_snapshot(),
(locked, saw_wake, pr_before, do_render), (locked, saw_wake, pr_before, do_render),
__poll_cpu,
); );
} }
} }

View File

@ -242,6 +242,7 @@ pub fn log_iter(
tocls: (u64, u64, u64), tocls: (u64, u64, u64),
wk: (u64, u64, u64), wk: (u64, u64, u64),
dec: (bool, bool, bool, bool), dec: (bool, bool, bool, bool),
poll_cpu_us: u64,
) { ) {
// Jank-hunt fix: emit through the log facade (nblog) instead of a private // Jank-hunt fix: emit through the log facade (nblog) instead of a private
// BufWriter — two independent buffers appending to the same file made IT // BufWriter — two independent buffers appending to the same file made IT
@ -250,10 +251,10 @@ pub fn log_iter(
let live_rows = i_slint_core::model::repeater::LV_LIVE_ROWS let live_rows = i_slint_core::model::repeater::LV_LIVE_ROWS
.load(std::sync::atomic::Ordering::Relaxed); .load(std::sync::atomic::Ordering::Relaxed);
log::info!( 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={}/{}/{}/{}", "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",
start_us, poll_us, nev, first_ev_us, timer_us, event_us, render_us, animating as u8, timeout_ms, 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, 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 dec.0 as u8, dec.1 as u8, dec.2 as u8, dec.3 as u8, poll_cpu_us
); );
} }

View File

@ -184,6 +184,16 @@ fn early_waker_thread(shared: Arc<Shared>) {
} }
let landed = i_slint_renderer_skia::wgpu_30_surface::vkprobe::monotonic_ns() let landed = i_slint_renderer_skia::wgpu_30_surface::vkprobe::monotonic_ns()
.saturating_sub(target); .saturating_sub(target);
// WAKE PROBE: log every attempt (120/s, non-blocking logger) so we
// can see the nanosleep landing distribution: `land` is ns relative
// to the edge target (negative = early). H1 (hypotheses-120hz.md):
// if land is systematically > +1 ms the waker skips every wake and
// the late Choreographer wake (~edge+5) wins every slot.
if i_slint_renderer_skia::wgpu_30_surface::vkprobe::EW_ON
.load(Ordering::Relaxed)
{
log::info!("EW land={}ms", (landed as i64 - 800_000) / 1000);
}
// Wake only if we landed within ~1 ms of the edge. If we overshot // Wake only if we landed within ~1 ms of the edge. If we overshot
// (CPU starvation), the Choreographer's late wake (~5 ms after the // (CPU starvation), the Choreographer's late wake (~5 ms after the
// edge) covers the frame instead. // edge) covers the frame instead.

View File

@ -89,6 +89,9 @@ pub mod vkprobe {
std::sync::atomic::AtomicBool::new(false); std::sync::atomic::AtomicBool::new(false);
/// Microseconds the most recent `present_gate()` slept (0 = no sleep). /// Microseconds the most recent `present_gate()` slept (0 = no sleep).
pub static GATE_US: AtomicU64 = AtomicU64::new(0); pub static GATE_US: AtomicU64 = AtomicU64::new(0);
/// WAKE PROBE: log every early-waker attempt (EW lines) — H1 check.
pub static EW_ON: std::sync::atomic::AtomicBool =
std::sync::atomic::AtomicBool::new(false);
/// CLOCK_MONOTONIC ns when the last vsync-wake (locked) render STARTED. /// CLOCK_MONOTONIC ns when the last vsync-wake (locked) render STARTED.
/// The event loop uses it to skip a second wake (e.g. the Choreographer's /// The event loop uses it to skip a second wake (e.g. the Choreographer's
/// late fallback wake arriving ~5 ms after the early-waker's edge wake /// late fallback wake arriving ~5 ms after the early-waker's edge wake