#!/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+)")), ("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+)")), ("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]}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": 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, log_path=None): # Default log path is sltest's; the gallery mirrors its STG lines to a # different file (nblog perf-mirror, `perf` feature) — pass --log-path. if log_path is None: log_path = f"/sdcard/Android/data/{app}/files/it.log" 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) adb_shell(f"rm -f {log_path}") 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 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?)") # 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) screen_awake(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", log_path, 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 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 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") ap.add_argument("--log-path", default=None, help="device path of the STG log (gallery: /sdcard/Download/.gallery_perf.log)") 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, args.log_path)) else: if not args.log: ap.print_usage(); sys.exit(2) sys.exit(report(args.log, tag=args.tag)) if __name__ == "__main__": main()