diff --git a/.claude/skills/android-perf/SKILL.md b/.claude/skills/android-perf/SKILL.md new file mode 100644 index 0000000..4d82eaf --- /dev/null +++ b/.claude/skills/android-perf/SKILL.md @@ -0,0 +1,61 @@ +--- +name: android-perf +description: Perfetto performance runs of the Android Vulkan renderer on a physical phone. Use to record a baseline, analyze a trace, or compare runs before and after a renderer change. +--- + +# Android performance with Perfetto + +A **run** is one release build of the dev app doing its benchmark turn under Perfetto: [scripts/android_perf.py](../../../scripts/android_perf.py) records it and [scripts/perfetto_analysis.py](../../../scripts/perfetto_analysis.py) reads the trace. +Both scripts' `--help` carry the flags. + +## Steps + +1. **Set up once.** Create the analysis venv if `build/perf-venv` is missing: + `python3 -m venv build/perf-venv && build/perf-venv/bin/pip install -r scripts/requirements-perf.txt`. + Done when `build/perf-venv/bin/python -c "import perfetto"` exits 0. +2. **Check the phone.** `adb devices -l` lists exactly one device (else pass `--serial`), the screen is unlocked and awake, and nothing else holds the GPU (Snapdragon Profiler capture, other apps). +3. **Record.** `python3 scripts/android_perf.py --seconds 30` with the same `--quality` and `--pose` for every run you will compare. + Done when it prints `status passed`, `app slices in trace: True` and an analysis block. + For a comparison, record at least two runs per side; the run-to-run spread is the noise floor. +4. **Read** each run directory: `report.json` (app timings from GPU timestamp queries), `analysis.json` (the trace), `trace.perfetto-trace` (open at https://ui.perfetto.dev for anything the numbers leave open). + Done when every figure in your report traces back to one of those files. +5. **Report** the device, Android version, commit and dirty flag from `report.json` `run`, every skipped step, and each conclusion with the figures behind it. + A difference counts only when it exceeds the spread between runs of the same side. + +## Reading a run + +The benchmark window is the `SplatKit benchmark` async slice: one full turn at a fixed pose with the gyroscope off and vsync requested off. +The frame budget is the display interval: 16.7 ms at 60 Hz. + +`report.json`, from the app's GPU timestamp queries: + +- **fps, frame p95** (`runs`): host-loop intervals over the turn, the headline numbers. +- **gpu ms** (`gpu_mean_ms`): GPU time per frame. + Above the budget means GPU-bound. +- **sort, cull ms** (`stage_sample_mean_ms`): periodic GPU samples of the radix sort and visibility passes. + +`analysis.json`, from the trace: + +- **`SplatKit submit and present`** (`render_thread_slices`): CPU blocked in `vkQueueSubmit` and `vkQueuePresentKHR`. + Long, with the render thread mostly `S`, means it waits on the GPU or the display. +- **`SplatKit wait for frame slot`**: the fence wait for a free frame in flight. + Long means the GPU is behind the CPU. +- **`SplatKit encode compute`**: CPU cost of recording the cull and sort dispatches. + The rest of `SplatKit frame` outside its three stages is draw recording and engine work. +- **`pacing`**: intervals between submits. + Intervals alternating between one and two display periods, with many hitches, mean frames miss vsync because GPU time is near or over the budget. +- **`render_thread`**: high `Running` means CPU-bound, and high `R` or `R+` means it waits for a core. + Running mostly on the slowest cluster means the scheduler parked it on little cores. +- **`cpu_clusters`**: a mean clock far below max on the render thread's cluster means throttling. + So does gpu ms rising across the 30-second windows in `logcat.txt`. + A throttled run measures heat: cool the phone and rerun. +- **`memory`**: process RSS. + GPU memory is not in the trace on Android 11. +- **`load_ms`**: world decode, collider decode and GPU upload of the last load. + +## Limits + +- Perfetto sees CPU time, scheduling, clocks and memory; GPU time comes only from the app's timestamp queries. + Per-draw GPU counters (fragments shaded, overdraw, ALU, bandwidth) come from a Snapdragon Profiler Snapshot of a debug build, which is valid for counts and never for milliseconds. +- `--pose` keeps the position; the turn resets yaw and pitch. +- A run without `app slices in trace: True` lost the app's trace sections: the installed APK must be the profileable release build the script makes. diff --git a/.gitignore b/.gitignore index d318c67..27ca0db 100644 --- a/.gitignore +++ b/.gitignore @@ -6,7 +6,8 @@ DerivedData/ *.glb .DS_Store .argent/ -.claude/ +.claude/* +!.claude/skills/ .idea/ .gradle/ local.properties diff --git a/apps/android-dev/app/src/main/AndroidManifest.xml b/apps/android-dev/app/src/main/AndroidManifest.xml index d2b7f96..fa55e40 100644 --- a/apps/android-dev/app/src/main/AndroidManifest.xml +++ b/apps/android-dev/app/src/main/AndroidManifest.xml @@ -6,6 +6,8 @@ android:allowBackup="false" android:appCategory="game" android:theme="@android:style/Theme.Material.NoActionBar.Fullscreen"> + + HITCH_FACTOR * median) + return summary + + +class Trace: + def __init__(self, path, pid=None): + from perfetto.trace_processor import TraceProcessor + self.tp = TraceProcessor(trace=str(path)) + # An app launched after recording starts can stay named : Perfetto read + # its /proc entry between the zygote fork and the rename, so the pid is the reliable match. + self.process = f"p.pid = {int(pid)}" if pid else f"p.name = '{PACKAGE}'" + + def rows(self, sql): + return [row.__dict__ for row in self.tp.query(sql)] + + def thread_slices(self, thread, name, window=None): + clause = f"and s.ts >= {window[0]} and s.ts + s.dur <= {window[1]}" if window else "" + return self.rows(f""" + select s.ts, s.dur from slice s + join thread_track tt on s.track_id = tt.id join thread t using (utid) + join process p using (upid) + where t.name = '{thread}' and {self.process} and s.name = '{name}' {clause} + order by s.ts""") + + def benchmark_window(self): + """The async slice the app keeps open over a benchmark turn, if the trace saw it end.""" + rows = self.rows(f""" + select s.ts, s.dur from slice s join process_track pt on s.track_id = pt.id + join process p using (upid) + where {self.process} and s.name = '{BENCHMARK}' and s.dur > 0 + order by s.ts desc limit 1""") + return (rows[0]["ts"], rows[0]["ts"] + rows[0]["dur"]) if rows else None + + def steady_window(self): + """Without a benchmark slice: from the end of the world upload to the last frame.""" + upload = self.thread_slices(RENDER_THREAD, UPLOAD_WORLD) + frames = self.thread_slices(RENDER_THREAD, FRAME) + if not upload or not frames: + return None + start = upload[-1]["ts"] + upload[-1]["dur"] + end = frames[-1]["ts"] + frames[-1]["dur"] + return (start, end) if end > start else None + + def thread_states(self, window): + return self.rows(f""" + select ts.state, ts.cpu, sum(min(ts.ts + ts.dur, {window[1]}) - max(ts.ts, {window[0]})) dur + from thread_state ts join thread t using (utid) join process p using (upid) + where t.name = '{RENDER_THREAD}' and {self.process} + and ts.ts < {window[1]} and ts.ts + ts.dur > {window[0]} + group by ts.state, ts.cpu""") + + def cpu_max_khz(self): + return {r["cpu"]: r["khz"] for r in self.rows(f""" + select cct.cpu, max(c.value) khz from counter c + join cpu_counter_track cct on c.track_id = cct.id + where cct.name = '{CPU_FREQUENCY_TRACK}' group by cct.cpu""")} + + def cpu_mean_khz(self, window): + """Time-weighted mean frequency per CPU over the window.""" + return {r["cpu"]: r["khz"] for r in self.rows(f""" + with f as ( + select cct.cpu, c.value, c.ts, + lead(c.ts, 1, {window[1]}) over (partition by cct.cpu order by c.ts) next_ts + from counter c join cpu_counter_track cct on c.track_id = cct.id + where cct.name = '{CPU_FREQUENCY_TRACK}') + select cpu, sum(value * (min(next_ts, {window[1]}) - max(ts, {window[0]}))) + / sum(min(next_ts, {window[1]}) - max(ts, {window[0]})) khz + from f where next_ts > {window[0]} and ts < {window[1]} group by cpu""")} + + def process_memory(self, window, counter): + rows = self.rows(f""" + select max(c.value) peak, avg(c.value) mean from counter c + join process_counter_track pct on c.track_id = pct.id join process p using (upid) + where {self.process} and pct.name = '{counter}' + and c.ts between {window[0]} and {window[1]}""") + if not rows or rows[0]["peak"] is None: + return None + return {"peak_mib": rows[0]["peak"] / BYTES_PER_MIB, "mean_mib": rows[0]["mean"] / BYTES_PER_MIB} + + +def render_thread_breakdown(states, clusters, window): + """Share of the window the render thread spends running per cluster, runnable or blocked.""" + span = window[1] - window[0] + cluster_of = {cpu: index for index, c in enumerate(clusters) for cpu in c["cpus"]} + running = [0] * len(clusters) + other = {} + for row in states: + if row["state"] == RUNNING and row["cpu"] in cluster_of: + running[cluster_of[row["cpu"]]] += row["dur"] + else: + other[row["state"]] = other.get(row["state"], 0) + row["dur"] + return { + "running_pct_by_cluster": [{"cpus": c["cpus"], "pct": PERCENT * r / span} for c, r in zip(clusters, running)], + "running_pct": PERCENT * sum(running) / span, + # R and R+ wait for a CPU; S sleeps (fence or present waits); D is blocked in the kernel. + "state_pct": {state: PERCENT * dur / span for state, dur in sorted(other.items())}, + } + + +def analyze(path, pid=None): + trace = Trace(path, pid) + window = trace.benchmark_window() + window_source = WINDOW_BENCHMARK if window else WINDOW_AFTER_UPLOAD + window = window or trace.steady_window() + if window is None: + return {"status": STATUS_NO_WINDOW, + "hint": f"no '{UPLOAD_WORLD}' then '{FRAME}' slices from {PACKAGE}; " + "is the app profileable, and is --pid right?"} + window_s = (window[1] - window[0]) / NS_PER_S + submits = trace.thread_slices(RENDER_THREAD, SUBMIT_PRESENT, window) + stages = {name: distribution_ms([s["dur"] for s in trace.thread_slices(RENDER_THREAD, name, window)]) + for name in (FRAME,) + FRAME_STAGES} + clusters = clusters_by_max_frequency(trace.cpu_max_khz()) + mean_khz = trace.cpu_mean_khz(window) + for cluster in clusters: + means = [mean_khz[cpu] for cpu in cluster["cpus"] if cpu in mean_khz] + cluster["mean_mhz"] = sum(means) / len(means) / KHZ_PER_MHZ if means else None + load = {} + for name in LOAD_SLICES: + thread = RENDER_THREAD if name == UPLOAD_WORLD else LOADER_THREAD + slices = trace.thread_slices(thread, name) + load[name] = slices[-1]["dur"] / NS_PER_MS if slices else None + return { + "status": STATUS_OK, + "window": window_source, + "window_s": window_s, + "submitted_frames": len(submits), + "submit_fps": len(submits) / window_s, + "render_thread_slices": stages, + "pacing": pacing([s["ts"] for s in submits]), + "render_thread": render_thread_breakdown(trace.thread_states(window), clusters, window), + "cpu_clusters": clusters, + "memory": {name: trace.process_memory(window, name) for name in RSS_COUNTERS}, + "load_ms": load, + "unavailable": "GPU frequency, GPU memory and thermal counters are not in the trace on kernels " + "without power/gpu_frequency, gpu_mem and thermal events; GPU timings come from " + "the app's timestamp queries in report.json", + } + + +def describe(result): + """Short text summary for a terminal.""" + if result["status"] != STATUS_OK: + return f"analysis: {result['status']}: {result.get('hint', '')}" + lines = [f"{result['window']} window {result['window_s']:.1f} s, {result['submitted_frames']} frames submitted " + f"({result['submit_fps']:.1f} fps)"] + for name, d in result["render_thread_slices"].items(): + if d["count"]: + lines.append(f" {name:<30} mean {d['mean_ms']:6.2f} ms p95 {d['p95_ms']:6.2f} max {d['max_ms']:6.2f}") + p = result["pacing"] + if p["count"]: + lines.append(f"pacing: interval p50 {p['p50_ms']:.1f} ms, p95 {p['p95_ms']:.1f}, max {p['max_ms']:.1f}, " + f"{p['hitches']} hitches over {HITCH_FACTOR}x median") + rt = result["render_thread"] + placement = ", ".join(f"cpus {c['cpus'][0]}-{c['cpus'][-1]} {c['pct']:.0f}%" for c in rt["running_pct_by_cluster"]) + states = ", ".join(f"{s} {v:.0f}%" for s, v in rt["state_pct"].items()) + lines.append(f"{RENDER_THREAD}: running {rt['running_pct']:.0f}% ({placement}); {states}") + clocks = ", ".join(f"cpus {c['cpus'][0]}-{c['cpus'][-1]} {c['mean_mhz'] or 0:.0f}/{c['max_mhz']:.0f} MHz" + for c in result["cpu_clusters"]) + lines.append(f"clocks mean/max: {clocks}") + rss = result["memory"][RSS] + if rss: + lines.append(f"memory rss peak {rss['peak_mib']:.0f} MiB, mean {rss['mean_mib']:.0f} MiB") + lines.append("load: " + ", ".join(f"{k.removeprefix(SLICE_PREFIX)} {v:.0f} ms" + for k, v in result["load_ms"].items() if v is not None)) + return "\n".join(lines) + + +def main(): + parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("trace", type=Path) + parser.add_argument("--pid", type=int, help=f"the app's pid; defaults to matching {PACKAGE} by name") + parser.add_argument("--json", type=Path, help="also write the full result here") + args = parser.parse_args() + result = analyze(args.trace, args.pid) + if args.json: + args.json.write_text(json.dumps(result, indent=2, allow_nan=False)) + print(describe(result)) + return 0 if result["status"] == STATUS_OK else 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/requirements-perf.txt b/scripts/requirements-perf.txt new file mode 100644 index 0000000..54b5fee --- /dev/null +++ b/scripts/requirements-perf.txt @@ -0,0 +1 @@ +perfetto==0.57.2 diff --git a/scripts/tests/test_android_perf.py b/scripts/tests/test_android_perf.py new file mode 100644 index 0000000..b2f2973 --- /dev/null +++ b/scripts/tests/test_android_perf.py @@ -0,0 +1,71 @@ +import importlib.util +from pathlib import Path +import unittest + +SCRIPTS = Path(__file__).resolve().parents[1] + + +def load(name): + spec = importlib.util.spec_from_file_location(name, SCRIPTS / f"{name}.py") + module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(module) + return module + + +perf = load("android_perf") +analysis = load("perfetto_analysis") +MS = 1_000_000 + + +class RecordingTest(unittest.TestCase): + def test_config_traces_the_app_for_the_requested_time(self): + config = perf.perfetto_config(45) + self.assertIn(f'atrace_apps: "{perf.PACKAGE}"', config) + self.assertIn("duration_ms: 45000", config) + self.assertIn('ftrace_events: "sched/sched_switch"', config) + + def test_launch_runs_the_benchmark_without_the_hud(self): + args = perf.launch_args(20, "high", None) + self.assertEqual(args[args.index(perf.EXTRA_SECONDS) + 1], "20") + self.assertEqual(args[args.index(perf.EXTRA_HUD) + 1], "false") + self.assertNotIn(perf.EXTRA_POSE, args) + self.assertEqual(perf.launch_args(20, "low", "1,2,3,0,0")[-1], "1,2,3,0,0") + + +class AnalysisTest(unittest.TestCase): + def test_nearest_rank_percentile(self): + self.assertEqual(analysis.percentile([4, 1, 3, 2], 50), 2) + self.assertEqual(analysis.percentile([4, 1, 3, 2], 95), 4) + self.assertIsNone(analysis.percentile([], 50)) + + def test_distribution_reports_milliseconds(self): + result = analysis.distribution_ms([2 * MS, 4 * MS]) + self.assertEqual(result["count"], 2) + self.assertEqual(result["mean_ms"], 3) + self.assertEqual(result["max_ms"], 4) + self.assertEqual(analysis.distribution_ms([]), {"count": 0}) + + def test_clusters_group_cpus_by_maximum_frequency(self): + clusters = analysis.clusters_by_max_frequency( + {0: 1785600, 1: 1785600, 4: 2419200, 5: 2419200, 7: 2841600}) + self.assertEqual([c["cpus"] for c in clusters], [[0, 1], [4, 5], [7]]) + self.assertEqual(clusters[-1]["max_mhz"], 2841.6) + + def test_pacing_counts_intervals_past_the_hitch_factor(self): + starts = [0, 16 * MS, 32 * MS, 66 * MS, 82 * MS] + result = analysis.pacing(starts) + self.assertEqual(result["count"], 4) + self.assertEqual(result["hitches"], 1) + + def test_breakdown_splits_running_by_cluster_and_keeps_waits(self): + clusters = [{"cpus": [0, 1]}, {"cpus": [4]}] + states = [{"state": analysis.RUNNING, "cpu": 0, "dur": 10}, {"state": analysis.RUNNING, "cpu": 4, "dur": 30}, + {"state": "S", "cpu": None, "dur": 60}] + result = analysis.render_thread_breakdown(states, clusters, (0, 100)) + self.assertEqual([c["pct"] for c in result["running_pct_by_cluster"]], [10, 30]) + self.assertEqual(result["running_pct"], 40) + self.assertEqual(result["state_pct"], {"S": 60}) + + +if __name__ == "__main__": + unittest.main()