sots-re/verify/harness/profiling/parse.py

103 lines
5.7 KiB
Python

#!/usr/bin/env python3
"""Parse sampler.ps1 output. Usage: parse.py samp.txt [t0_ms t1_ms] (window for histograms)"""
import sys, re, bisect, collections
fn = sys.argv[1]
t0 = int(sys.argv[2]) if len(sys.argv) > 2 else 0
t1 = int(sys.argv[3]) if len(sys.argv) > 3 else 10**12
funcs = [int(l, 16) for l in open('funcs.txt')]
names = {}
for l in open('names.txt'):
a, n = l.split(None, 1); names[int(a, 16)] = n.strip()
for a, n in [(0x89a640, 'DemoApp::OnTick'), (0x898800, 'DemoApp::OnUpdate'), (0x899210, 'DemoApp::OnRender')]:
names[a] = n
STATE = {0: 'Init', 1: 'Ready', 2: 'Running', 3: 'Standby', 4: 'Terminated', 5: 'Wait', 6: 'Transition', 7: 'DeferredReady', 8: 'GateWait'}
WR = {0: 'Executive', 1: 'FreePage', 2: 'PageIn', 3: 'PoolAlloc', 4: 'DelayExecution', 5: 'Suspended', 6: 'UserRequest', 7: 'WrExecutive', 8: 'WrFreePage', 9: 'WrPageIn', 10: 'WrPoolAlloc', 11: 'WrDelayExecution', 12: 'WrSuspended', 13: 'WrUserRequest', 14: 'WrEventPair', 15: 'WrQueue', 16: 'WrLpcReceive', 17: 'WrLpcReply', 18: 'WrVirtualMemory', 19: 'WrPageOut', 20: 'WrRendezvous', 21: 'WrKeyedEvent', 22: 'WrTerminated', 23: 'WrProcessInSwap', 24: 'WrCpuRateControl', 25: 'WrCalloutStack', 26: 'WrKernel', 27: 'WrResource', 28: 'WrPushLock', 29: 'WrMutex', 30: 'WrQuantumEnd', 31: 'WrDispatchInt', 32: 'WrPreempted', 33: 'WrYieldExecution', 34: 'WrFastMutex', 35: 'WrGuardedMutex', 36: 'WrRundown', 37: 'WrAlertByThreadId', 38: 'WrDeferredPreempt'}
mods = {}; threads = {}; exe_base = None
lines = open(fn, encoding='utf-8', errors='replace').read().splitlines()
for l in lines:
if l.startswith('M '):
p = l.split(); base = int(p[1], 16); size = int(p[2], 16); name = ' '.join(p[3:]).split(' exports=')[0]
mods[name] = (base, size)
if name.startswith('Sword'): exe_base = base
elif l.startswith('T '):
p = l.split(); threads[p[1]] = l
delta = exe_base - 0x400000
def fname(a):
"""ghidra addr -> function name/start"""
i = bisect.bisect_right(funcs, a) - 1
st = funcs[i] if i >= 0 else a
return names.get(st, 'sub_%08x' % st)
def sym(frame):
m = re.match(r'Sword of the Stars\.exe\+0x([0-9a-f]+)\(0x([0-9a-f]+)\)', frame)
if m:
g = int(m.group(2), 16) - delta
return fname(g) + '(@%08x)' % g, 'exe'
m = re.match(r'([^!+]+)(!([^+]+))?\+0x[0-9a-f]+', frame)
if m:
return (m.group(1) + ('!' + m.group(3) if m.group(3) else '')), m.group(1)
return frame, '?'
cpu = [] # (t, {tid: ms})
samples = collections.defaultdict(list) # tid -> [(t, state, wr, frames)]
for l in lines:
if l.startswith('C '):
p = l.split(); t = int(p[1]); d = {}
for x in p[2:]:
tid, ms = x.split(':'); d[tid] = float(ms)
cpu.append((t, d))
elif l.startswith('S '):
p = l.split(' ', 4); t = int(p[1]); tid = p[2]; st = p[3][3:]
rest = p[4] if len(p) > 4 else ''
main, _, scan = rest.partition(' < |scan| ')
frames = main.split(' < ')
scanf = scan.split(' < ') if scan else []
samples[tid].append((t, st, frames, scanf))
def tclass(tid):
l = threads.get(tid, '')
if 'vulkan_lvp' in l: return 'lavapipe'
if 'd3d9.dll' in l: return 'dxvk'
if 'Sword' in l:
m = re.search(r'\(0x([0-9a-f]+)\)', l); g = int(m.group(1), 16) - delta
return {0x925794: 'MAIN', 0x8ef1d0: 'audio', 0x901f40: 'netwd', 0x735bb0: 'mesh'}.get(g, 'exe@%x' % g)
return 'other'
print('# exe base 0x%08x delta 0x%x' % (exe_base, delta))
print('# threads:')
for tid, l in threads.items():
print(' ', tid, tclass(tid), l.split('start=')[1][:60])
print('\n# CPU timeline (ms per ~500ms bucket): t MAIN lavapipe dxvk audio net mesh other')
tot = collections.Counter()
for t, d in cpu:
if t < t0 or t > t1: continue
c = collections.Counter()
for tid, ms in d.items(): c[tclass(tid)] += ms; tot[tclass(tid)] += ms
print(' %7d %6.0f %8.0f %6.0f %6.0f %5.0f %5.0f %6.0f' % (t, c['MAIN'], c['lavapipe'], c['dxvk'], c['audio'], c['netwd'], c['mesh'], c['other']))
print(' TOTAL ', dict(tot))
for tid, ss in samples.items():
ss = [s for s in ss if t0 <= s[0] <= t1]
if not ss: continue
print('\n# thread %s (%s): %d samples in window' % (tid, tclass(tid), len(ss)))
sh = collections.Counter(); top = collections.Counter(); inc = collections.Counter(); waiter = collections.Counter(); exetop = collections.Counter()
for t, st, frames, scanf in ss:
s, w = (st.split('/') + ['?'])[:2]
sh['%s/%s' % (STATE.get(int(s), s) if s.isdigit() else s, WR.get(int(w), w) if w.isdigit() else w)] += 1
syms = [sym(f) for f in frames]
top[syms[0][0]] += 1
seen = set()
for n, m in syms:
if n not in seen: seen.add(n); inc[n] += 1
# first exe frame (what game code is doing)
ex = next((n for n, m in syms if m == 'exe'), None)
if ex: exetop[ex] += 1
# if waiting in ntdll: who called the wait (first non-ntdll/kernelbase frame)
if syms[0][1] == 'ntdll.dll':
wf = next((n for n, m in syms if m not in ('ntdll.dll', 'KERNELBASE.dll', 'KERNEL32.DLL')), '?')
waiter[syms[0][0] + ' <- ' + wf + (' <- ' + ex if ex else '')] += 1
n = len(ss)
print(' state:', ', '.join('%s %.0f%%' % (k, 100.0 * v / n) for k, v in sh.most_common()))
print(' top-of-stack:')
for k, v in top.most_common(15): print(' %5.1f%% %s' % (100.0 * v / n, k))
print(' wait sites (syscall <- caller <- first exe frame):')
for k, v in waiter.most_common(12): print(' %5.1f%% %s' % (100.0 * v / n, k))
print(' first exe frame (innermost game function):')
for k, v in exetop.most_common(20): print(' %5.1f%% %s' % (100.0 * v / n, k))
print(' inclusive:')
for k, v in inc.most_common(45): print(' %5.1f%% %s' % (100.0 * v / n, k))