From 00cecdf061756192608cf564efb41be2df2ec13a Mon Sep 17 00:00:00 2001 From: Acelogic <7362641+Acelogic@users.noreply.github.com> Date: Sat, 24 Oct 2026 21:54:41 -0400 Subject: [PATCH] tools: summarize a run's present pacing windows tools/summarize-present-pacing.py reduces a console's AdrenoDisplay perf windows to busy and quiet groups: copies per second, the copy interval buckets, ready / missed / true-miss ticks, per-IB GPU, submission, cache and preparation time, the copy, tick lateness and q, the perf done line's early completions and arrival histograms, and with --report the GPU's time per clock (DVFSREP1). Its host test runs it on a synthetic console. --- tools/summarize-present-pacing.py | 154 +++++++++++++++++++++++++ tools/test-summarize-present-pacing.py | 66 +++++++++++ 2 files changed, 220 insertions(+) create mode 100644 tools/summarize-present-pacing.py create mode 100644 tools/test-summarize-present-pacing.py diff --git a/tools/summarize-present-pacing.py b/tools/summarize-present-pacing.py new file mode 100644 index 0000000..e7f59ad --- /dev/null +++ b/tools/summarize-present-pacing.py @@ -0,0 +1,154 @@ +#!/usr/bin/env python3 +# SPDX-License-Identifier: MIT +"""Summarize a run's AdrenoDisplay perf windows: frame pacing and where a busy window's time went. Host only. + + python3 tools/summarize-present-pacing.py build/PREFIX/console.txt [--report build/PREFIX/report.bin] [--json] + +A perf window is the set of "AdrenoDisplay: perf s=" lines one perfLineGated call prints (600 layer-0 +copies, AdrenoDisplay/stats.cpp). Windows are split into busy (at least --busy-ibs completed IBs, default 200: about +20 IBs a second) and quiet ones, and each group is reduced to: +- copies per second (median, min) and the copy intervals by the pace line's buckets (<= 17, <= 20, <= 34, <= 50, + > 50 ms; <= 20 ms is on time, the tick firing late; 20-34 ms is one refresh shown twice; more is worse); +- the ticks: ready (a layer-0 copy started in the tick), missed (a frame was on screen, nothing new copied), idle; + missed less the relatch's copies (the head the tick deferred, copied into the same frame) is the share of refreshes + WindowServer did not deliver in time ("true misses"); +- per IB: GPU time (the monitor's poll ticks at 19.2 MHz), the kext's submission time with the lock held, its cache + maintenance time and bytes, its resource preparations; the copy time, the tick's lateness and q (swap to copy); +- with the early-completion kext (the perf done line): completions at the copy, late frames, engagements, and the + arrival and lateness histograms summed over the group. +With --report, the GPU's time per clock from the DVFSREP1 record (tools/dvfs_report.py) is added.""" +import argparse +import collections +import json +import re +import statistics +import sys +from pathlib import Path + +HOST_HZ = 19_200_000 # the monitor's IB tick counter (gtk) +NEED = ('why', 'pace', 'map', 'gpu', 'pipe', 'sync', 'vsync') + + +def windows(text): + w = collections.defaultdict(dict) + for line in text.split('\n'): + m = re.search(r'AdrenoDisplay: perf why=(\w+) s=(\d+) (.*)', line) + if m: + w[int(m.group(2))]['why'] = dict(re.findall(r'(\w+)=(\S+)', m.group(3)), kind=m.group(1)) + continue + m = re.search(r'AdrenoDisplay: perf (\w+) s=(\d+) (.*)', line) + if m: + w[int(m.group(2))][m.group(1)] = dict(re.findall(r'(\w+)=(\S+)', m.group(3))) + return w + + +def ints(text): + return [int(x) for x in text.split('/')] + + +def window_row(s, r): + """One periodic window's numbers, or None (an incomplete or non-periodic window).""" + if not all(k in r for k in NEED) or r['why'].get('kind') != 'periodic': + return None + p, mp, g, pi, sy, v = (r[k] for k in ('pace', 'map', 'gpu', 'pipe', 'sync', 'vsync')) + pp, tk = ints(p['pp']), ints(p['tk']) + span = sum(pp) * int(p['mean']) / 1e6 + ib = int(mp['ib']) + gtk, sub, cache, prep = ints(g['gtk']), ints(g['sub_us']), ints(g['cache']), ints(g['prep']) + relatch = r.get('relatch', {}) + row = dict(s=s, pps=float(p['pps']), span=span, ib=ib, buckets=pp, ticks=tk[0], ready=tk[1], missed=tk[2], idle=tk[3], + relatched=int(relatch.get('go', 0)), defer=int(sy['defer']), + gpu_ms_ib=gtk[0] / HOST_HZ * 1e3 / ib if ib else 0.0, + gpu_busy=gtk[0] / HOST_HZ / span if span else 0.0, + sub_ms_ib=sub[0] / 1e3 / ib if ib else 0.0, cache_ms_ib=cache[2] / 1e3 / ib if ib else 0.0, + cache_mib_ib=cache[1] / ib if ib else 0.0, prep_ms_ib=prep[1] / 1e3 / ib if ib else 0.0, + copy_us=int(r['why']['mean_us']), late_us=ints(v['grid'])[0], q_us=int(p['q'])) + if 'done' in r: + d = r['done'] + row['done'] = dict(mode=int(d['mode']), on=int(d['on']), early=int(d['done']), late=int(d['late']), + engages=int(d['eng']), ahead=int(d['ahd']), arr=ints(d['arr']), lat=ints(d['lat'])) + return row + + +def group(rows): + if not rows: + return None + ticks = sum(r['ticks'] for r in rows) or 1 + buckets = [sum(r['buckets'][i] for r in rows) for i in range(5)] + intervals = sum(buckets) or 1 + med = lambda k: round(statistics.median(r[k] for r in rows), 3) + out = dict(windows=len(rows), pps_median=med('pps'), pps_min=min(r['pps'] for r in rows), + ticks_per_s=round(ticks / sum(r['span'] for r in rows), 2), + ready_pct=round(100 * sum(r['ready'] for r in rows) / ticks, 1), + missed_pct=round(100 * sum(r['missed'] for r in rows) / ticks, 1), + true_miss_pct=round(100 * sum(r['missed'] - r['relatched'] for r in rows) / ticks, 1), + deferred_pct=round(100 * sum(r['defer'] for r in rows) / ticks, 1), + intervals_pct=[round(100 * b / intervals, 1) for b in buckets], + over34_pct=round(100 * (buckets[3] + buckets[4]) / intervals, 1), + ibs_per_s=round(sum(r['ib'] for r in rows) / sum(r['span'] for r in rows), 1)) + for k in ('gpu_ms_ib', 'gpu_busy', 'sub_ms_ib', 'cache_ms_ib', 'cache_mib_ib', 'prep_ms_ib', 'copy_us', 'late_us', + 'q_us'): + out[k + '_median'] = med(k) + done = [r['done'] for r in rows if 'done' in r] + if done: + out['done'] = dict(modes=sorted({d['mode'] for d in done}), engaged_windows=sum(1 for d in done if d['on']), + early=sum(d['early'] for d in done), late=sum(d['late'] for d in done), + engages=sum(d['engages'] for d in done), ahead=sum(d['ahead'] for d in done), + arrival_2ms_bins=[sum(d['arr'][i] for d in done) for i in range(len(done[0]['arr']))], + late_bins_2_4_8_more=[sum(d['lat'][i] for d in done) for i in range(len(done[0]['lat']))]) + return out + + +def summarize(text, busy_ibs=200): + rows = [x for x in (window_row(s, r) for s, r in sorted(windows(text).items())) if x] + return dict(busy=group([r for r in rows if r['ib'] >= busy_ibs]), + quiet=group([r for r in rows if r['ib'] < busy_ibs]), busy_ibs=busy_ibs) + + +def gpu_clocks(report): + sys.path.insert(0, str(Path(__file__).resolve().parent)) + import dvfs_report + raw = Path(report).read_bytes() + decoded = dvfs_report.decode_block(raw[dvfs_report.OFFSET:dvfs_report.OFFSET + 8 * 190]) # as its main reads it + gpu = decoded.get('gpu', {}) if isinstance(decoded, dict) else {} + keep = ('status', 'ceiling_mhz', 'seconds_at_mhz', 'mean_mhz', 'errors', 'thermal') + return {k: gpu[k] for k in keep if k in gpu} + + +def main(): + ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + ap.add_argument('console', type=Path) + ap.add_argument('--report', type=Path) + ap.add_argument('--busy-ibs', type=int, default=200) + ap.add_argument('--json', action='store_true') + a = ap.parse_args() + out = summarize(a.console.read_text(errors='replace'), a.busy_ibs) + if a.report: + out['gpu_clock'] = gpu_clocks(a.report) + if a.json: + print(json.dumps(out, indent=1)) + return + for name in ('busy', 'quiet'): + g = out[name] + if not g: + print(f'{name}: no windows') + continue + print(f"{name}: {g['windows']} windows, copies/s median {g['pps_median']} (min {g['pps_min']}), ticks/s " + f"{g['ticks_per_s']}, IBs/s {g['ibs_per_s']}; ticks ready {g['ready_pct']}% missed {g['missed_pct']}% " + f"(true misses {g['true_miss_pct']}%), deferred {g['deferred_pct']}%; intervals <=17/20/34/50/>50 ms " + f"{'/'.join(str(x) for x in g['intervals_pct'])}%, over 34 ms {g['over34_pct']}%") + print(f" per IB: GPU {g['gpu_ms_ib_median']} ms (GPU busy {g['gpu_busy_median']}), submit {g['sub_ms_ib_median']} ms, " + f"cache {g['cache_ms_ib_median']} ms / {g['cache_mib_ib_median']} MiB, preparation {g['prep_ms_ib_median']} ms; " + f"copy {g['copy_us_median']} us, tick late {g['late_us_median']} us, q {g['q_us_median']} us") + if 'done' in g: + d = g['done'] + print(f" early completion: modes {d['modes']}, engaged at {d['engaged_windows']} window ends, {d['early']} " + f"completions at the copy, {d['late']} late frames ({d['engages']} engagements), {d['ahead']} arrivals " + f"behind another; arrivals by 2 ms {d['arrival_2ms_bins']}, lateness <2/<4/<8/more " + f"{d['late_bins_2_4_8_more']}") + if 'gpu_clock' in out: + print(f"gpu clock: {json.dumps(out['gpu_clock'])}") + + +if __name__ == '__main__': + main() diff --git a/tools/test-summarize-present-pacing.py b/tools/test-summarize-present-pacing.py new file mode 100644 index 0000000..f791ef9 --- /dev/null +++ b/tools/test-summarize-present-pacing.py @@ -0,0 +1,66 @@ +#!/usr/bin/env python3 +# SPDX-License-Identifier: MIT +"""Host test for tools/summarize-present-pacing.py on a synthetic console: two complete periodic windows (one busy, one +quiet, the quiet one with the early-completion perf done line), one incomplete window and one reject window, which +must both be left out.""" +import importlib.util +import unittest +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[1] +spec = importlib.util.spec_from_file_location('summarize', ROOT / 'tools/summarize-present-pacing.py') +tool = importlib.util.module_from_spec(spec) +spec.loader.exec_module(tool) + + +def window(s, ib, pp, mean, tk, gtk, sub, cache, prep, go, defer, done=None, why='periodic'): + lines = [ + f'AdrenoDisplay: perf why={why} s={s} presents=600 copies=600 win=600 mean_us=2000 max_us=3000 all_mean_us=2000 ' + 'all_max_us=9000', + f'AdrenoDisplay: perf pace s={s} pps=50.0 pp={pp} mean={mean} p95=34 tk={tk} late=700 off=0 gpu=1/2000 q=6000', + f'AdrenoDisplay: perf vsync s={s} period_ns=16666666 grid=900/3000 early=1/100 skip=0 rs=0/0 lead=900 arm=1/0 ' + 'unarmed=0 ticks=1', + f'AdrenoDisplay: perf sync s={s} defer={defer} swaps={defer} forced=0 max_us=2000 marks=1 busy=1 ovf=0 stale=0 unm=0', + f'AdrenoDisplay: perf pipe s={s} on=3 fl={ib} ovl=0 imm=0 sync=0 fold=0 drain=0 tmr=0 polls=0 spin_us=0 ' + 'gap_us=0 max_ms=1 fail=0', + f'AdrenoDisplay: perf relatch s={s} on=7 arm={go} go={go} late=0 gone=0 gate=0 polls=0 ovt=0 lead=0/0 wait=0 ' + 'rel=0/0/0/0/0/0/0/0 ef=0/0/0 unm=0', + f'AdrenoDisplay: perf map s={s} ins=0 pg=0/0/0 clr=0 sfree=0 pool=0/0/0/0 va=0/0/0/0 ib={ib}', + f'AdrenoDisplay: perf gpu s={s} gtk={gtk}/0 sub_us={sub}/0 prep={prep} unw=0/0 cache={cache} res=0/0/0/0 ' + 'mib=0/0', + ] + if done: + lines.append(f'AdrenoDisplay: perf done s={s} {done}') + return lines + + +class Summary(unittest.TestCase): + def test_groups(self): + text = '\n'.join( + window(1, 600, '300/150/100/40/10', 20000, '600/400/180/20', 19200000, 1200000, '60000/60000/1800000', + '120000/600000', 60, 70) + + window(2, 30, '500/90/10/0/0', 16900, '600/590/8/2', 192000, 30000, '3000/1000/30000', '3000/60000', 0, 1, + done='mode=2 on=1 done=5 late=2 eng=1 ahd=3 arr=1/2/3/4/5/6/7/8/9 lat=1/0/1/0') + + window(3, 600, '1/0/0/0/0', 1, '1/1/0/0', 1, 1, '1/1/1', '1/1', 0, 0)[:3] + # incomplete: left out + window(4, 600, '1/0/0/0/0', 1, '1/1/0/0', 1, 1, '1/1/1', '1/1', 0, 0, why='reject')) + out = tool.summarize(text, 200) + busy, quiet = out['busy'], out['quiet'] + self.assertEqual((busy['windows'], quiet['windows']), (1, 1)) + self.assertEqual(busy['intervals_pct'], [50.0, 25.0, 16.7, 6.7, 1.7]) + self.assertEqual(busy['over34_pct'], 8.3) + self.assertEqual((busy['ready_pct'], busy['missed_pct'], busy['true_miss_pct']), (66.7, 30.0, 20.0)) + self.assertAlmostEqual(busy['gpu_ms_ib_median'], 1.667, places=3) # 1 s of host ticks over 600 IBs + self.assertAlmostEqual(busy['sub_ms_ib_median'], 2.0, places=3) + self.assertAlmostEqual(busy['cache_ms_ib_median'], 3.0, places=3) + self.assertAlmostEqual(busy['cache_mib_ib_median'], 100.0, places=3) + self.assertAlmostEqual(busy['prep_ms_ib_median'], 1.0, places=3) + self.assertNotIn('done', busy) + self.assertEqual(quiet['done'], dict(modes=[2], engaged_windows=1, early=5, late=2, engages=1, ahead=3, + arrival_2ms_bins=[1, 2, 3, 4, 5, 6, 7, 8, 9], late_bins_2_4_8_more=[1, 0, 1, 0])) + + def test_empty(self): + self.assertEqual(tool.summarize('nothing here'), dict(busy=None, quiet=None, busy_ibs=200)) + + +if __name__ == '__main__': + unittest.main()