diff --git a/tools/__pycache__/jank_capture.cpython-311.pyc b/tools/__pycache__/jank_capture.cpython-311.pyc new file mode 100644 index 0000000..7d0b4c7 Binary files /dev/null and b/tools/__pycache__/jank_capture.cpython-311.pyc differ diff --git a/tools/__pycache__/jank_eval.cpython-311.pyc b/tools/__pycache__/jank_eval.cpython-311.pyc index e520faa..14a625e 100644 Binary files a/tools/__pycache__/jank_eval.cpython-311.pyc and b/tools/__pycache__/jank_eval.cpython-311.pyc differ diff --git a/tools/jank_capture.py b/tools/jank_capture.py index 144bff2..a5d2968 100644 --- a/tools/jank_capture.py +++ b/tools/jank_capture.py @@ -53,7 +53,8 @@ LINE_RES = [ r"render=(\d+)us anim=(\d) to=(\d+)ms .*dec=([\d/]+) pcpu=(\d+)us " r"rcpu=(\d+)us vsw=(\d+) nvol=(\d+)")), ("VSYNC", re.compile(r"^VSYNC ftn=(\d+) mon=(\d+)")), - ("PRES", re.compile(r"^PRES f=(\d+)\w* mon=(\d+) pre_us=(\d+) precpu=(\d+)us")), + ("PRES", re.compile(r"^PRES f=(\d+)\w* mon=(\d+) pre_us=(\d+)")), + ("NOPRES",re.compile(r"^NOPRES f=(\d+) mon=(\d+) why=(\S+)")), ("EW", re.compile(r"^EW land=(-?\d+)ms")), ("SLOWEV",re.compile(r"^SLOWEV (\S+) (\d+)us cpu=(\d+)us")), ("FR", re.compile(r"^FR gap=([\d.]+) mon=(\d+)")), @@ -151,7 +152,9 @@ def miss_report(parsed, period_us, max_episodes=12, ctx_ms=33): elif kind == "VSYNC": tag = f"VSYNC ftn={grp[0]} (+{(mon - int(grp[0]))/1e6:.2f}ms cb latency)" elif kind == "PRES": - tag = f"PRES f={grp[0]} pre={grp[2]} precpu={grp[3]}" + tag = f"PRES f={grp[0]} pre={grp[2]}us" + elif kind == "NOPRES": + tag = f"NOPRES f={grp[0]} why={grp[2]}" elif kind == "FR": tag = f"FR gap={grp[0]}ms" elif kind == "SLOWEV": @@ -195,6 +198,7 @@ def capture(app, drags, tag, tag_file, outdir, settle_after): time.sleep(3) if not resumed(app, rpt): rpt["valid"] = False + screen_awake(rpt) # before: screen must be Awake for input to land if launch != "COLD": rpt["notes"].append(f"launch was {launch}, not COLD (leftover process?)") @@ -210,6 +214,7 @@ def capture(app, drags, tag, tag_file, outdir, settle_after): # 5. state + stop resumed(app, rpt) + screen_awake(rpt) adb_shell(f"am force-stop {app}") time.sleep(1) @@ -232,6 +237,26 @@ def capture(app, drags, tag, tag_file, outdir, settle_after): print(f" valid: {rpt['valid']}") return 0 if rpt["valid"] else 1 +def screen_awake(rpt): + """The capture is INVALID unless the screen is Awake: with the screen + off, `input swipe` injects nothing and the app idles — a whole run can + be silently wasted (buildD 2026-10-30: 49 IT lines, 1 present, screen + asleep the entire time).""" + out = adb_shell("dumpsys power | grep -E 'mWakefulness=' | head -1").stdout.strip() + awake = "Awake" in out + kg = adb_shell("dumpsys window | grep -m1 'isKeyguardShowing'").stdout.strip() + keyguard_up = "true" in kg + key = "awake_after_run" if "awake_after_run" in rpt else "awake_before_run" + if keyguard_up: + rpt["valid"] = False + rpt["notes"].append(f"keyguard showing ({key}): input would be eaten by the lock screen") + return False + rpt[key] = awake + if not awake or keyguard_up: + rpt["valid"] = False + rpt["notes"].append(f"screen NOT awake ({key}): {out or 'no mWakefulness line'}") + return awake + def resumed(app, rpt): out = adb_shell("dumpsys activity activities | grep ResumedActivity").stdout ok = app in out diff --git a/tools/jank_eval.py b/tools/jank_eval.py index 1bd8e57..bb66548 100644 --- a/tools/jank_eval.py +++ b/tools/jank_eval.py @@ -30,7 +30,7 @@ Exit: 0 = PASS, 1 = FAIL, 2 = no usable data. Self-test: --selftest (synthesizes log FILES and runs the same main() path end-to-end; the tool must classify each case or exit non-zero). """ -import argparse, math, os, re, sys, tempfile +import argparse, bisect, math, os, re, sys, tempfile from collections import defaultdict PRES_RE = re.compile(r"^PRES f=(\d+)\w* mon=(\d+)") @@ -82,6 +82,38 @@ def anchor_phase(monots, period): if ang < 0: ang += 2*math.pi return int(ang/(2*math.pi)*period) +def slot_of_ftn(m, ftns, P): + """Assign a present to the slot of the NEAREST OBSERVED hardware edge, + in a TIME-CONTINUOUS slot domain. (2026-10-30: the cumulative grid + anchored at ftns[0] is WRONG after a display phase-slip — the 120 Hz + panel clock re-locks at an arbitrary phase after idle blanking, so every + present after the slip measures ~5-6 ms 'late' against the stale grid + while landing perfectly against the real edges. Measured on the phone: + an entire drag window (w1) read late=230/dropped=24 while per-cycle + tracing showed presents at edge +2.0 ms.) + + The slot of present m is: round((ftn_i − ftns[0])/P) where ftn_i is the + nearest observed edge before m (plus one when m is in that edge's second + half). A phase-slip Δ

P: + x = (m - ftns[0]) / P + s = int(x + 0.5) if x >= 0 else -int(-x + 0.5) + return s, (m - ftns[0]) - s * P + base = (ftns[i] - ftns[0]) / P + s = int(base + 0.5) if base >= 0 else -int(-base + 0.5) + if d >= P / 2: + s += 1 + return s, d + def slot_of(m, P, grid): """grid = ('edge', ftn0) or ('anchor', anchor). Returns (slot, phase_ns). edge: phase in [0, P) from the vsync edge (hardware truth) @@ -148,11 +180,15 @@ def explicit_windows(pres, t0, spec): out.append((name or f"w{len(out)}", idx0, idx1)) return out -def evaluate(pres, P, grid, windows, suspect=False): +def evaluate(pres, P, grid, windows, suspect=False, ftns=None): """suspect=True (fitted grid, no VSYNC edges): drops/doubles are reported for information but excluded from the verdict — a fitted grid can't prove - them. Stalls and late-phase remain meaningful.""" + them. Stalls and late-phase remain meaningful. + ftns: observed hardware vsync edges — when given, slots/phases are + assigned relative to the NEAREST observed edge (phase-slip robust); see + slot_of_ftn.""" t0 = pres[0][1] + use_ftn = ftns is not None and len(ftns) > 10 any_fail = False total = 0 for name, i0, i1 in windows: @@ -167,7 +203,10 @@ def evaluate(pres, P, grid, windows, suspect=False): phases = [] for k in range(len(seg)): f, m = seg[k] - s, p = slot_of(m, P, grid) + if use_ftn: + s, p = slot_of_ftn(m, ftns, P) + else: + s, p = slot_of(m, P, grid) phases.append(p) if prev_s is not None: gap = s - prev_s @@ -304,7 +343,7 @@ def run_file(path, period_ms, windows_spec): wins = explicit_windows(pres, t0, windows_spec) if windows_spec else auto_windows(pres, P) if not wins: print("no active windows found"); return False, suspect - return evaluate(pres, P, grid, wins, suspect=suspect), suspect + return evaluate(pres, P, grid, wins, suspect=suspect, ftns=ftns or None), suspect def main(): ap = argparse.ArgumentParser() diff --git a/vendor/i-slint-backend-android-activity-1.18.1/Cargo.toml b/vendor/i-slint-backend-android-activity-1.18.1/Cargo.toml index 23ef7f3..c177aa0 100644 --- a/vendor/i-slint-backend-android-activity-1.18.1/Cargo.toml +++ b/vendor/i-slint-backend-android-activity-1.18.1/Cargo.toml @@ -101,6 +101,10 @@ default-features = false [target.'cfg(target_os = "android")'.dependencies.jni] version = "0.22" +# eventfd for the vsync delivery fd (vsync.rs wake-fd-race fix) +[target.'cfg(target_os = "android")'.dependencies.libc] +version = "0.2" + [target.'cfg(target_os = "android")'.dependencies.ndk-08] version = "0.8.0" features = ["rwh_06"] 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 ea59c9a..ec1ac8a 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 @@ -126,6 +126,11 @@ impl i_slint_core::platform::Platform for AndroidPlatform { // the frame held by the render-ahead pipeline (otherwise the last // content change would never be displayed). let mut prev_locked = false; + // Edge (ns) of the last vsync delivered to this thread via the + // eventfd trampoline (vsync.rs). A value newer than this at + // decision time means a wake was delivered THIS iteration — immune + // to the ALooper wake-fd swallow (see vsync.rs note). + let mut last_delivered_edge = 0u64; loop { let mut timeout = ctx.duration_until_next_timer_update(); // While animating, the vsync thread wakes this loop at each display refresh @@ -260,6 +265,17 @@ impl i_slint_core::platform::Platform for AndroidPlatform { let t_poll1 = stg::now_us(); let __poll_cpu = stg::thread_cpu_us().saturating_sub(__cpu_p0); let lv1 = stg::lv_snapshot(); + // Wake-fd-race fix (2026-10-30): the ALooper wake byte can be + // CONSUMED by Looper::pollInner while pollOnce returns a + // co-batched input ident (system/core/libutils/Looper.cpp — the + // POLL_WAKE result is a dropped local; see vsync.rs). The + // dedicated eventfd trampoline runs inside poll_events and + // publishes the delivered edge there — check it NOW, after. + let __delivered = vsync.take_delivered_edge(); + if __delivered > last_delivered_edge { + saw_wake = true; + last_delivered_edge = __delivered; + } // Unconditionally update timers and animations on every event-loop wakeup ctx.update_timers_and_animations(); @@ -328,7 +344,16 @@ impl i_slint_core::platform::Platform for AndroidPlatform { __now_ns.saturating_sub(__e) / 1000, __now_ns.saturating_sub(__last) / 1000); } - let __accept = saw_wake && (__p == 0 || __sw > __sn); + // DIRTY BACKSTOP (2026-10-30): the 6 ms poll cap exists to + // bound chain-breaks — but a timeout iteration has + // saw_wake=false, so `saw_wake && guard` never rendered and + // the "backstop" backstopped nothing (the 20-40 ms silences). + // If the window is dirty and the last render is >=2 slots + // old, render NOW regardless of wake state. + let __dirty = self.window.pending_redraw.get(); + let __age = __now_ns.saturating_sub(__last); + let __backstop = __dirty && __last != 0 && __p != 0 && __age >= 2 * __p; + let __accept = (saw_wake && (__p == 0 || __sw > __sn)) || __backstop; if __accept { i_slint_renderer_skia::wgpu_30_surface::vkprobe::LAST_RENDER_START_NS .store(__now_ns, std::sync::atomic::Ordering::Relaxed); diff --git a/vendor/i-slint-backend-android-activity-1.18.1/vsync.rs b/vendor/i-slint-backend-android-activity-1.18.1/vsync.rs index 04c7e9e..1aa557e 100644 --- a/vendor/i-slint-backend-android-activity-1.18.1/vsync.rs +++ b/vendor/i-slint-backend-android-activity-1.18.1/vsync.rs @@ -5,7 +5,8 @@ //! Optimized for ultra-low latency: self-re-entrant Choreographer callbacks wake //! the main loop directly on vsync without thread round-trip serialization delay. -use std::sync::atomic::{AtomicBool, Ordering}; +use std::os::fd::FromRawFd; +use std::sync::atomic::{AtomicBool, AtomicI32, AtomicU64, Ordering}; use std::sync::{Arc, Condvar, Mutex}; use std::thread::JoinHandle; @@ -13,13 +14,22 @@ use crate::android_activity::AndroidAppWaker; use crate::ndk::looper::{ForeignLooper, ThreadLooper}; mod ffi { - use core::ffi::{c_long, c_void}; + use core::ffi::{c_int, c_long, c_void}; #[repr(C)] pub struct AChoreographer { _unused: [u8; 0], } + #[repr(C)] + pub struct ALooper { + _unused: [u8; 0], + } pub type FrameCallback = unsafe extern "C" fn(frame_time_nanos: c_long, data: *mut c_void); + pub type FdCallback = + unsafe extern "C" fn(fd: c_int, events: c_int, data: *mut c_void) -> c_int; + + pub const ALOOPER_POLL_CALLBACK: c_int = -1; + pub const ALOOPER_EVENT_INPUT: c_int = 0x0001; #[link(name = "android")] unsafe extern "C" { @@ -29,9 +39,36 @@ mod ffi { callback: FrameCallback, data: *mut c_void, ); + pub fn ALooper_forThread() -> *mut ALooper; + pub fn ALooper_addFd( + looper: *mut ALooper, + fd: c_int, + ident: c_int, + events: c_int, + callback: Option, + data: *mut c_void, + ) -> c_int; } } +/// ALooper wake-fd race (2026-10-30, ROOT CAUSE of the 120 Hz slot drops): +/// `Looper::pollInner` (system/core/libutils/Looper.cpp) drains the wake fd +/// in the SAME epoll batch as any ready input fd, and `pollOnce` returns the +/// input's ident — the `POLL_WAKE` result is a local that gets dropped. The +/// `ALooper_wake` byte is consumed WITHOUT `PollEvent::Wake` ever reaching +/// Slint, and it cannot be recovered (the byte is gone). With motion events +/// arriving 1-4 ms after the edge (always, for a real finger at 120-240 Hz +/// input rate; ~1 in 5 frames for 20 Hz adb input) the wake is lost and the +/// locked render decision (`saw_wake && slot-guard`) drops the dirty frame +/// for that slot — measured: 8-12% of slots dropped, uniform `dec=1/0/1/0`. +/// +/// Fix: a dedicated eventfd registered with the main looper under +/// `ALOOPER_POLL_CALLBACK`. The Looper invokes its C callback INSIDE +/// `pollInner` (before pollOnce returns, and regardless of which ident +/// pollOnce hands back), so the delivery can never be swallowed by an input +/// response. The trampoline publishes the edge ns into `delivered_edge`; the +/// main loop treats "new edge delivered" exactly like `saw_wake`. + struct Shared { state: Mutex, cond: Condvar, @@ -39,6 +76,35 @@ struct Shared { looper: Mutex>, main_waker: AndroidAppWaker, choreographer: *mut ffi::AChoreographer, + /// Dedicated vsync-delivery eventfd (see the wake-fd race note above). + /// Raw fd (>=0 once registered; -1 = unavailable). The fd is leaked on + /// purpose: it is registered with the MAIN looper, which outlives the + /// driver (same lifetime convention as the forgotten Timer). + evfd_raw: AtomicI32, + /// Edge (CLOCK_MONOTONIC ns) of the latest vsync DELIVERED to the main + /// thread via the eventfd trampoline. The main loop swaps it out each + /// iteration; a value > last-seen means "saw a wake this iteration" — + /// immune to the ALooper wake-fd swallow. + delivered_edge: AtomicU64, +} + +/// Trampoline: runs on the MAIN thread inside ALooper_pollOnce (see the +/// race note above). Publishes the edge that `frame_callback` just wrote. +unsafe extern "C" fn vsync_fd_trampoline(fd: i32, _events: i32, data: *mut core::ffi::c_void) -> i32 { + // DRAIN FIRST (level-triggered): the eventfd is a counter; if we never + // read it, it stays readable forever and ALooper_pollOnce returns + // POLL_CALLBACK on EVERY poll — the main loop busy-spins at ~10 kHz + // (measured: 1812 spin iterations per run, wake→render latency stretched + // to +5.5 ms phase in the affected window). + let mut counter: u64 = 0; + libc::read(fd, &mut counter as *mut u64 as *mut core::ffi::c_void, 8); + let shared = &*(data as *const Shared); + let edge = i_slint_renderer_skia::wgpu_30_surface::vkprobe::VSYNC_EDGE_NS + .load(Ordering::Acquire); + if edge > 0 { + shared.delivered_edge.store(edge, Ordering::Release); + } + 1 // keep the fd registered } unsafe impl Send for Shared {} @@ -76,7 +142,36 @@ impl VsyncDriver { looper: Mutex::new(None), main_waker: main_waker.clone(), choreographer: std::ptr::null_mut(), + evfd_raw: AtomicI32::new(-1), + delivered_edge: AtomicU64::new(0), }); + // Register the delivery eventfd with the MAIN looper (this runs on + // the main thread, from run_event_loop). ALOOPER_POLL_CALLBACK makes + // the Looper invoke the trampoline itself inside pollInner. + unsafe { + let evfd = libc::eventfd(0, libc::EFD_NONBLOCK); + if evfd >= 0 { + let looper = ffi::ALooper_forThread(); + let r = ffi::ALooper_addFd( + looper, + evfd, + ffi::ALOOPER_POLL_CALLBACK, + ffi::ALOOPER_EVENT_INPUT, + Some(vsync_fd_trampoline), + Arc::as_ptr(&shared) as *mut core::ffi::c_void, + ); + if r >= 0 { + log::info!("VSYNC EVFD registered fd={evfd}"); + shared.evfd_raw.store(evfd, Ordering::Release); + // Leak: the fd belongs to the main looper for the life of + // the process (the driver's drop must not close it). + std::mem::forget(std::os::fd::OwnedFd::from_raw_fd(evfd)); + } else { + log::error!("VSYNC EVFD ALooper_addFd failed"); + libc::close(evfd); + } + } + } let handle = std::thread::Builder::new() .name("slint vsync".into()) .spawn({ @@ -112,6 +207,15 @@ impl VsyncDriver { self.shared.driving.load(Ordering::Acquire) } + /// Consume the latest vsync edge delivered to the main thread via the + /// eventfd trampoline (0 = nothing new this iteration). Call ONCE per + /// main-loop iteration, after poll_events. + pub fn take_delivered_edge(&self) -> u64 { + self.shared.delivered_edge.swap(0, Ordering::AcqRel) + } + + /// (edge delivery happens in `frame_callback`, which owns &Shared) + /// Push (animating, dirty) into the driver every main-loop iteration. /// The vsync thread re-posts the first Choreographer callback, and /// `frame_callback` re-posts the chain, while `animating || dirty`. @@ -259,17 +363,29 @@ unsafe extern "C" fn frame_callback( data: *mut core::ffi::c_void, ) { let shared = &*(data as *const Shared); - // CRITICAL PATH: wake the main loop FIRST. The VSYNC log line below is - // a file write (50-200us typical, worse under I/O pressure) — doing it - // before the wake would push the main loop's render start (and thus the - // present phase) later in the slot. - shared.main_waker.wake(); - // PRESENT GATE: publish the exact vsync edge (CLOCK_MONOTONIC ns — the - // same epoch as `mon_ns()` above) so the renderer can quantize its - // `Queue::present` to the vsync grid (wgpu_30_surface::vkprobe). + // Publish the exact vsync edge (CLOCK_MONOTONIC ns — the same epoch as + // `mon_ns()` above) FIRST: the trampoline reads VSYNC_EDGE_NS, and the + // slot guard in the event loop keys off it. i_slint_renderer_skia::wgpu_30_surface::vkprobe::note_vsync_edge( frame_time_nanos as u64, ); + // CRITICAL PATH: deliver the edge to the main loop. (1) the dedicated + // eventfd — its trampoline runs inside ALooper_pollOnce and CANNOT be + // swallowed by a co-batched input response (the wake-fd race); (2) + // ALooper_wake as secondary (still the normal PollEvent::Wake path when + // no other fd is ready in the batch). The VSYNC log line below is a + // file write (50-200us typical) — kept after both wakes so it cannot + // push the main loop's render start later in the slot. + let evfd = shared.evfd_raw.load(Ordering::Acquire); + if evfd >= 0 { + let one: u64 = 1; + libc::write( + evfd, + &one as *const u64 as *const core::ffi::c_void, + core::mem::size_of::(), + ); + } + shared.main_waker.wake(); let mon = unsafe { mon_ns() }; if mon > 0 { log::info!("VSYNC ftn={} mon={}", frame_time_nanos, mon); diff --git a/vendor/i-slint-renderer-skia/wgpu_30_surface.rs b/vendor/i-slint-renderer-skia/wgpu_30_surface.rs index 94a8161..c264004 100644 --- a/vendor/i-slint-renderer-skia/wgpu_30_surface.rs +++ b/vendor/i-slint-renderer-skia/wgpu_30_surface.rs @@ -617,10 +617,21 @@ impl crate::Surface for WGPUSurface { } let __cpu0 = vkprobe::thread_cpu_ns(); let __t_acq = vkprobe::now_us(); + // NOPRES log (2026-10-30): an early return here leaves pending_frame + // EMPTY (the held frame was already presented at the top of this + // call), so the NEXT draw has nothing to present — one display slot + // vanishes with no PRES line. The cause is logged HERE, at the + // failing draw. Balance check: #FR == #PRES + #NOPRES + first-draw. + let __nopres = |why: &str| { + let mon = vkprobe::monotonic_ns(); + if mon > 0 { + log::info!("NOPRES f={} mon={} why={}", __f, mon, why); + } + }; let frame = match surface.get_current_texture() { wgpu::CurrentSurfaceTexture::Success(t) => t, - wgpu::CurrentSurfaceTexture::Occluded => return Ok(DrawOutcome::Occluded), - wgpu::CurrentSurfaceTexture::Timeout => return Ok(DrawOutcome::Timeout), + wgpu::CurrentSurfaceTexture::Occluded => { __nopres("occluded"); return Ok(DrawOutcome::Occluded); }, + wgpu::CurrentSurfaceTexture::Timeout => { __nopres("timeout"); return Ok(DrawOutcome::Timeout); }, wgpu::CurrentSurfaceTexture::Validation => { return Err("WGPU surface validation error in get_current_texture".into()); } @@ -636,7 +647,7 @@ impl crate::Surface for WGPUSurface { surface.configure(&self.wgpu.device, surface_config); match surface.get_current_texture() { wgpu::CurrentSurfaceTexture::Success(t) => t, - _ => return Ok(DrawOutcome::Occluded), + _ => { __nopres("reconfig"); return Ok(DrawOutcome::Occluded); }, } } };