diff --git a/docs/BUGS/hypotheses-120hz.md b/docs/BUGS/hypotheses-120hz.md index 797326d..0137a3d 100644 --- a/docs/BUGS/hypotheses-120hz.md +++ b/docs/BUGS/hypotheses-120hz.md @@ -108,10 +108,56 @@ phone, 2×4 s drags, 1433 transitions: stall on the per-line flush. Batch-flush (N lines or 100 ms) needed for long runs. -### Remaining plan -1. User finger test: sltest first (minimal), then gallery with the - render-ahead build (already built, aarch64). -2. If residual jank on gallery: same sltslot.py analysis on the gallery - perf log; spikes there are textured (bigger SKD) — the absorption - should still hold; CPU-spike attack (Skia) as fallback. -3. Batch-flush fix for sltest's logger before longer phone sessions. +### 2026-07-09 (3) — jank_eval.py: the referee + +User rightly rejected ad-hoc analysis (and my over-optimistic +"effectively zero-jank" claim for the slt4 run). Built +`tools/jank_eval.py`: strict PASS/FAIL against the zero-jank definition +(no dropped slot, no same-slot double, no present past the SF latch +(+5 ms edge phase), no >20 ms present gap, phase spread p10-p90 <= 0.5 ms) +per active window. + +- SLOT GRID: VSYNC `ftn=` edges = hardware truth (slot = floor((m-ftn0)/P), + P = median 1-slot ftn delta). Anchor-fit fallback only for VSYNC-less + logs (documented ambiguity limit >P/2). +- Self-test: 7 synthetic LOG FILES run through the same main() path — + perfect / 3-slot drop / double / past-latch late / 120 ms stall / + phase swing / sub-threshold jitter — all classified correctly. +- Emulator validated: correctly detects the 60 Hz emulated display, + finds active windows, reports the known emulated-SF jank. Window + thresholds scale with display rate. +- Estimator lessons (documented in the tool): median-of-deltas is biased + by correlated jitter (1.8% for a 0.15 ms sawtooth!); a residual-score + period search is non-minimizing at the true P (nearest-slot + quantization); floor-vs-round slot assignment flips frames near the + anchor. The hardware edge grid avoids all of it. + +**Honest re-judgement of slt4 (my 2-minute phone test), via the new tool** +(window w0 = drag 1, n=452, 120.066 Hz): + dropped=4 (incl. one 30.6 ms + one 21.0 ms stall), late=20 + (+5.1..+7.4 ms, early in the drag), phase spread 1.11 ms, 163 phase + jumps >0.5 ms -> FAIL. The user's "I saw jank during the test" is + confirmed by the data. (w1-w3 = post-test drain-stall corruption + + user phone usage, excluded.) + +### Diagnosis state (what the CPU profiling did and did NOT answer) +- Answered: per-frame CPU work when a frame RUNS = 3.7 ms median, tight + p90. It is not missing compute; there is no CPU work missing. +- UNANSWERED (now targeted): why NO frame ran in the stall slots, and + why renders started past the latch. Candidates ranked: + 1. FRESHNESS GUARD misfire: threshold 6.83 ms vs earliest legitimate + interval after a Choreographer-phase render 7.03 ms = 0.2 ms margin; + any jitter false-rejects a render (and a reject can't be "undone" — + the held frame waits a full extra slot). + 2. Lost wakes: locked do_render = saw_wake && fresh; if BOTH the early + waker and the Choreographer fail to deliver a Wake event for a slot, + the frame silently vanishes. No counter exists for this today. + 3. Loop blocked (driver/system call) for tens of ms — rcpu split will + show wall≫rcpu. +- Next build (phone): slot-based guard (reject only if the wake's slot + <= last rendered slot, slot from the edge grid) + a per-slot render + ledger that logs every missed slot WITH its reason (no-wake / + guard-reject / not-animating / blocked). jank_eval is the referee. +- sltest logger: batch-flush fix still pending (drain thread went silent + ~120 s into process B; PRES lines use a separate path so present data + survived). diff --git a/src/lib.rs b/src/lib.rs index 6404e86..3c3aede 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1479,6 +1479,7 @@ mod nblog { || msg.starts_with("CPUW ") || msg.starts_with("IT ") || msg.starts_with("SLOWEV ") + || msg.starts_with("MISS ") || msg.starts_with("OTHR ") || msg.starts_with("INVK ") || msg.starts_with("INVK_TAG ") @@ -1509,6 +1510,7 @@ mod nblog { || msg.starts_with("CPUW ") || msg.starts_with("IT ") || msg.starts_with("SLOWEV ") + || msg.starts_with("MISS ") || msg.starts_with("OTHR ") || msg.starts_with("INVK ") || msg.starts_with("INVK_TAG ") diff --git a/tools/__pycache__/jank_eval.cpython-311.pyc b/tools/__pycache__/jank_eval.cpython-311.pyc new file mode 100644 index 0000000..e520faa Binary files /dev/null and b/tools/__pycache__/jank_eval.cpython-311.pyc differ diff --git a/tools/jank_eval.py b/tools/jank_eval.py new file mode 100644 index 0000000..12550c1 --- /dev/null +++ b/tools/jank_eval.py @@ -0,0 +1,302 @@ +#!/usr/bin/env python3 +""" +jank_eval.py — deterministic 120 Hz scroll-jank evaluator. + +Reads app-side perf logs (PRES/VSYNC lines from the vendored stg/vkprobe +instrumentation) and produces a strict, repeatable PASS/FAIL report against +the zero-jank definition (docs/BUGS/hypotheses-120hz.md): + + PASS iff, in every ACTIVE window (sustained rendering): + 1. no DROPPED slot (present in slot k, next present in slot k+2+) + 2. no DOUBLE (two presents in the same display slot) + 3. no LATE present (edge-grid phase > +5.0 ms, past the SF latch) + 4. no STALL (present-to-present > 20 ms) + 5. phase spread p10-p90 <= 0.5 ms (edge grid: phase within slot) + +SLOT GRID (the part that takes care to get right): + * PRIMARY: the VSYNC `ftn=` field is the hardware vsync EDGE timestamp. + slot(m) = floor((m - ftn0)/P), phase = (m-ftn0) mod P in [0,P). + Exact and unambiguous for any present phase. P = median 1-slot ftn + delta (hardware truth). + * FALLBACK (no VSYNC lines, e.g. emulator sanity runs): slot = + round((m - anchor)/P) with anchor = circular mean of present phases. + Ambiguous for presents >P/2 from the anchor (documented limitation); + LATE detection is unreliable in this mode. + +Windows: --windows "startMs,endMs name; ..." (ms from first present) +or auto-detected (present rate > 60/s active, < 10/s idle). + +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 +from collections import defaultdict + +PRES_RE = re.compile(r"^PRES f=(\d+)\w* mon=(\d+)") +VSYNC_RE = re.compile(r"^VSYNC ftn=(\d+) mon=(\d+)") + +def parse_log(lines): + pres, ftns = [], [] + for l in lines: + m = PRES_RE.match(l) + if m: + pres.append((int(m.group(1)), int(m.group(2)))) + continue + m = VSYNC_RE.match(l) + if m: + ftns.append(int(m.group(1))) + return pres, ftns + +def vsync_period(ftns): + """Hardware period: median of the 1-slot ftn deltas.""" + if len(ftns) < 30: return None + d = sorted(b - a for a, b in zip(ftns, ftns[1:]) if 4_000_000 < b - a < 25_000_000) + return d[len(d)//2] if d else None + +def fallback_period(monots): + """Mean of the deltas (telescoping — unbiased by correlated jitter). + Do NOT use a fitted period for the verdict on the phone; it is a + sanity-run convenience for logs without VSYNC edges.""" + n = len(monots) + return int((monots[-1] - monots[0])/(n-1)) if n > 1 else 8_333_333 + +def anchor_phase(monots, period): + """Circular mean of present phases (handles 0/P wrap and bimodal + wake-source phases; the anchor stays

= 0 else -int(-x + 0.5) + return s, (m - ref) - s*P + +def auto_windows(pres, period): + if not pres: return [] + t0 = pres[0][1] + rate = 1000.0/(period/1e6) # display Hz (120 phone, 60 emulator) + hi, lo = 0.75*rate, 0.25*rate # active vs idle density thresholds + BUCK = 500_000_000 + dens = defaultdict(int) + for f, m in pres: + dens[(m - t0)//BUCK] += 1 + last = int((pres[-1][1] - t0)//BUCK) + wins, start = [], None + for b in range(last + 1): + r = dens.get(b, 0) * 2 + if r > hi and start is None: + start = b + elif r < lo and start is not None: + wins.append((start, b)); start = None + if start is not None: + wins.append((start, last + 1)) + out = [] + for i, (b0, b1) in enumerate(wins): + idx0 = next((k for k, (f, m) in enumerate(pres) if (m - t0)//BUCK >= b0), None) + idx1 = len(pres) + for k in range(len(pres) - 1, -1, -1): + if (pres[k][1] - t0)//BUCK < b1: + idx1 = k + 1 + break + if idx0 is not None: + out.append((f"w{i}", idx0, idx1)) + return out + +def explicit_windows(pres, t0, spec): + out = [] + for part in spec.split(";"): + part = part.strip() + if not part: continue + rng, _, name = part.partition(" ") + a, b = rng.split(",") + a, b = int(a)*1_000_000, int(b)*1_000_000 + idx0 = next((k for k, (f, m) in enumerate(pres) if m >= t0 + a), None) + idx1 = len(pres) + for k in range(len(pres) - 1, -1, -1): + if pres[k][1] <= t0 + b: + idx1 = k + 1 + break + if idx0 is not None: + out.append((name or f"w{len(out)}", idx0, idx1)) + return out + +def evaluate(pres, P, grid, windows): + t0 = pres[0][1] + any_fail = False + total = 0 + for name, i0, i1 in windows: + seg = pres[i0:i1] + total += len(seg) + if len(seg) < 10: + print(f"\n=== window '{name}' n={len(seg)} -> SKIP (short)") + continue + drops = doubles = lates = stalls = jit = 0 + drop_at, stall_at, late_at, double_at = [], [], [], [] + prev_s = prev_p = None + phases = [] + for k in range(len(seg)): + f, m = seg[k] + s, p = slot_of(m, P, grid) + phases.append(p) + if prev_s is not None: + gap = s - prev_s + if gap >= 2: + drops += gap - 1 + drop_at.append((k, gap, (m - seg[k-1][1])/1e6)) + elif gap == 0: + doubles += 1 + double_at.append(k) + if p > 5_000_000: + lates += 1 + late_at.append((k, p/1e6)) + if k and (m - seg[k-1][1]) > 20_000_000: + stalls += 1 + stall_at.append((k, (m - seg[k-1][1])/1e6)) + if prev_p is not None and abs(p - prev_p) > 500_000: + jit += 1 + prev_s, prev_p = s, p + ps = sorted(phases) + spread = (ps[int(len(ps)*9)//10] - ps[len(ps)//10])/1e6 + ok = drops == 0 and doubles == 0 and lates == 0 and stalls == 0 and spread <= 0.5 + any_fail = any_fail or not ok + print(f"\n=== window '{name}' n={len(seg)} " + f"[{(seg[0][1]-t0)/1e6:.0f}..{(seg[-1][1]-t0)/1e6:.0f} ms] -> " + f"{'PASS' if ok else 'FAIL'}") + print(f" dropped={drops} doubles={doubles} late={lates} stalls={stalls} " + f"phase p10-p90={spread:.2f} ms phase-jumps>0.5ms={jit}") + for k, gap, ms in drop_at[:5]: + print(f" DROP #{k}: skipped {gap-1} slot(s), gap {ms:.1f} ms") + for k, ms in stall_at[:5]: + print(f" STALL #{k}: {ms:.1f} ms") + for k, ms in late_at[:5]: + print(f" LATE #{k}: phase +{ms:.2f} ms") + for k in double_at[:5]: + print(f" DOUBLE #{k}") + print(f"\n=== SUMMARY windows={len(windows)} frames={total} -> " + + ("PASS" if not any_fail and windows else "FAIL")) + return (not any_fail) and bool(windows) + +# ---------------------------------------------------------------- self-test +def selftest(): + """Synthesize LOG FILES (VSYNC ftn + PRES lines) and run the same + run_file() path as production. Cases must be classified exactly.""" + P = 8_333_333 + T0 = 100_000_000 + def gen(name, off, skips=(), doubles=(), stall_after=None, n=600): + lines, i = [], 0 + t = T0 + for i in range(n): + if i in skips: + t += P + continue + lines.append(f"VSYNC ftn={t} mon={t+200_000}") + m = t + off(i) + lines.append(f"PRES f={i} mon={m}") + if i in doubles: + lines.append(f"PRES f={i}b mon={m+300_000}") + t += P + if stall_after is not None and i == stall_after: + t += 120_000_000 + path = tempfile.NamedTemporaryFile("w", suffix=".log", delete=False) + path.write("\n".join(lines)) + path.close() + return path.name + + cases = [ + ("perfect 120Hz +1ms", lambda i: 1_000_000, {}, set(), None, True, + dict(drops=0, doubles=0, lates=0, stalls=0, max_spread=0.2)), + ("3-slot drop at 200", lambda i: 1_000_000, {200, 201, 202}, set(), None, False, + dict(drops=3, doubles=0, lates=0, stalls=1, max_spread=99)), + ("double at 300", lambda i: 1_000_000, {}, {300}, None, False, + dict(drops=0, doubles=1, lates=0, stalls=0, max_spread=0.2)), + ("late i%7==0 +6ms (past latch)", lambda i: 6_000_000 if i % 7 == 0 else 1_000_000, + {}, set(), None, False, + dict(drops=0, doubles=0, lates=1, stalls=0, max_spread=99)), + ("120ms stall at 400", lambda i: 1_000_000, {}, set(), 400, False, + dict(drops=14, doubles=0, lates=0, stalls=1, max_spread=99)), + ("phase swing +/-.6ms", lambda i: 1_000_000 + (i % 5 - 2)*300_000, + {}, set(), None, False, + dict(drops=0, doubles=0, lates=0, stalls=0, max_spread=1.25)), + ("tiny jitter 0.3ms", lambda i: 1_000_000 + (i % 3 - 1)*150_000, + {}, set(), None, True, + dict(drops=0, doubles=0, lates=0, stalls=0, max_spread=0.31)), + ] + ok_all = True + for name, off, skips, dbl, stall_after, expect_pass, exp in cases: + path = gen(name, off, skips, dbl, stall_after) + import io, contextlib + buf = io.StringIO() + with contextlib.redirect_stdout(buf): + res = run_file(path, period_ms=None, windows_spec="") + os.unlink(path) + txt = buf.getvalue() + m = re.search(r"dropped=(\d+) doubles=(\d+) late=(\d+) stalls=(\d+).*p10-p90=([\d.]+)", txt) + if not m: + print(f" selftest {name:32s} *** could not parse report ***\n{txt}") + ok_all = False + continue + d, db, la, st, sp = int(m.group(1)), int(m.group(2)), int(m.group(3)), int(m.group(4)), float(m.group(5)) + good = (res == expect_pass) and d >= exp["drops"] and db >= exp["doubles"] \ + and la >= exp["lates"] and st >= exp["stalls"] and sp <= exp["max_spread"] + ok_all = ok_all and good + print(f" selftest {name:32s} expect={'PASS' if expect_pass else 'FAIL':4s} " + f"got={'PASS' if res else 'FAIL':4s} (drops={d} dbl={db} late={la} stalls={st} " + f"spread={sp:.2f}) {'OK' if good else '*** MISMATCH ***'}") + print("self-test:", "PASS" if ok_all else "FAIL") + return 0 if ok_all else 1 + +def run_file(path, period_ms, windows_spec): + lines = open(path, errors="replace").read().splitlines() + pres, ftns = parse_log(lines) + if len(pres) < 50: + print("no usable PRES data"); return False + monots = [m for _, m in pres] + src, P = None, None + if ftns: + P = vsync_period(ftns) + if P: src = "vsync-edges" + if period_ms: + P, src = int(period_ms*1e6), "override" + if not P: + P, src = fallback_period(monots), "fallback-fit" + grid = ("edge", ftns[0]) if (src == "vsync-edges" or (period_ms and ftns)) else \ + ("anchor", anchor_phase(monots, P)) + t0 = monots[0] + print(f"display period: {P/1e6:.4f} ms (rate {1e6/(P/1e6):.1f} Hz, {src}; " + f"grid={'vsync-edge' if grid[0]=='edge' else 'anchor-fallback'})") + 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 + return evaluate(pres, P, grid, wins) + +def main(): + ap = argparse.ArgumentParser() + ap.add_argument("file", nargs="?") + ap.add_argument("--windows", default="", help='"startMs,endMs name; ..." (ms from first present)') + ap.add_argument("--period-ms", type=float, default=None, + help="force the display period (phone: 8.3333)") + ap.add_argument("--selftest", action="store_true") + args = ap.parse_args() + if args.selftest: + sys.exit(selftest()) + if not args.file: + ap.print_usage(); sys.exit(2) + ok = run_file(args.file, args.period_ms, args.windows) + sys.exit(0 if ok else 1) + +if __name__ == "__main__": + main() 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 7d6f6c3..d8ee44d 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 @@ -289,33 +289,43 @@ impl i_slint_core::platform::Platform for AndroidPlatform { // means the next iteration renders too; if the content is // unchanged the extra render is invisible. // - // FRESHNESS GUARD: with the early waker (vsync.rs), TWO - // wakes can arrive per slot — the early one (~0.8 ms BEFORE - // the vsync edge) and the Choreographer's late fallback - // (~5 ms after it). The first one of each slot renders; - // the second must NOT (double render = 2× the slot budget = - // 60 Hz collapse). The intervals (measured): - // late-after-early = ~5.8 ms → must be REJECTED - // early-after-late = ~7.5 ms → must be ACCEPTED - // same-kind = ~8.33 ms → ACCEPTED - // Threshold `period − 1.5 ms` (≈6.8 ms) sits between 5.8 - // and 7.5 with ~0.7-1.0 ms of jitter margin on both sides. - // (A 0.7-period threshold rejects early-after-late and a - // 1.0-period threshold locks the cadence onto the late - // wakes — both measured to fragment the burst.) + // SLOT-BASED WAKE GUARD (hypotheses-120hz.md, 2026-07-09 (3)). + // Replaces the interval freshness guard, which had a 0.2 ms + // false-reject margin (threshold 6.83 ms vs earliest + // legitimate interval 7.03 ms after a Choreographer-phase + // render) and — worse — could not express the real rule. + // The rule: at most ONE render per display slot. A wake + // belongs to slot floor((t − E)/P) (E = last observed vsync + // edge, P = period; a stale E only shifts all indices by a + // constant, so the comparison is exact). Reject only when + // the wake's slot is the one already rendered; a wake N + // slots later (after a spike or lost wakes) MUST render — + // and the gap is logged as MISS with the wake state, which + // is the missing evidence for the stall slots. let __now_ns = i_slint_renderer_skia::wgpu_30_surface::vkprobe::monotonic_ns(); - let __period_ns = i_slint_renderer_skia::wgpu_30_surface::vkprobe::VSYNC_PERIOD_NS + let __p = i_slint_renderer_skia::wgpu_30_surface::vkprobe::VSYNC_PERIOD_NS + .load(std::sync::atomic::Ordering::Relaxed); + let __e = i_slint_renderer_skia::wgpu_30_surface::vkprobe::VSYNC_EDGE_NS .load(std::sync::atomic::Ordering::Relaxed); let __last = i_slint_renderer_skia::wgpu_30_surface::vkprobe::LAST_RENDER_START_NS .load(std::sync::atomic::Ordering::Relaxed); - let __min_gap = __period_ns.saturating_sub(1_500_000); - let __fresh = __period_ns == 0 - || __now_ns.saturating_sub(__last) >= __min_gap; - if __fresh { + let __slot = |t: u64| -> i128 { + if t >= __e { ((t - __e) as i128) / (__p as i128) } + else { -((( __e - t) as i128 + __p as i128 - 1) / (__p as i128)) } + }; + let __sw = if __p == 0 { 0 } else { __slot(__now_ns) }; + let __sn = if __p == 0 || __last == 0 { i128::MIN } else { __slot(__last) }; + if __p != 0 && __last != 0 && __sw >= __sn + 2 + && stg::IT_ON.load(std::sync::atomic::Ordering::Relaxed) + { + stg::log_miss(__sw - __sn - 1, saw_wake, __now_ns); + } + let __accept = saw_wake && (__p == 0 || __sw > __sn); + if __accept { i_slint_renderer_skia::wgpu_30_surface::vkprobe::LAST_RENDER_START_NS .store(__now_ns, std::sync::atomic::Ordering::Relaxed); } - saw_wake && __fresh + __accept } else { self.window.pending_redraw.get() }; 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 8753325..3a8c9b9 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 @@ -172,6 +172,16 @@ pub fn log_slow_event(name: &str, us: u64, cpu_us: u64) { log::info!("SLOWEV {} {}us cpu={}us", name, us, cpu_us); } +/// Slot-ledger (hypotheses-120hz.md): a wake arrived for a slot >= 2 past +/// the last rendered slot — the intermediate slot(s) produced NO frame. +/// nowake = whether THIS wake was seen (a no-wake iteration precedes it). +/// This line is the missing evidence for the 20-100 ms stall slots: +/// saw_wake=true ⇒ the previous slots' wakes were LOST (eventfd/waker) +/// nowake context + slow poll/ev in the preceding IT line ⇒ loop blocked +pub fn log_miss(slots: i128, saw_wake: bool, now_ns: u64) { + log::info!("MISS mon={} slots={} nowake={}", now_ns, slots, if saw_wake { 1 } else { 0 }); +} + /// Jank-hunt: total `invoke_from_event_loop` pushes (INVK n=..). pub static INVK_PUSH_COUNT: AtomicU64 = AtomicU64::new(0);