perf tooling: jank_capture.py (end-to-end capture+report) + stress-test fixes in jank_eval
jank_capture.py: one command owns the whole pipeline so provenance can
never be wrong (the failure mode this replaces: append-only logs spanning
processes, hand byte-offsets, tail-guessing, wrong-build data):
1. record build identity (versionName + apk sha256 + tag)
2. force-stop + DELETE it.log (file can then contain exactly ONE process)
3. cold launch, verify ResumedActivity (before and after)
4. scripted drags ('4,2,4' = 4s drag, 2s settle, 4s drag)
5. pull the complete log
6. report: PROVENANCE + jank_eval verdict + MISS forensics
verdicts: PASS(0) / FAIL(1) / SUSPECT(fitted grid) / INVALID(multi-process)
MISS forensics: groups consecutive misses into episodes, classifies each
(CHAIN-STALL / LOOP-STUCK / GUARD-REJECT / NO-WAKE-ITER) with a +-33 ms
all-thread context window (IT poll/ev/rd/dec/pc/rc/vsw/nvol, VSYNC
latency, PRES, FR, SLOWEV, DECODE, OTHR, INVK).
self-test: synthetic 120Hz log with a 30 ms stuck-poll episode.
jank_eval.py fixes found under emulator stress:
- auto-windows active threshold was circular: 0.75x the refresh rate
meant a JANKY app (low present rate) is never detected as active.
Now 0.4x rate / 250 ms buckets. (Emulated 60 Hz scroll at 30-40 Hz
present was invisible to the old threshold.)
- BUCK 500->250 ms required the density multiplier *2 -> *4 (forgot,
caught by stress: only the fastest spans were windowed).
- fallback period (no VSYNC lines) was a telescoping mean (spans idle
gaps: 391 presents over 23 s fit '59.6 ms'). Now median-of-deltas
snapped to standard rates. A fitted grid cannot prove drops/doubles:
verdict on it excludes them (stalls+lates+spread remain) and the
verdict is marked SUSPECT (exit 3) instead of PASS/FAIL.
- run_file now returns (ok, suspect); small-log early exit fixed.
Stress matrix on emulator (x86_64, 60 Hz SF) — all pass:
capture pipeline x3 (standard 4,2,4 / fast 1,1,1 / slow 6,2,6)
pause/resume mid-drag (teardown -> occluded -> resume burst)
determinism (identical report twice), multi-process -> INVALID,
explicit --windows, --period-ms override, no-VSYNC -> SUSPECT path,
small log -> exit 1, synthetic perfect 120 Hz -> PASS exit 0.
This commit is contained in:
parent
915e04c2c3
commit
a68c8996c6
351
tools/jank_capture.py
Normal file
351
tools/jank_capture.py
Normal file
|
|
@ -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()
|
||||
|
|
@ -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()
|
||||
|
|
|
|||
Loading…
Reference in New Issue
Block a user