128 lines
4.3 KiB
Python
Executable file
128 lines
4.3 KiB
Python
Executable file
#!/usr/bin/env python
|
|
|
|
import sys
|
|
import argparse
|
|
import re
|
|
|
|
def do_logparse(logname):
|
|
|
|
rmatch = re.compile(r'^([0-9]+\.[0-9]{3}): (done )?((vpu0)|(vpu1)|(qpu1)) ([A-Z_]+) cb:([0-9a-f]+) ')
|
|
rqcycle = re.compile(r'^([0-9]+\.[0-9]{3}): v3d: QPU Total clock cycles for all QPUs doing vertex/coordinate shading +([0-9]+)$')
|
|
rqtscycle = re.compile(r'^([0-9]+\.[0-9]{3}): v3d: QPU Total clock cycles for all QPUs stalled waiting for TMUs +([0-9]+)$')
|
|
rl2hits = re.compile(r'^([0-9]+\.[0-9]{3}): v3d: L2C Total Level 2 cache ([a-z]+) +([0-9]+)$')
|
|
|
|
ttotal = {'idle':0.0}
|
|
tstart = {}
|
|
qctotal = {}
|
|
qtstotal = {}
|
|
l2hits = {}
|
|
l2total = {}
|
|
time0 = None
|
|
idle_start = None
|
|
qpu_op_no = 0
|
|
op_count = 0
|
|
|
|
with open(logname, "rt") as infile:
|
|
for line in infile:
|
|
match = rmatch.match(line)
|
|
if match:
|
|
# print match.group(1), ":", match.group(2), ":", match.group(3), ":", match.group(7), ":"
|
|
time = float(match.group(1))
|
|
unit = match.group(3)
|
|
opstart = not match.group(2)
|
|
optype = match.group(7)
|
|
hascb = match.group(8) != "0"
|
|
|
|
if unit == 'qpu1':
|
|
unit = unit + "." + str(qpu_op_no)
|
|
if not opstart:
|
|
if hascb or optype == 'EXECUTE_SYNC':
|
|
qpu_op_no = 0
|
|
else:
|
|
qpu_op_no += 1
|
|
|
|
# Ignore sync type
|
|
if optype == 'EXECUTE_SYNC':
|
|
continue
|
|
|
|
if not time0:
|
|
time0 = time
|
|
|
|
if opstart:
|
|
tstart[unit] = time;
|
|
elif unit in tstart:
|
|
op_count += 1
|
|
if not unit in ttotal:
|
|
ttotal[unit] = 0.0
|
|
ttotal[unit] += time - tstart[unit]
|
|
del tstart[unit]
|
|
|
|
if not idle_start and not tstart:
|
|
idle_start = time
|
|
elif idle_start and tstart:
|
|
ttotal['idle'] += time - idle_start
|
|
idle_start = None
|
|
|
|
match = rqcycle.match(line)
|
|
if match:
|
|
unit = "qpu1." + str(qpu_op_no)
|
|
if not unit in qctotal:
|
|
qctotal[unit] = 0
|
|
qctotal[unit] += int(match.group(2))
|
|
|
|
match = rqtscycle.match(line)
|
|
if match:
|
|
unit = "qpu1." + str(qpu_op_no)
|
|
if not unit in qtstotal:
|
|
qtstotal[unit] = 0
|
|
qtstotal[unit] += int(match.group(2))
|
|
|
|
match = rl2hits.match(line)
|
|
if match:
|
|
unit = "qpu1." + str(qpu_op_no)
|
|
if not unit in l2total:
|
|
l2total[unit] = 0
|
|
l2hits[unit] = 0
|
|
l2total[unit] += int(match.group(3))
|
|
if match.group(2) == "hits":
|
|
l2hits[unit] += int(match.group(3))
|
|
|
|
|
|
if not time0:
|
|
print "No v3d profile records found"
|
|
else:
|
|
tlogged = time - time0
|
|
|
|
print "Logged time:", tlogged, " Op count:", op_count
|
|
for unit in sorted(ttotal):
|
|
print b'%6s: %10.3f %7.3f%%' % (unit, ttotal[unit], ttotal[unit] * 100.0 / tlogged)
|
|
print
|
|
for unit in sorted(qctotal):
|
|
if not unit in qtstotal:
|
|
qtstotal[unit] = 0;
|
|
print b'%6s: Qcycles: %10d, TMU stall: %10d (%7.3f%%)' % (unit, qctotal[unit], qtstotal[unit], (qtstotal[unit] * 100.0)/qctotal[unit])
|
|
if unit in l2total:
|
|
print b' L2Total: %10d, hits: %10d (%7.3f%%)' % (l2total[unit], l2hits[unit], (l2hits[unit] * 100.0)/l2total[unit])
|
|
|
|
|
|
|
|
if __name__ == '__main__':
|
|
argp = argparse.ArgumentParser(
|
|
formatter_class=argparse.RawDescriptionHelpFormatter,
|
|
description="QPU/VPU perf summary from VC logging",
|
|
epilog = """
|
|
Will also summarise TMU stalls if logging requests set in qpu noflush param
|
|
in the profiled code.
|
|
|
|
Example use:
|
|
vcgencmd set_logging level=0xc0
|
|
<command to profile>
|
|
sudo vcdbg log msg >& t.log
|
|
v3dusage.py t.log
|
|
""")
|
|
|
|
argp.add_argument("logfile")
|
|
args = argp.parse_args()
|
|
|
|
do_logparse(args.logfile)
|
|
|