gallery/tools/jank_capture.py

#!/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()