Diagnostics: guest-thread stall reporting, SPU reservation counters, autotest harness

Hangs where the RSX idles were only ever visible from the RSX side, so a stall
report now names every guest thread, its state, PC and function, and for SPUs adds
the reservation counters -- conditional store calls, failures, notifications, and
the SPURS heuristic's deliberate non-notifications -- plus where the host thread
last was in cpu_task. block_counter alone cannot separate a thread livelocked
retrying PUTLLC from one that is genuinely idle; both report zero blocks a second.

The SPU code window prints once per process. Unguarded it re-emitted a whole
function on every stall dump, measured at 538 lines a second over 31 dumps with a
690 MiB log left behind, which on Android is itself a stall -- it was degrading the
hang it was meant to describe, and it buried the state lines that answered the
question.

do_local_task counters cover the case the profiler cannot: it reports the thread is
in Local task and has been for 0.00s, which together mean it is not stuck there at
all and the FIFO loop is calling it repeatedly. Which FIFO state, and whether guest
GET equals PUT, separates a starved RSX from a stuck one.

tools/ps3autotests drives ps3autotests on a device over adb and diffs per
instruction against real-hardware output; compare-platforms.py does the three-way
ARM/x86/hardware split that separates shared upstream failures from ARM-only ones.
This is what found the CFLTS and FMS divergences.
This commit is contained in:
jpolo1224
2026-08-17 20:50:56 -04:00
parent 8caacc8231
commit 55a35b5e1d
7 changed files with 806 additions and 4 deletions
+106
View File
@@ -0,0 +1,106 @@
#!/usr/bin/env python3
"""Reduce an RPCS3/ARMSX3 log to a per-thread syscall trace, for diffing one platform against
another.
Why per-thread and not the raw log: the interleaving between threads differs on every boot and on
every machine, so a global diff is all noise. What each thread DID, in order, is stable -- so this
emits one sequence per guest thread and drops everything that legitimately varies (timestamps,
addresses, argument values, pointer widths). Diff the output of two runs and the first divergence
in a thread's sequence is the call that behaved differently.
Both emulators write the same log format, so the same normalisation applies to a desktop RPCS3.log
and an Android RPCSX.log with no flags to remember.
Usage:
normalise-log.py RPCSX.log > arm.trace
normalise-log.py RPCS3.log --tail 90 > x86.trace # last 90s only
diff -u x86.trace arm.trace | head -40
# then, to see it per thread:
normalise-log.py RPCSX.log --thread PhysWISESpursHdlr0
"""
import argparse
import re
import sys
from collections import OrderedDict
# ·W 0:00:58.030816 {PPU[0x1000000] Thread (main_thread) [liblv2: 0x01b309ac]} sys_fs: sys_fs_stat(path=...)
LINE = re.compile(
r"^.?(?P<lvl>[A-Z!]?)\s*(?P<t>\d+:\d\d:\d\d\.\d+)\s+\{(?P<ctx>[^}]*)\}\s*(?P<body>.*)$"
)
# Thread identity: the name in parentheses if present, else the raw context minus its address.
TNAME = re.compile(r"Thread \(([^)]*)\)|^(RSX|SPU|PPU)")
CALL = re.compile(r"(?:^|\s)(?P<name>_?sys[a-zA-Z0-9_]*|cell[A-Za-z0-9_]+|sceNp[A-Za-z0-9_]+)\s*\(")
def seconds(stamp):
h, m, s = stamp.split(":")
return int(h) * 3600 + int(m) * 60 + float(s)
def thread_of(ctx):
m = re.search(r"Thread \(([^)]*)\)", ctx)
if m:
# PPU[0x1000000] Thread (main_thread) -> "PPU main_thread". The id is per-run, the name is not.
kind = ctx.split("[", 1)[0].strip() or "PPU"
return f"{kind} {m.group(1)}"
# SPU[0x1000100] 'Name' / RSX [0x...] -- keep the kind and any quoted name.
q = re.search(r"'([^']*)'", ctx)
kind = ctx.split("[", 1)[0].strip()
return f"{kind} {q.group(1)}" if q else kind
def main():
ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
ap.add_argument("log")
ap.add_argument("--tail", type=float, default=None,
help="only the last N seconds of emulated time (the window around a hang)")
ap.add_argument("--thread", default=None, help="restrict to threads whose name contains this")
ap.add_argument("--keep-repeats", action="store_true",
help="do not collapse a call repeated back-to-back (default collapses, with a count)")
args = ap.parse_args()
per_thread = OrderedDict()
last_time = 0.0
rows = []
with open(args.log, "r", encoding="utf-8", errors="replace") as fh:
for line in fh:
m = LINE.match(line)
if not m:
continue
call = CALL.search(m.group("body"))
if not call:
continue
t = seconds(m.group("t"))
last_time = max(last_time, t)
rows.append((t, thread_of(m.group("ctx")), call.group("name")))
cutoff = (last_time - args.tail) if args.tail else -1.0
for t, thread, name in rows:
if t < cutoff:
continue
if args.thread and args.thread not in thread:
continue
seq = per_thread.setdefault(thread, [])
if not args.keep_repeats and seq and seq[-1][0] == name:
seq[-1][1] += 1
else:
seq.append([name, 1])
if not per_thread:
sys.exit("no syscalls matched -- wrong log, or --tail/--thread too narrow")
print(f"# {args.log}: {len(rows)} calls, {len(per_thread)} threads"
+ (f", last {args.tail}s of {last_time:.1f}s" if args.tail else f", {last_time:.1f}s"))
for thread, seq in sorted(per_thread.items()):
print(f"\n=== {thread} ({sum(n for _, n in seq)} calls) ===")
for name, n in seq:
print(f"{name}{f' x{n}' if n > 1 else ''}")
if __name__ == "__main__":
main()
+160
View File
@@ -0,0 +1,160 @@
#!/usr/bin/env python3
"""Diff two platforms' ps3autotests output per instruction: which opcodes differ on ARM vs x86.
This is the deliverable the tests exist for, and it is NOT the same as diffing either platform
against the .expected file. A diff against hardware answers "is this emulator perfect", which no
emulator is -- RPCS3 does not implement every status bit, and some tests print through paths whose
ABI makes them fragile. A diff of ARM against x86 answers the question that actually matters here:
which instructions behave DIFFERENTLY on the two backends. Only those can explain a game that
works on one and not the other.
Three columns per instruction, because the distinction decides who owns the bug:
arm!=x86 the ARM backend diverges. Ours to fix.
both!=hw both backends differ from hardware the same way. Upstream, or a test artifact.
arm!=hw total, for context.
Usage:
compare-platforms.py cpu/spu_fpu --arm results/cpu_spu_fpu.actual --x86 x86/spu_fpu.txt
compare-platforms.py --arm-dir results/ --x86-dir x86/ # every test found in both
"""
import argparse
import glob
import os
import sys
from collections import Counter
REPO_DEFAULT = os.path.join(
os.path.dirname(os.path.abspath(__file__)), "..", "..", "..", "ps3autotests"
)
def load(path):
with open(path, "r", encoding="utf-8", errors="replace") as fh:
return [ln.rstrip() for ln in fh.read().replace("\r\n", "\n").split("\n") if ln.strip()]
def mnemonic(line):
head = line.split("(", 1)[0].strip() if "(" in line else ""
parts = head.split()
return parts[0] if parts else "<other>"
def expected_for(test, repo):
hits = glob.glob(os.path.join(repo, "tests", test, "*.expected"))
return load(hits[0]) if hits else None
def report(test, arm, x86, hw, args):
n = min(len(arm), len(x86))
if not n:
print(f"{test}: nothing to compare (arm={len(arm)} x86={len(x86)} lines)")
return None
if len(arm) != len(x86):
print(f" NOTE: line counts differ (arm={len(arm)} x86={len(x86)}); comparing the first {n}")
arm_vs_x86 = Counter()
both_vs_hw = Counter()
arm_vs_hw = Counter()
total = Counter()
examples = {}
for i in range(n):
a, b = arm[i], x86[i]
h = hw[i] if hw and i < len(hw) else None
m = mnemonic(b) if "(" in b else mnemonic(a)
total[m] += 1
if a != b:
arm_vs_x86[m] += 1
examples.setdefault(m, (i + 1, b, a, h))
if h is not None:
if a != h:
arm_vs_hw[m] += 1
if a == b and a != h:
both_vs_hw[m] += 1
ours = sum(arm_vs_x86.values())
print(f"\n=== {test} ===")
print(f" {n} lines compared, {ours} differ between ARM and x86")
if not ours:
print(" ARM matches x86 exactly." + ("" if not hw else
f" ({sum(both_vs_hw.values())} lines where BOTH differ from hardware -- upstream, not ours)"))
return 0
print(f" {'instruction':<12}{'arm!=x86':>10}{'both!=hw':>10}{'arm!=hw':>9}{'of':>8}")
for m, c in arm_vs_x86.most_common(args.summary):
print(f" {m:<12}{c:>10}{both_vs_hw[m]:>10}{arm_vs_hw[m]:>9}{total[m]:>8}")
print("\n first ARM-vs-x86 differences:")
for m, _c in arm_vs_x86.most_common(args.examples):
ln, b, a, h = examples[m]
print(f" {m} line {ln}")
print(f" x86 : {b}")
print(f" arm : {a}")
if h is not None:
print(f" hardware: {h}")
return ours
def main():
ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
ap.add_argument("tests", nargs="*", help="test path(s) like cpu/spu_fpu, for the .expected lookup")
ap.add_argument("--arm", help="ARM output file")
ap.add_argument("--x86", help="x86 output file")
ap.add_argument("--arm-dir", help="directory of ARM .actual files")
ap.add_argument("--x86-dir", help="directory of x86 output files")
ap.add_argument("--repo", default=REPO_DEFAULT, help="ps3autotests checkout, for .expected")
ap.add_argument("--summary", type=int, default=30)
ap.add_argument("--examples", type=int, default=4)
args = ap.parse_args()
pairs = []
if args.arm and args.x86:
test = args.tests[0] if args.tests else os.path.basename(args.arm).split(".")[0]
pairs.append((test, args.arm, args.x86))
elif args.arm_dir and args.x86_dir:
# Match on the test's basename, so cpu_spu_fpu.actual pairs with spu_fpu.txt or
# cpu_spu_fpu.actual -- whatever the desktop side happened to call it.
#
# Only .actual on our side, and never .diff on either: the runner writes <test>.diff
# beside <test>.actual, and a bare glob pairs each test with its own diff as though that
# were a second platform. That produced two entries per test and a verdict of "80292
# differing lines" from a run that had none.
def usable(path):
return not os.path.isdir(path) and not path.endswith(".diff")
arm_files = [a for a in sorted(glob.glob(os.path.join(args.arm_dir, "*.actual")))] or \
[a for a in sorted(glob.glob(os.path.join(args.arm_dir, "*"))) if usable(a)]
for a in arm_files:
key = os.path.basename(a).split(".")[0].replace("cpu_", "").replace("lv2_", "")
hits = [b for b in sorted(glob.glob(os.path.join(args.x86_dir, "*")))
if key in os.path.basename(b) and usable(b)]
if hits:
pairs.append((key, a, hits[0]))
if not pairs:
sys.exit("no matching filenames between --arm-dir and --x86-dir")
else:
sys.exit("give --arm and --x86, or --arm-dir and --x86-dir")
worst = 0
for test, apath, bpath in pairs:
lookup = test if "/" in test else next(
(t for t in ("cpu/" + test, "lv2/" + test, "rsx/" + test)
if glob.glob(os.path.join(args.repo, "tests", t, "*.expected"))), None)
hw = expected_for(lookup, args.repo) if lookup else None
d = report(test, load(apath), load(bpath), hw, args)
worst = max(worst, d or 0)
print("\n=== verdict ===")
print(" ARM matches x86 on every compared line." if worst == 0 else
f" {worst} differing lines on the worst test -- those instructions are the ARM-specific ones.")
sys.exit(0 if worst == 0 else 1)
if __name__ == "__main__":
main()
+259
View File
@@ -0,0 +1,259 @@
#!/usr/bin/env python3
"""Run RPCS3/ps3autotests against ARMSX3 on a connected device and diff the output.
Each test in that repository is a PS3 program plus a .expected file holding the TTY output a
real PS3 produced. So a test is: boot the ELF, capture what it printed, compare. A difference
names an instruction and the exact operands that behave differently here than on hardware,
which is the part that guesswork cannot supply -- see --summary, which groups differences by
mnemonic and turns 80k lines of hex into "fma: 1847 wrong, everything else: clean".
Usage:
run-tests.py --list
run-tests.py cpu/spu_fpu
run-tests.py cpu/spu_fpu cpu/spu_alu --out results/
run-tests.py --all-spu
Notes:
- The app is force-stopped between tests, and each test is booted through the VIEW intent the
manifest already accepts. That means this DRIVES the device: do not run it while someone is
using the app for something else.
- TTY.log cannot be truncated from adb (it lives under Android/data, which shell may read but
not write). The harness notes its size first, then watches: the app resets the log when it
boots, so a size DROP means the whole file belongs to this test. Assuming the pre-launch size
was a prefix silently produced a 29k-of-108k-line capture that read as a huge test failure.
- A test is considered finished when TTY.log stops growing for --idle seconds. There is no
completion marker in the protocol, and some tests print for a long time.
"""
import argparse
import os
import subprocess
import sys
import time
from collections import Counter
PKG = "com.armsx3"
ACTIVITY = f"{PKG}/com.armsx2.Main"
TTY = f"/sdcard/Android/data/{PKG}/files/cache/TTY.log"
DEVICE_DIR = "/sdcard/ARMSX3-autotests"
REPO_DEFAULT = os.path.join(
os.path.dirname(os.path.abspath(__file__)), "..", "..", "..", "ps3autotests"
)
def adb(*args, binary=False, check=True):
"""Run adb and return stdout. exec-out is used for file reads so nothing mangles bytes."""
proc = subprocess.run(
["adb", *args], capture_output=True, check=False
)
if check and proc.returncode != 0:
sys.exit(f"adb {' '.join(args)} failed: {proc.stderr.decode(errors='replace').strip()}")
return proc.stdout if binary else proc.stdout.decode(errors="replace")
def tty_size():
out = adb("exec-out", f"wc -c < {TTY} 2>/dev/null || echo 0").strip()
return int(out.split()[0]) if out.split() else 0
def discover(tests_root):
"""Every test directory holding both an .expected and a bootable ELF."""
found = []
for dirpath, _dirnames, filenames in os.walk(tests_root):
expected = [f for f in filenames if f.endswith(".expected")]
if not expected:
continue
# A .ppu.elf is the loader even for SPU tests: it uploads the .spu.elf and prints what
# comes back, so booting the SPU ELF directly would skip the half that reports results.
elf = next((f for f in filenames if f.endswith(".ppu.elf")), None)
elf = elf or next((f for f in filenames if f.endswith(".elf")), None)
if not elf:
continue
found.append(
(os.path.relpath(dirpath, tests_root), dirpath, elf, os.path.join(dirpath, expected[0]))
)
return sorted(found)
def normalise(text):
"""Line endings and trailing blanks only. Nothing else -- the point is to compare hex."""
return [ln.rstrip() for ln in text.replace("\r\n", "\n").replace("\r", "\n").split("\n") if ln.strip()]
def mnemonic(line):
"""Leading token of a test line, e.g. 'fma' from 'fma ([00],[01],[02]) -> ...'.
Not every test prints instruction-shaped lines: the lv2 suites print prose, and a line may
open with '(' or have nothing before it at all, which crashed this on an empty split.
"""
head = line.split("(", 1)[0].strip() if "(" in line else ""
parts = head.split()
return parts[0] if parts else "<other>"
def run_one(name, dirpath, elf, expected_path, args):
print(f"\n=== {name} ===", flush=True)
remote_dir = f"{DEVICE_DIR}/{os.path.basename(dirpath)}"
adb("shell", f"mkdir -p {remote_dir}")
# Whole directory: SPU tests load a sibling .spu.elf by relative path.
for f in sorted(os.listdir(dirpath)):
full = os.path.join(dirpath, f)
if os.path.isfile(full) and not f.endswith(".expected"):
adb("push", "-q", full, f"{remote_dir}/{f}")
adb("shell", f"am force-stop {PKG}", check=False)
time.sleep(1.5)
before = tty_size()
adb(
"shell",
f"am start -a android.intent.action.VIEW -d file://{remote_dir}/{elf} -n {ACTIVITY}",
check=False,
)
# Grown-then-quiet, because there is no end-of-test marker to wait for.
#
# The offset is decided by watching, not assumed: the app TRUNCATES TTY.log when it boots, so
# a previous test's output is not a prefix of this one's. Slicing at the pre-launch size then
# reads from the middle of a fresh file -- which produced a torn first line and 29k of 108k
# lines, silently, and looked like a spectacular test failure rather than a harness bug. If the
# size is ever seen below where it started, the log was reset and the whole file is ours.
start = time.time()
last_size, last_change = before, time.time()
offset = before
while True:
time.sleep(2)
size = tty_size()
if size < offset:
offset = 0
if size != last_size:
last_size, last_change = size, time.time()
print(f" ... {size - offset} bytes", end="\r", flush=True)
elapsed_quiet = time.time() - last_change
if size > offset and elapsed_quiet >= args.idle:
break
if time.time() - start > args.timeout:
print(f" timed out after {args.timeout}s", flush=True)
break
if size == offset and time.time() - start > args.boot_wait:
print(f" no output after {args.boot_wait}s -- did it boot?", flush=True)
break
raw = adb("exec-out", f"cat {TTY}", binary=True)
adb("shell", f"am force-stop {PKG}", check=False)
got = normalise(raw[offset:].decode("utf-8", errors="replace"))
# Two output conventions, and only one of them is TTY.
#
# The SPU suites reach TTY through spu_printf and the lv2 ones print to it directly, but the
# PPU suites fopen "/app_home/output.txt" and write there -- /app_home being the directory the
# test was launched from, i.e. the one pushed above. Six PPU tests were reported as "NO OUTPUT"
# for a whole run while their results sat on the device, so check the file whenever TTY is
# empty rather than assuming a silent test failed to boot.
if not got:
from_file = adb("exec-out", f"cat {remote_dir}/output.txt 2>/dev/null", binary=True)
if from_file:
print(f" (output.txt, {len(from_file)} bytes -- this suite writes a file, not TTY)")
got = normalise(from_file.decode("utf-8", errors="replace"))
with open(expected_path, "r", encoding="utf-8", errors="replace") as fh:
want = normalise(fh.read())
os.makedirs(args.out, exist_ok=True)
stem = name.replace("/", "_")
with open(os.path.join(args.out, f"{stem}.actual"), "w", encoding="utf-8") as fh:
fh.write("\n".join(got) + "\n")
return compare(name, got, want, args, stem)
def compare(name, got, want, args, stem):
if not got:
print(" NO OUTPUT -- test did not run (or printed nothing)")
return False
# Positional compare: these tests are deterministic and ordered, so line N vs line N is
# meaningful and far more useful than a fuzzy diff -- it keeps the operands aligned.
diffs = []
for i in range(min(len(got), len(want))):
if got[i] != want[i]:
diffs.append((i + 1, want[i], got[i]))
missing = len(want) - len(got)
print(f" lines: {len(got)} captured / {len(want)} expected"
+ (f" ({missing:+d})" if missing else ""))
if not diffs and not missing:
print(" PASS")
return True
print(f" FAIL: {len(diffs)} differing lines")
by_mnem = Counter(mnemonic(w) for _, w, _ in diffs)
total = Counter(mnemonic(w) for w in want)
print(" by instruction:")
for mn, count in by_mnem.most_common(args.summary):
print(f" {mn:<10} {count:>7} wrong of {total[mn]:>7}")
with open(os.path.join(args.out, f"{stem}.diff"), "w", encoding="utf-8") as fh:
for ln, w, g in diffs:
fh.write(f"line {ln}\n expected: {w}\n actual : {g}\n")
print(f" first differences:")
for ln, w, g in diffs[:5]:
print(f" line {ln}\n expected: {w}\n actual : {g}")
print(f" full diff: {os.path.join(args.out, f'{stem}.diff')}")
return False
def main():
ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
ap.add_argument("tests", nargs="*", help="test paths relative to tests/, e.g. cpu/spu_fpu")
ap.add_argument("--repo", default=REPO_DEFAULT, help="ps3autotests checkout")
ap.add_argument("--out", default="autotest-results", help="where to write .actual/.diff")
ap.add_argument("--list", action="store_true", help="list runnable tests and exit")
ap.add_argument("--all-spu", action="store_true", help="every cpu/spu_* test")
ap.add_argument("--idle", type=float, default=8.0, help="seconds of TTY silence = finished")
ap.add_argument("--boot-wait", type=float, default=90.0, help="seconds to wait for first output")
ap.add_argument("--timeout", type=float, default=900.0, help="hard cap per test")
ap.add_argument("--summary", type=int, default=25, help="instructions to show in the summary")
args = ap.parse_args()
tests_root = os.path.join(os.path.abspath(args.repo), "tests")
if not os.path.isdir(tests_root):
sys.exit(f"no tests/ under {args.repo} -- clone https://github.com/RPCS3/ps3autotests")
available = discover(tests_root)
if args.list:
for name, _d, elf, exp in available:
print(f"{name:<40} {elf:<28} expected={os.path.getsize(exp) // 1024}K")
return
if args.all_spu:
wanted = [t for t in available if os.path.basename(t[0]).startswith("spu_")]
elif args.tests:
wanted = [t for t in available if t[0] in args.tests]
unknown = set(args.tests) - {t[0] for t in wanted}
if unknown:
sys.exit(f"unknown test(s): {', '.join(sorted(unknown))} (try --list)")
else:
sys.exit("name at least one test, or --all-spu, or --list")
if not adb("devices").strip().splitlines()[1:]:
sys.exit("no device connected")
results = {}
for name, dirpath, elf, expected in wanted:
results[name] = run_one(name, dirpath, elf, expected, args)
print("\n=== summary ===")
for name, ok in results.items():
print(f" {'PASS' if ok else 'FAIL'} {name}")
sys.exit(0 if all(results.values()) else 1)
if __name__ == "__main__":
main()