From ca219d1b67a9bc130879aff43c90d293905429f3 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Mon, 12 Oct 2026 18:07:52 +0200 Subject: [PATCH] feat(tools): digest a performance trace for an issue or a pull request tools/trace_digest.py reads an APS5_TRACE_FRAMES capture (aps5-trace-*.json.gz) and prints a markdown report of a few KB, or the same data as JSON: the summary line from aps5-summary.jsonl, the slowest frames with their largest slices, the busy, wait and untraced time of each thread, the largest slices per frame, the longest waits, and with --stacks the hottest frames of an APS5_SAMPLE_WORKER collapsed-stack file. Python standard library only; a unittest checks every section on a small synthetic trace. Co-Authored-By: Claude Opus 5.5 --- CMakeLists.txt | 2 + tools/tests/test_trace_digest.py | 129 ++++++++++++++++++ tools/trace_digest.py | 222 +++++++++++++++++++++++++++++++ 3 files changed, 353 insertions(+) create mode 100644 tools/tests/test_trace_digest.py create mode 100644 tools/trace_digest.py diff --git a/CMakeLists.txt b/CMakeLists.txt index c0b526313..158daf490 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -97,6 +97,8 @@ if(BUILD_TESTING) add_test(NAME pad_input COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tools/tests/test_pad_input.py) set_tests_properties(pad_input PROPERTIES TIMEOUT 20) + add_test(NAME trace_digest COMMAND ${Python3_EXECUTABLE} + ${CMAKE_CURRENT_SOURCE_DIR}/tools/tests/test_trace_digest.py) endif() endif() diff --git a/tools/tests/test_trace_digest.py b/tools/tests/test_trace_digest.py new file mode 100644 index 000000000..fd02c62e3 --- /dev/null +++ b/tools/tests/test_trace_digest.py @@ -0,0 +1,129 @@ +import contextlib +import gzip +import io +import json +import sys +import tempfile +import unittest +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) +import trace_digest + + +def complete(tid, name, ts, dur): + return {"name": name, "ph": "X", "ts": ts, "dur": dur, "pid": 7, "tid": tid} + + +EVENTS = [ + {"name": "process_name", "ph": "M", "ts": 0, "pid": 7, "tid": 0, "args": {"name": "AnyPS5"}}, + {"name": "thread_name", "ph": "M", "ts": 0, "pid": 7, "tid": 1, "args": {"name": "queue worker 0x0"}}, + {"name": "thread_name", "ph": "M", "ts": 0, "pid": 7, "tid": 2, "args": {"name": "presenter"}}, + complete(1, "Driver.WorkerWait", 0, 4000), + complete(1, "Driver.Packet", 4000, 5000), + complete(1, "Driver.Packet.memory_wait", 5000, 2000), + complete(1, "Driver.Packet", 12000, 16000), + complete(1, "Driver.Packet.draw", 13000, 7000), + complete(2, "Driver.Present", 0, 2000), + complete(2, "Driver.Present.inflight_wait", 500, 1000), + complete(2, "Driver.Present", 10000, 16000), + complete(2, "Driver.Present.inflight_wait", 10500, 14500), + {"name": "queue worker 0x0 folded", "ph": "C", "ts": 0, "pid": 7, "tid": 1, "args": {"ms": 1.5}}, + {"name": "present", "ph": "i", "ts": 0, "pid": 7, "tid": 2, "s": "g", "args": {"present": 600}}, + {"name": "present", "ph": "i", "ts": 10000, "pid": 7, "tid": 2, "s": "g", "args": {"present": 601}}, + {"name": "present", "ph": "i", "ts": 30000, "pid": 7, "tid": 2, "s": "g", "args": {"present": 602}}, +] + +SUMMARY = {"commit": "abc", "dirty": False, "env": {"APS5_TRACE_FRAMES": "600:3"}, "gpu": "GPU", "driver": "Driver 1", "os": "OS 1", + "resolution": "1920x1080", "window": {"spec": "frames 600:3", "first_present": 600, "ms": 40.0}, "presents": 3, + "frame_ms": {"p50": 10.0, "p90": 20.0, "p99": 20.0, "max": 20.0}, "gpu_busy_ms_per_present": 5.0, + "worker_busy_pct": {"queue worker 0x0": 50.0}, "top_phases_ms_per_frame": {"Driver.Packet": 7.0}, "trace_dropped": False, + "trace": "aps5-trace-abc-7.json.gz"} + +STACKS = "# samples=5 depth=64 truncated=1\n# module a.prx 0x1000 0x1\nntdll.dll+0x1;a.prx+0x10;a.prx+0x20 3\nntdll.dll+0x1;a.prx+0x10;a.prx+0x30 1\n[truncated];a.prx+0x40;a.prx+0x30 1\n" + + +class TraceDigestTests(unittest.TestCase): + def setUp(self): + self.directory = tempfile.TemporaryDirectory() + root = Path(self.directory.name) + self.trace = root / "aps5-trace-abc-7.json.gz" + with gzip.open(self.trace, "wt", encoding="utf-8") as handle: + json.dump({"traceEvents": EVENTS}, handle) + (root / "aps5-summary.jsonl").write_text(json.dumps(dict(SUMMARY, trace="other.json.gz")) + "\n" + json.dumps(SUMMARY) + "\n", encoding="utf-8") + self.stacks = root / "worker.collapsed.txt" + self.stacks.write_text(STACKS, encoding="utf-8") + + def tearDown(self): + self.directory.cleanup() + + def result(self): + return trace_digest.digest(trace_digest.load_trace(self.trace), trace_digest.load_summary(None, self.trace), + trace_digest.load_stacks(self.stacks), worst=2, top=3) + + def test_summary_is_the_line_of_this_trace(self): + self.assertEqual(self.result()["summary"]["trace"], "aps5-trace-abc-7.json.gz") + + def test_frames_end_at_the_window(self): + result = self.result() + self.assertEqual(result["frames"], 3) + self.assertAlmostEqual(result["window_ms"], 40.0) + + def test_slowest_frame_lists_its_slices(self): + slowest = self.result()["slowest_frames"] + self.assertEqual([frame["present"] for frame in slowest], [601, 600]) + self.assertAlmostEqual(slowest[0]["ms"], 20.0) + largest = {(entry["name"], entry["thread"]): entry["ms"] for entry in slowest[0]["slices"]} + self.assertAlmostEqual(largest[("Driver.Packet", "queue worker 0x0")], 16.0) + self.assertAlmostEqual(largest[("Driver.Present", "presenter")], 16.0) + self.assertAlmostEqual(largest[("Driver.Present.inflight_wait", "presenter")], 14.5) + + def test_threads_split_busy_and_wait(self): + threads = {thread["thread"]: thread for thread in self.result()["threads"]} + worker = threads["queue worker 0x0"] + self.assertAlmostEqual(worker["wait_ms_per_frame"], 6.0 / 3) + self.assertAlmostEqual(worker["busy_ms_per_frame"], 19.0 / 3) + self.assertAlmostEqual(worker["untraced_ms_per_frame"], 15.0 / 3) + self.assertAlmostEqual(worker["folded_ms_per_frame"], 1.5 / 3) + self.assertEqual(worker["top"][0]["name"], "Driver.Packet") + presenter = threads["presenter"] + self.assertAlmostEqual(presenter["wait_ms_per_frame"], 15.5 / 3) + self.assertAlmostEqual(presenter["busy_ms_per_frame"], 2.5 / 3) + + def test_largest_slices_per_frame(self): + largest = self.result()["top_slices_ms_per_frame"] + self.assertEqual(largest[0]["name"], "Driver.Packet") + self.assertAlmostEqual(largest[0]["ms"], 21.0 / 3) + + def test_longest_waits(self): + waits = self.result()["longest_waits"] + self.assertEqual((waits[0]["name"], waits[0]["thread"], waits[0]["present"]), ("Driver.Present.inflight_wait", "presenter", 601)) + self.assertAlmostEqual(waits[0]["ms"], 14.5) + self.assertEqual(waits[1]["name"], "Driver.WorkerWait") + + def test_stacks_self_and_total(self): + stacks = self.result()["stacks"] + self.assertEqual(stacks["samples"], 5) + self.assertAlmostEqual(stacks["truncated_pct"], 20.0) + self.assertEqual(stacks["self"][0], {"frame": "a.prx+0x20", "pct": 60.0}) + total = {entry["frame"]: entry["pct"] for entry in stacks["total"]} + self.assertEqual(stacks["common_frames"], 2) + self.assertNotIn("a.prx+0x10", total) + self.assertEqual(total, {"a.prx+0x20": 60.0, "a.prx+0x30": 40.0, "a.prx+0x40": 20.0}) + + def test_command_line_markdown_and_json(self): + output = io.StringIO() + with contextlib.redirect_stdout(output): + self.assertEqual(trace_digest.main([str(self.trace), "--stacks", str(self.stacks)]), 0) + text = output.getvalue() + for heading in ("**Slowest frames**", "**Threads**", "**Largest slices**", "**Longest waits**", "**Worker stacks**"): + self.assertIn(heading, text) + self.assertLess(len(text.encode("utf-8")), 5000) + output = io.StringIO() + with contextlib.redirect_stdout(output): + trace_digest.main([str(self.trace), "--json"]) + self.assertEqual(json.loads(output.getvalue())["frames"], 3) + + +if __name__ == "__main__": + unittest.main() diff --git a/tools/trace_digest.py b/tools/trace_digest.py new file mode 100644 index 000000000..99011db35 --- /dev/null +++ b/tools/trace_digest.py @@ -0,0 +1,222 @@ +import argparse +import bisect +import collections +import gzip +import json +import sys +from pathlib import Path + +DESCRIPTION = """Digest of an APS5_TRACE_FRAMES / APS5_TRACE_SECONDS capture (aps5-trace-*.json.gz) for an issue or a +pull request: the summary line, the slowest frames with their largest slices, the busy and wait time of each +thread, the largest slices per frame, the longest waits and, with --stacks, the hottest functions of an +APS5_SAMPLE_WORKER collapsed-stack file. The summary line is read from aps5-summary.jsonl next to the trace +unless --summary names another file.""" + + +def is_wait(name): + return "wait" in name.rsplit(".", 1)[-1].lower() + + +class Trace: + def __init__(self, document): + self.threads = {} + self.slices = collections.defaultdict(list) + self.presents = [] + self.folded = collections.defaultdict(float) + for event in document["traceEvents"]: + phase = event.get("ph") + if phase == "M" and event.get("name") == "thread_name": + self.threads[event["tid"]] = event["args"]["name"] + elif phase == "X": + self.slices[event["tid"]].append([float(event["ts"]), float(event["dur"]), event["name"], 0, False]) + elif phase == "i" and event.get("name") == "present": + self.presents.append((float(event["ts"]), event.get("args", {}).get("present"))) + elif phase == "C": + self.folded[event["tid"]] += sum(float(value) for value in event.get("args", {}).values()) + self.presents.sort() + for slices in self.slices.values(): + slices.sort(key=lambda entry: (entry[0], -entry[1])) + stack = [] + for entry in slices: + while stack and entry[0] >= stack[-1][0] + stack[-1][1]: + stack.pop() + entry[3] = len(stack) + entry[4] = any(is_wait(parent[2]) for parent in stack) + stack.append(entry) + + def name(self, tid): + return self.threads.get(tid, f"tid {tid}") + + def frames(self, end): + starts = [ts for ts, _ in self.presents] + if end is None: + end = starts[-1] if starts else 0.0 + bounds = starts + ([end] if not starts or end > starts[-1] else []) + return [(index, bounds[index], bounds[index + 1], self.presents[index][1]) for index in range(len(bounds) - 1)] + + +def load_trace(path): + opener = gzip.open if str(path).endswith(".gz") else open + with opener(path, "rt", encoding="utf-8") as handle: + return Trace(json.load(handle)) + + +def load_summary(path, trace_path): + candidate = Path(path) if path else Path(trace_path).with_name("aps5-summary.jsonl") + if not candidate.exists(): + return None + lines = [json.loads(line) for line in candidate.read_text(encoding="utf-8").splitlines() if line.strip()] + for line in reversed(lines): + if path or line.get("trace") == Path(trace_path).name: + return line + return None + + +def load_stacks(path): + stacks = [] + for line in Path(path).read_text(encoding="utf-8").splitlines(): + if line.startswith("#") or not line.strip(): + continue + frames, _, count = line.rpartition(" ") + stacks.append((frames.split(";"), int(count))) + return stacks + + +def digest(trace, summary=None, stacks=None, worst=5, top=10): + window_ms = summary["window"]["ms"] if summary else None + frames = trace.frames(window_ms * 1000.0 if window_ms is not None else None) + span_us = frames[-1][2] - frames[0][1] if frames else 0.0 + count = max(len(frames), 1) + result = {"summary": summary, "frames": len(frames), "window_ms": span_us / 1000.0} + + slowest = [] + for index, begin, end, present in sorted(frames, key=lambda frame: frame[1] - frame[2])[:worst]: + inside = collections.Counter() + for tid, slices in trace.slices.items(): + for ts, dur, name, _, _ in slices: + overlap = min(ts + dur, end) - max(ts, begin) + if overlap > 0: + inside[(name, trace.name(tid))] += overlap + slowest.append({"present": present, "ms": (end - begin) / 1000.0, "at_ms": begin / 1000.0, + "slices": [{"name": name, "thread": thread, "ms": us / 1000.0} for (name, thread), us in inside.most_common(4)]}) + result["slowest_frames"] = slowest + + threads = [] + totals = collections.Counter() + waits = [] + for tid, slices in sorted(trace.slices.items()): + traced = sum(dur for _, dur, _, depth, _ in slices if depth == 0) + waited = sum(dur for _, dur, name, _, nested in slices if is_wait(name) and not nested) + leaders = collections.Counter() + for ts, dur, name, depth, nested in slices: + totals[name] += dur + if depth == 0 and not is_wait(name): + leaders[name] += dur + if is_wait(name) and not nested: + waits.append((dur, name, trace.name(tid), ts)) + threads.append({"thread": trace.name(tid), "busy_ms_per_frame": (traced - waited) / 1000.0 / count, + "wait_ms_per_frame": waited / 1000.0 / count, + "untraced_ms_per_frame": max(span_us - traced, 0.0) / 1000.0 / count, + "folded_ms_per_frame": trace.folded.get(tid, 0.0) / count, + "busy_pct": 100.0 * (traced - waited) / span_us if span_us else 0.0, + "wait_pct": 100.0 * waited / span_us if span_us else 0.0, + "top": [{"name": name, "ms_per_frame": us / 1000.0 / count} for name, us in leaders.most_common(2)]}) + result["threads"] = threads + result["top_slices_ms_per_frame"] = [{"name": name, "ms": us / 1000.0 / count} for name, us in totals.most_common(top)] + starts = [ts for ts, _ in trace.presents] + result["longest_waits"] = [{"name": name, "thread": thread, "ms": dur / 1000.0, "at_ms": ts / 1000.0, + "present": trace.presents[bisect.bisect_right(starts, ts) - 1][1] if starts and ts >= starts[0] else None} + for dur, name, thread, ts in sorted(waits, reverse=True)[:top]] + + if stacks is not None: + samples = sum(count for _, count in stacks) + own = collections.Counter() + inclusive = collections.Counter() + truncated = 0 + common = None + for frames_of, number in stacks: + if frames_of[0] == "[truncated]": + truncated += number + frames_of = frames_of[1:] + elif frames_of: + common = set(frames_of) if common is None else common & set(frames_of) + if not frames_of: + continue + own[frames_of[-1]] += number + for frame in set(frames_of): + inclusive[frame] += number + common = common or set() + for frame in common: + del inclusive[frame] + share = lambda value: 100.0 * value / samples if samples else 0.0 + result["stacks"] = {"samples": samples, "truncated_pct": share(truncated), "common_frames": len(common), + "self": [{"frame": frame, "pct": share(value)} for frame, value in own.most_common(top)], + "total": [{"frame": frame, "pct": share(value)} for frame, value in inclusive.most_common(top)]} + return result + + +def markdown(result): + lines = [] + summary = result["summary"] + if summary: + frame = summary["frame_ms"] + lines.append(f"**{summary['window']['spec']}** from present {summary['window']['first_present']}: {summary['presents']} presents, " + f"frame p50 {frame['p50']:.1f} / p90 {frame['p90']:.1f} / p99 {frame['p99']:.1f} / max {frame['max']:.1f} ms, " + f"GPU busy {summary['gpu_busy_ms_per_present']:.1f} ms per present") + lines.append(f"{summary['gpu']}, {summary['driver']}, {summary['os']}, {summary['resolution']}, commit {summary['commit']}" + f"{' (dirty)' if summary.get('dirty') else ''}, dropped: {'yes' if summary['trace_dropped'] else 'no'}") + lines.append("") + lines.append("```json") + lines.append(json.dumps(summary, separators=(",", ":"))) + lines.append("```") + else: + lines.append(f"{result['frames']} frames over {result['window_ms']:.1f} ms (no summary line found)") + lines.append("") + lines.append("**Slowest frames** (largest slices inside each, inclusive)") + lines.append("") + for frame in result["slowest_frames"]: + parts = ", ".join(f"{entry['name']} ({entry['thread']}) {entry['ms']:.1f}" for entry in frame["slices"]) + lines.append(f"- present {frame['present']}: {frame['ms']:.1f} ms at {frame['at_ms']:.0f} ms: {parts}") + lines.append("") + lines.append("**Threads** (ms per frame)") + lines.append("") + lines.append("| thread | busy | wait | untraced | in slices < 20 us | largest |") + lines.append("|---|---|---|---|---|---|") + for thread in result["threads"]: + largest = ", ".join(f"{entry['name']} {entry['ms_per_frame']:.1f}" for entry in thread["top"]) + lines.append(f"| {thread['thread']} | {thread['busy_ms_per_frame']:.1f} ({thread['busy_pct']:.0f} %) | {thread['wait_ms_per_frame']:.1f} ({thread['wait_pct']:.0f} %) " + f"| {thread['untraced_ms_per_frame']:.1f} | {thread['folded_ms_per_frame']:.1f} | {largest} |") + lines.append("") + lines.append("**Largest slices** (ms per frame, inclusive, all threads): " + ", ".join(f"{entry['name']} {entry['ms']:.1f}" for entry in result["top_slices_ms_per_frame"])) + lines.append("") + lines.append("**Longest waits**") + lines.append("") + for wait in result["longest_waits"]: + lines.append(f"- {wait['name']} ({wait['thread']}) {wait['ms']:.1f} ms at {wait['at_ms']:.0f} ms, present {wait['present']}") + if "stacks" in result: + stacks = result["stacks"] + lines.append("") + lines.append(f"**Worker stacks** ({stacks['samples']} samples, {stacks['truncated_pct']:.1f} % truncated; total leaves out the {stacks['common_frames']} frames every complete stack shares)") + lines.append("") + lines.append("- self: " + ", ".join(f"{entry['frame']} {entry['pct']:.1f} %" for entry in stacks["self"])) + lines.append("- total: " + ", ".join(f"{entry['frame']} {entry['pct']:.1f} %" for entry in stacks["total"])) + return "\n".join(lines) + "\n" + + +def main(arguments=None): + parser = argparse.ArgumentParser(description=DESCRIPTION) + parser.add_argument("trace", help="aps5-trace-*.json.gz (or .json)") + parser.add_argument("--summary", help="file with the summary line (default: aps5-summary.jsonl next to the trace)") + parser.add_argument("--stacks", help="collapsed-stack file of APS5_SAMPLE_WORKER (.collapsed.txt)") + parser.add_argument("--frames", type=int, default=5, help="slowest frames to list (default 5)") + parser.add_argument("--top", type=int, default=10, help="entries per list (default 10)") + parser.add_argument("--json", action="store_true", help="print the digest as JSON") + options = parser.parse_args(arguments) + result = digest(load_trace(options.trace), load_summary(options.summary, options.trace), + load_stacks(options.stacks) if options.stacks else None, options.frames, options.top) + sys.stdout.write(json.dumps(result, indent=1) + "\n" if options.json else markdown(result)) + return 0 + + +if __name__ == "__main__": + sys.exit(main())