diff --git a/tools/jank_capture.py b/tools/jank_capture.py new file mode 100644 index 0000000..144bff2 --- /dev/null +++ b/tools/jank_capture.py @@ -0,0 +1,351 @@ +#!/usr/bin/env python3 +""" +jank_capture.py — reliable end-to-end 120 Hz jank capture + report. + +One command owns the WHOLE pipeline so data provenance can never be wrong +(the failure mode this tool replaces: append-only logs spanning processes, +hand-computed byte offsets, tail-guessing, analyzing the wrong build's data): + + jank_capture.py capture --app wow.gmp.sltest --drags 4,2,4 [--tag buildC] + +Steps (each verified, capture marked INVALID on any state failure): + 1. verify device + record build identity (versionName, apk sha256 if given) + 2. force-stop, DELETE it.log + perf.log (=> the file can only contain + exactly ONE process from now on) + 3. cold launch, verify ResumedActivity + 4. scripted input: drags with settles ("4,2,4" = 4s drag, 2s settle, 4s drag) + 5. verify still ResumedActivity, force-stop + 6. pull the complete log (== exactly one process) + 7. report: provenance + jank_eval verdict + miss forensics + +Report sections: + [1] PROVENANCE device, app, tag, apk, time span, line counts, validity + [2] JANK jank_eval windows (drops/doubles/late/stalls/phase) + [3] MISSES every miss episode, classified, with the surrounding + all-thread timeline (what else was happening at the same + time: UI loop, vsync thread, workers, C calls, IO) + + jank_capture.py report FILE.log [--drags ...] re-analyze a captured log + jank_capture.py --selftest offline validation +""" +import argparse, hashlib, os, re, shutil, subprocess, sys, time +from collections import defaultdict + +HERE = os.path.dirname(os.path.abspath(__file__)) +sys.path.insert(0, HERE) +import jank_eval + +ADB_SERIAL = os.environ.get("ADB_SERIAL", "") +def adb(*args, timeout=120): + cmd = ["adb"] + if ADB_SERIAL: cmd += ["-s", ADB_SERIAL] + cmd += list(args) + return subprocess.run(cmd, capture_output=True, text=True, timeout=timeout) + +def adb_shell(cmd, timeout=120): + return adb("shell", cmd, timeout=timeout) + +# ------------------------------------------------------------- miss forensics +MISS_RE = re.compile( + r"^MISS mon=(\d+) slots=(-?\d+) nowake=(\d)(?: sw=(-?\d+) sn=(-?\d+) eage=(\d+)us lastage=(\d+)us)?") +LINE_RES = [ + ("IT", re.compile(r"^IT (\d+) poll=(\d+)us nev=(\d+) fe=(\d+)us timers=(\d+)us ev=(\d+)us " + 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")), + ("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+)")), + ("DECODE",re.compile(r"^DECODE ")), + ("OTHR", re.compile(r"^OTHR ")), + ("INVK", re.compile(r"^INVK ")), +] + +def parse_lines(lines): + """-> list of (kind, mon, text, fields). Log lines are single-writer and + time-ordered; lines without a timestamp (SLOWEV, DECODE, OTHR, INVK, EW) + inherit the NEXT timestamped line's mon: they are emitted just before the + next logged event (e.g. a SLOWEV fires when a 30 ms C call RETURNS, so + its true time is at the following IT line, not the one before).""" + out = [] + for i, l in enumerate(lines): + for kind, rx in LINE_RES: + m = rx.match(l) + if not m: + continue + mon = None + if kind == "IT": + # t is µs-since-boot; approximate iteration mid-time = t + poll/2 + mon = int(m.group(1)) * 1000 + int(m.group(2)) * 500 + out.append((kind, mon, l, m.groups())) + elif kind == "VSYNC": + out.append((kind, int(m.group(2)), l, m.groups())) + elif kind == "PRES": + out.append((kind, int(m.group(2)), l, m.groups())) + elif kind == "FR": + out.append((kind, int(m.group(2)), l, m.groups())) + else: + out.append([kind, None, l, m.groups()]) # mon filled below + break + else: + if l.startswith("MISS "): + mm = MISS_RE.match(l) + out.append(["MISS", int(mm.group(1)) if mm else None, l, None]) + # second pass: fill untimed mons from the NEXT timestamped line + next_mon = None + for i in range(len(out) - 1, -1, -1): + if out[i][1] is None and next_mon is not None: + out[i][1] = next_mon + if out[i][1] is not None: + next_mon = out[i][1] + return [tuple(p) for p in out] + +def classify_miss(m, period_us): + """m = MISS regex groups (v2 has sw/sn/eage/lastage; v1 doesn't).""" + slots, nowake = int(m.group(2)), int(m.group(3)) + if m.lastindex and m.lastindex >= 7: + sw, sn = int(m.group(4)), int(m.group(5)) + eage, lastage = int(m.group(6)), int(m.group(7)) + if eage > 2 * period_us: + return "CHAIN-STALL: Choreographer edge ref stale >2 slots (callback chain died)", m + if nowake == 1 and sw > sn: + return "LOOP-STUCK: wake present but prior slots unrendered (UI thread stuck; see ctx)", m + if sw <= sn: + return "GUARD-REJECT: wake slot <= last rendered slot (grid anomaly)", m + if nowake == 0: + return "NO-WAKE-ITER: loop iterating on non-wake events; Wakes missing", m + return (f"v1-format MISS slots={slots}" + ("" if nowake else " (no-wake)")), m + +def miss_report(parsed, period_us, max_episodes=12, ctx_ms=33): + misses = [p for p in parsed if p[0] == "MISS"] + if not misses: + print(" (no MISS lines)") + return + # group consecutive MISSes into episodes (gap < 3 slots * period) + eps = [] + for p in misses: + m = MISS_RE.match(p[2]) + mon = int(m.group(1)) + if eps and mon - eps[-1][1] < 3 * period_us * 1000: + eps[-1][2].append((mon, m)); eps[-1][1] = mon + else: + eps.append([mon, mon, [(mon, m)]]) + print(f" {len(misses)} MISS lines in {len(eps)} episodes") + for i, (t0, t1, ms) in enumerate(eps[:max_episodes]): + m_last = ms[-1][1] + cls, _ = classify_miss(m_last, period_us) + maxslots = max(int(x[1].group(2)) for x in ms) + print(f"\n episode {i+1}: {len(ms)} misses, max-gap {maxslots} slots, " + f"span {(t1-t0)/1e6:.1f} ms") + print(f" class: {cls}") + # context window around the episode START (what was happening before) + c0, c1 = t0 - ctx_ms*1_000_000, t0 + 2*1_000_000 + ctx = [p for p in parsed if p[1] is not None and c0 <= p[1] <= c1] + for kind, mon, line, grp in ctx[-14:]: + if kind == "IT" and grp: + poll, nev, fe, tim, ev, rd, anim, to = (int(grp[i]) for i in range(1, 9)) + dec, pc, rc, v, nv = grp[9], int(grp[10]), int(grp[11]), int(grp[12]), int(grp[13]) + tag = (f"IT poll={poll} ev={ev} rd={rd} a={anim} dec={dec} " + f"pc={pc} rc={rc} vsw={v} nvol={nv}") + 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]}" + elif kind == "FR": + tag = f"FR gap={grp[0]}ms" + elif kind == "SLOWEV": + tag = f"SLOWEV {grp[0]} {grp[1]}us cpu={grp[2]}us" + else: + tag = line[:96] + print(f" {tag}") + if len(eps) > max_episodes: + print(f" ... {len(eps)-max_episodes} more episodes (full data in log)") + +# --------------------------------------------------------------- the capture +def capture(app, drags, tag, tag_file, outdir, settle_after): + rpt = {"valid": True, "notes": []} + # 1. device + identity + d = adb("devices").stdout + if ADB_SERIAL not in d: + print(f"device {ADB_SERIAL} not found"); return 2 + ver = adb_shell(f"dumpsys package {app} | grep versionName | head -1").stdout.strip() + rpt.update(app=app, tag=tag or "unknown-build", + version=ver or "n/a", + host_date=time.strftime("%Y-%m-%d %H:%M:%S")) + if tag_file and os.path.exists(tag_file): + h = hashlib.sha256(open(tag_file, "rb").read()).hexdigest()[:16] + rpt["apk_sha256_16"] = h + rpt["drags"] = drags + + # 2. clean slate: the log can only contain THIS process + adb_shell(f"am force-stop {app}") + time.sleep(1) + for f in ("it.log", "perf.log"): + adb_shell(f"rm -f /sdcard/Android/data/{app}/files/{f}") + n0 = adb_shell(f"dumpsys activity activities | grep -c '{app}'").stdout.strip() + rpt["activity_records_after_forcestop"] = n0 + + # 3. cold launch + r = adb_shell(f"am start -W -n {app}/android.app.NativeActivity") + launch = "" + for line in r.stdout.splitlines(): + if "LaunchState" in line: launch = line.split(":", 1)[1].strip() + rpt["launch"] = launch + time.sleep(3) + if not resumed(app, rpt): + rpt["valid"] = False + if launch != "COLD": + rpt["notes"].append(f"launch was {launch}, not COLD (leftover process?)") + + # 4. scripted input + t_run0 = time.time() + spec = [float(x) for x in drags.split(",") if x.strip()] + for i, dur in enumerate(spec): + adb_shell(f"input swipe 640 1900 640 900 {int(dur*1000)}") + time.sleep(dur) + settle = settle_after if i < len(spec) - 1 else 2.0 + time.sleep(settle) + rpt["run_seconds"] = round(time.time() - t_run0, 1) + + # 5. state + stop + resumed(app, rpt) + adb_shell(f"am force-stop {app}") + time.sleep(1) + + # 6. pull exactly one process's log + os.makedirs(outdir, exist_ok=True) + name = time.strftime("cap_%H%M%S") + (f"_{tag}" if tag else "") + dest = os.path.join(outdir, name + ".log") + r = adb("pull", f"/sdcard/Android/data/{app}/files/it.log", dest, timeout=300) + if r.returncode != 0 or not os.path.exists(dest): + print("LOG PULL FAILED:\n", r.stdout, r.stderr) + return 2 + rpt["log_file"] = dest + print(f"\nlog: {dest} ({os.path.getsize(dest)} bytes)\n") + # 7. report + report(dest, tag=rpt["tag"]) + print(f"\n[1] PROVENANCE") + for k, v in rpt.items(): + if k not in ("log_file",): + print(f" {k}: {v}") + print(f" valid: {rpt['valid']}") + return 0 if rpt["valid"] else 1 + +def resumed(app, rpt): + out = adb_shell("dumpsys activity activities | grep ResumedActivity").stdout + ok = app in out + key = "resumed_after_run" if "resumed_after_run" in rpt else "resumed_after_launch" + rpt[key] = ok + if not ok: + rpt["valid"] = False + rpt["notes"].append(f"app NOT ResumedActivity ({key}) — another app stole foreground") + return ok + +# ------------------------------------------------------------------- report +def report(path, tag=None): + lines = open(path, errors="replace").read().splitlines() + size = os.path.getsize(path) + # process boundary check: exactly one ITLOG init + inits = [l for l in lines if l.startswith("ITLOG init")] + n_it = sum(1 for l in lines if l.startswith("IT ")) + n_pres = sum(1 for l in lines if l.startswith("PRES ")) + n_miss = sum(1 for l in lines if l.startswith("MISS ")) + print(f"[1] PROVENANCE") + print(f" file: {path} ({size} bytes, {len(lines)} lines)") + print(f" tag: {tag or 'n/a'} ITLOG-init lines: {len(inits)}" + + (f" ({inits[0]})" if inits else " *** NO PROCESS MARKER ***")) + if len(inits) != 1: + print(f" *** INVALID: expected exactly 1 process in the log, found {len(inits)} ***") + print(f" IT={n_it} PRES={n_pres} MISS={n_miss}") + + print(f"\n[2] JANK (jank_eval)") + ok, suspect = jank_eval.run_file(path, period_ms=None, windows_spec="") + + print(f"\n[3] MISS FORENSICS") + parsed = parse_lines(lines) + # period from VSYNC edges (or 120Hz default) + ftns = [int(m.group(1)) for l in lines if (m := re.match(r"^VSYNC ftn=(\d+) mon=(\d+)", l))] + period_us = jank_eval.vsync_period(ftns) // 1000 if len(ftns) > 30 else 8_333 + miss_report(parsed, period_us) + verdict = "PASS" if ok else "FAIL" + if suspect and ok: + verdict = "SUSPECT" + valid_prov = (len(inits) == 1) + if not valid_prov: + verdict = "INVALID" + print(f"\nVERDICT={verdict}") + return 0 if (ok and valid_prov and not suspect) else 1 + +# ------------------------------------------------------------- self-test +def selftest(): + import io, contextlib, tempfile + P = 8_333_333 + T0 = 1_000_000_000 + lines = ["ITLOG init pid=4242"] + # 100 clean frames + one 3-slot miss episode + context + for i in range(100): + t = T0 + i * P + lines.append(f"VSYNC ftn={t} mon={t + 520_000}") + skip = i in (50, 51, 52) + if not skip: + lines.append(f"IT {t + 600_000//1000} poll=1000us nev=1 fe=100us timers=5us ev=20us " + f"render=3000us anim=1 to=6ms lv1=0/0 e=0/0/0 ent=0/0 lv2=0/0 flk=0/0 " + f"inb=0/0 toc=0/0/0 wk=0/0/0 live=7 dec=1/1/0/1 pcpu=100us rcpu=2900us vsw=0 nvol=0") + lines.append(f"PRES f={i} mon={t + 1_500_000} pre_us=900 precpu=800us") + # the miss episode: loop stuck 30ms inside poll (one long-poll IT), + # wakes resume, the loop then sees the slot gap and fires MISSes + t = T0 + 53 * P + lines.append(f"SLOWEV Input 30000us cpu=300us") + lines.append(f"IT {t//1000} poll=30000us nev=1 fe=300us timers=5us ev=10us " + f"render=0us anim=1 to=6ms lv1=0/0 e=0/0/0 ent=0/0 lv2=0/0 flk=0/0 " + f"inb=0/0 toc=0/0/0 wk=0/0/0 live=7 dec=1/0/0/0 pcpu=300us rcpu=0us vsw=4 nvol=1") + for k, nw in enumerate((1, 0, 1)): + lines.append(f"MISS mon={t + 30_100_000 + k*P} slots={k+1} nowake={nw} " + f"sw=54 sn=53 eage=8300us lastage=30000us") + tmp = tempfile.NamedTemporaryFile("w", suffix=".log", delete=False) + tmp.write("\n".join(lines) + "\n"); tmp.close() + path = tmp.name + buf = io.StringIO() + with contextlib.redirect_stdout(buf): + res = report(path, tag="selftest") + os.unlink(path) + txt = buf.getvalue() + checks = { + "one process marker": "ITLOG-init lines: 1" in txt, + "episode found": "3 MISS lines in 1 episodes" in txt, + "class LOOP-STUCK or CHAIN": ("LOOP-STUCK" in txt) or ("CHAIN-STALL" in txt), + "SLOWEV in context": "SLOWEV Input 30000us" in txt, + "IT ctx with vsw": "vsw=4 nvol=1" in txt, + "verdict emitted": "VERDICT=" in txt, + } + ok = True + for k, v in checks.items(): + ok = ok and v + print(f" selftest {k:24s} {'OK' if v else '*** MISSING ***'}") + print("self-test:", "PASS" if ok else "FAIL") + return 0 if ok else 1 + +def main(): + if len(sys.argv) > 1 and sys.argv[1] == "--selftest": + sys.exit(selftest()) + ap = argparse.ArgumentParser() + ap.add_argument("cmd", choices=["capture", "report"]) + ap.add_argument("log", nargs="?", help="log file for report") + ap.add_argument("--app", default="wow.gmp.sltest") + ap.add_argument("--drags", default="4,2,4", help='comma list: 4,2,4 = 4s drag, 2s settle, 4s drag') + ap.add_argument("--settle-after", type=float, default=2.0) + ap.add_argument("--tag", default=None, help="build tag for provenance") + ap.add_argument("--tag-file", default=None, help="APK path; sha256 recorded") + ap.add_argument("--outdir", default="/tmp/jank") + args = ap.parse_args() + if args.cmd == "capture": + sys.exit(capture(args.app, args.drags, args.tag, args.tag_file, + args.outdir, args.settle_after)) + else: + if not args.log: + ap.print_usage(); sys.exit(2) + sys.exit(report(args.log, tag=args.tag)) + +if __name__ == "__main__": + main() diff --git a/tools/jank_eval.py b/tools/jank_eval.py index 12550c1..1bd8e57 100644 --- a/tools/jank_eval.py +++ b/tools/jank_eval.py @@ -55,11 +55,20 @@ def vsync_period(ftns): 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 + """Median of consecutive PRES deltas, snapped to the nearest standard + refresh period. (The telescoping MEAN is useless here: it spans idle + gaps too — 391 presents over a 23 s run fit a '59.6 ms' period on a 60 Hz + display.) The display is always a standard rate, so snap. Do NOT use a + fitted period for the verdict on the phone; VSYNC edges are the truth. + """ + if len(monots) < 2: + return 8_333_333 + d = sorted(monots[i+1] - monots[i] for i in range(len(monots) - 1)) + med = d[len(d)//2] + STD_MS = [1/240, 1/144, 1/120, 1/100, 1/90, 1/85, 1/72, 1/60, 1/50, + 1/48, 1/40, 1/30, 1/24] + best = min(STD_MS, key=lambda r: abs(1.0/r - med/1e6)) + return int(1_000_000_000 / (1.0/best)) def anchor_phase(monots, period): """Circular mean of present phases (handles 0/P wrap and bimodal @@ -86,18 +95,23 @@ def slot_of(m, P, grid): return s, (m - ref) - s*P def auto_windows(pres, period): + """NOTE: the active threshold must NOT be high — it is circular (a JANKY + app has a LOW present rate and would then not be detected as active at + all: emulated 60 Hz scroll presenting at 30-40 Hz missed a 0.75× + threshold). 0.4×rate catches a scroll running at a quarter of refresh; + idle (0-2 presents/s) stays far below it.""" 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 + hi, lo = 0.4*rate, 0.1*rate + BUCK = 250_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 + r = dens.get(b, 0) * 4 # per-second rate (BUCK = 250 ms) if r > hi and start is None: start = b elif r < lo and start is not None: @@ -134,7 +148,10 @@ def explicit_windows(pres, t0, spec): out.append((name or f"w{len(out)}", idx0, idx1)) return out -def evaluate(pres, P, grid, windows): +def evaluate(pres, P, grid, windows, suspect=False): + """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.""" t0 = pres[0][1] any_fail = False total = 0 @@ -171,7 +188,9 @@ def evaluate(pres, P, grid, windows): 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 + ok = (lates == 0 and stalls == 0 and spread <= 0.5) + if not suspect: + ok = ok and drops == 0 and doubles == 0 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] -> " @@ -190,6 +209,7 @@ def evaluate(pres, P, grid, windows): + ("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 @@ -241,7 +261,7 @@ def selftest(): import io, contextlib buf = io.StringIO() with contextlib.redirect_stdout(buf): - res = run_file(path, period_ms=None, windows_spec="") + res, _sus = 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) @@ -263,7 +283,7 @@ 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 + print("no usable PRES data"); return False, False monots = [m for _, m in pres] src, P = None, None if ftns: @@ -276,12 +296,15 @@ def run_file(path, period_ms, windows_spec): grid = ("edge", ftns[0]) if (src == "vsync-edges" or (period_ms and ftns)) else \ ("anchor", anchor_phase(monots, P)) t0 = monots[0] + suspect = (grid[0] == "anchor") 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'})") + f"grid={'vsync-edge' if grid[0]=='edge' else 'anchor-fallback'}" + + (" *** SUSPECT: fitted grid — only stalls are meaningful here " + "(drop/double need the hardware edge grid)" if suspect else "")) 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) + print("no active windows found"); return False, suspect + return evaluate(pres, P, grid, wins, suspect=suspect), suspect def main(): ap = argparse.ArgumentParser() @@ -295,8 +318,10 @@ def main(): 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) + ok, suspect = run_file(args.file, args.period_ms, args.windows) + if not ok: + sys.exit(1) + sys.exit(3 if suspect else 0) # 3 = PASS-but-SUSPECT (fitted grid) if __name__ == "__main__": main()