288 lines
10 KiB
Python
288 lines
10 KiB
Python
#!/usr/bin/env python3
|
|
'''
|
|
Plot buffer pts and events in relation to the wall clock. The plots can be used
|
|
to spot anomalies, such as processing gaps.
|
|
|
|
How to run:
|
|
1) generate a log
|
|
GST_DEBUG="GST_TRACER:7" GST_TRACERS=stats GST_DEBUG_FILE=trace.log <application>
|
|
|
|
2) generate the images
|
|
python3 gsttr-tsplot.py trace.log <outdir>
|
|
eog <outdir>/*.png
|
|
'''
|
|
|
|
# TODO:
|
|
# - improve event plot
|
|
# - ideally each event is a vertical line
|
|
# http://stackoverflow.com/questions/35105672/vertical-lines-from-data-in-file-in-time-series-plot-using-gnuplot
|
|
# - this won't work well if the event is e.g. 'qos'
|
|
# - we could sort them by event type and separate them by double new-lines,
|
|
# we'd then use 'index <x>' to plot them in different colors with
|
|
# - buffer-pts should be ahead of clock time of the pipeline
|
|
# - we don't have the clock ts in the log though
|
|
|
|
import logging
|
|
import os
|
|
from subprocess import Popen, PIPE, DEVNULL
|
|
from string import Template
|
|
from tracer.analysis_runner import AnalysisRunner
|
|
from tracer.analyzer import Analyzer
|
|
from tracer.parser import Parser
|
|
from tracer.structure import Structure
|
|
|
|
|
|
logging.basicConfig(level=logging.WARNING)
|
|
logger = logging.getLogger('gsttr-tsplot')
|
|
|
|
_HANDLED_CLASSES = ('buffer', 'event', 'new-pad', 'new-element')
|
|
|
|
_GST_BUFFER_FLAG_DISCONT = (1 << 6)
|
|
|
|
_PLOT_SCRIPT_HEAD = Template(
|
|
'''
|
|
set term pngcairo truecolor size $width,$height font "Helvetica,14"
|
|
set style line 1 lc rgb '#8b1a0e' pt 1 ps 1 lt 1 lw 1 # --- red
|
|
set style line 2 lc rgb '#5e9c36' pt 6 ps 1 lt 1 lw 1 # --- green
|
|
set style line 100 lc rgb '#999999' lt 0 lw 1
|
|
set grid back ls 100
|
|
set key font ",10"
|
|
set label font ",10"
|
|
set tics font ",10"
|
|
set xlabel font ",10"
|
|
set ylabel font ",10"
|
|
''')
|
|
_PLOT_SCRIPT_BODY = Template(
|
|
'''
|
|
set output '$png_file_name'
|
|
set multiplot layout 3,1 title "$title\\n$subtitle"
|
|
|
|
set xlabel ""
|
|
set xrange [*:*] writeback
|
|
set xtics format ""
|
|
set ylabel "Buffer Time (sec.msec)" offset 1,0
|
|
set yrange [*:*]
|
|
set ytics
|
|
plot '$buf_file_name' using 1:2 with linespoints ls 1 notitle
|
|
|
|
set xrange restore
|
|
set ylabel "Duration (sec.msec)" offset 1,0
|
|
plot '$buf_file_name' using 1:3 with linespoints ls 1title "cycle", \
|
|
'' using 1:4 with linespoints ls 2 title "duration"
|
|
|
|
set xrange restore
|
|
set xtics format "%g" scale .5 offset 0,.5
|
|
set xlabel "Clock Time (sec.msec)" offset 0,1
|
|
set ylabel "Events" offset 1,0
|
|
set yrange [$ypos_max:10]
|
|
set ytics format ""
|
|
plot '$ev_file_name' using 1:4:3:(0) with vectors heads size screen 0.008,90 ls 1 notitle, \
|
|
'' using 2:4 with points ls 1 notitle, \
|
|
'' using 2:4:5 with labels font ',7' offset char 0,-0.5 notitle
|
|
unset multiplot
|
|
''')
|
|
|
|
|
|
class TsPlot(Analyzer):
|
|
'''Generate a timestamp plots from a tracer log.
|
|
|
|
These show the buffer pts on the y-axis and the wall-clock time the buffer
|
|
was produced on the x-axis. This helps to spot timing issues, such as
|
|
stalled elements.
|
|
'''
|
|
|
|
def __init__(self, outdir, show_ghost_pads, size):
|
|
super(TsPlot, self).__init__()
|
|
self.outdir = outdir
|
|
self.show_ghost_pads = show_ghost_pads
|
|
self.params = {
|
|
'width': size[0],
|
|
'height': size[1],
|
|
}
|
|
self.buf_files = {}
|
|
self.buf_cts = {}
|
|
self.ev_files = {}
|
|
self.element_names = {}
|
|
self.element_info = {}
|
|
self.pad_names = {}
|
|
self.pad_info = {}
|
|
self.ev_labels = {}
|
|
self.ev_data = {}
|
|
self.ev_ypos = {}
|
|
|
|
def _get_data_file(self, files, key, name_template):
|
|
data_file = files.get(key)
|
|
if not data_file:
|
|
pad_name = self.pad_names.get(key)
|
|
if pad_name:
|
|
file_name = name_template % (self.outdir, key, pad_name)
|
|
data_file = open(file_name, 'w')
|
|
files[key] = data_file
|
|
return data_file
|
|
|
|
def _log_event_data(self, pad_file, ix):
|
|
data = self.ev_data.get(ix)
|
|
if not data:
|
|
return
|
|
line = self.ev_labels[ix]
|
|
ct = data['ct']
|
|
x1 = data['first-ts']
|
|
# TODO: scale 'y' according to max-y of buf or do a multiplot
|
|
y = (1 + data['ypos']) * -10
|
|
if ct == 1:
|
|
pad_file.write('%f %f %f %f "%s"\n' % (x1, x1, 0.0, y, line))
|
|
else:
|
|
x2 = data['last-ts']
|
|
xd = (x2 - x1)
|
|
xm = x1 + xd / 2
|
|
pad_file.write('%f %f %f %f "%s (%d)"\n' % (x1, xm, xd, y, line, ct))
|
|
|
|
def _log_event(self, s):
|
|
# build a [ts, event-name] data file
|
|
ix = int(s.values['pad-ix'])
|
|
pad_file = self._get_data_file(self.ev_files, ix, '%s/ev_%d_%s.dat')
|
|
if not pad_file:
|
|
return
|
|
# convert timestamps to seconds
|
|
x = int(s.values['ts']) / 1e9
|
|
# some events fire often, labeling each would be unreadable
|
|
# so we aggregate a series of events of the same type
|
|
line = s.values['name']
|
|
if line == self.ev_labels.get(ix):
|
|
# count lines and track last ts
|
|
data = self.ev_data[ix]
|
|
data['ct'] += 1
|
|
data['last-ts'] = x
|
|
else:
|
|
self._log_event_data(pad_file, ix)
|
|
# start new data, assign a -y coord by event type
|
|
if ix not in self.ev_ypos:
|
|
ypos = {}
|
|
self.ev_ypos[ix] = ypos
|
|
else:
|
|
ypos = self.ev_ypos[ix]
|
|
if line in ypos:
|
|
y = ypos[line]
|
|
else:
|
|
y = len(ypos)
|
|
ypos[line] = y
|
|
self.ev_labels[ix] = line
|
|
self.ev_data[ix] = {
|
|
'ct': 1,
|
|
'first-ts': x,
|
|
'ypos': y,
|
|
}
|
|
|
|
def _log_buffer(self, s):
|
|
if not int(s.values['have-buffer-pts']):
|
|
return
|
|
# build a [ts, buffer-pts] data file
|
|
ix = int(s.values['pad-ix'])
|
|
pad_file = self._get_data_file(self.buf_files, ix, '%s/buf_%d_%s.dat')
|
|
if not pad_file:
|
|
return
|
|
flags = int(s.values['buffer-flags'])
|
|
if flags & _GST_BUFFER_FLAG_DISCONT:
|
|
pad_file.write('\n')
|
|
# convert timestamps to e.g. seconds
|
|
cts = int(s.values['ts']) / 1e9
|
|
pts = int(s.values['buffer-pts']) / 1e9
|
|
dur = int(s.values['buffer-duration']) / 1e9
|
|
if ix not in self.buf_cts:
|
|
dcts = 0
|
|
else:
|
|
dcts = cts - self.buf_cts[ix]
|
|
self.buf_cts[ix] = cts
|
|
pad_file.write('%f %f %f %f\n' % (cts, pts, dcts, dur))
|
|
|
|
def handle_tracer_entry(self, event):
|
|
if event[Parser.F_FUNCTION]:
|
|
return
|
|
|
|
msg = event[Parser.F_MESSAGE]
|
|
p = msg.find(',')
|
|
if p == -1:
|
|
return
|
|
entry_name = msg[:p]
|
|
if entry_name not in _HANDLED_CLASSES:
|
|
return
|
|
|
|
try:
|
|
s = Structure(msg)
|
|
except ValueError:
|
|
logger.warning("failed to parse: '%s'", msg)
|
|
return
|
|
|
|
if entry_name == 'new-element':
|
|
ix = int(s.values['ix'])
|
|
self.element_names[ix] = s.values['name']
|
|
self.element_info[ix] = 'Element Type: %s' % s.values['type']
|
|
elif entry_name == 'new-pad':
|
|
pad_type = s.values['type']
|
|
if self.show_ghost_pads or pad_type not in ['GstGhostPad', 'GstProxyPad']:
|
|
parent_ix = int(s.values['parent-ix'])
|
|
parent_name = self.element_names.get(parent_ix, '')
|
|
ix = int(s.values['ix'])
|
|
self.pad_names[ix] = '%s.%s' % (parent_name, s.values['name'])
|
|
self.pad_info[ix] = '(%s, Pad Type: %s)' % (
|
|
self.element_info.get(parent_ix, ''), pad_type)
|
|
elif entry_name == 'event':
|
|
self._log_event(s)
|
|
else: # 'buffer'
|
|
self._log_buffer(s)
|
|
|
|
def report(self):
|
|
for ix, pad_file in self.ev_files.items():
|
|
self._log_event_data(pad_file, ix)
|
|
pad_file.close()
|
|
|
|
script = _PLOT_SCRIPT_HEAD.substitute(self.params)
|
|
for ix, pad_file in self.buf_files.items():
|
|
pad_file.close()
|
|
name = self.pad_names[ix]
|
|
buf_file_name = '%s/buf_%d_%s.dat' % (self.outdir, ix, name)
|
|
ev_file_name = '%s/ev_%d_%s.dat' % (self.outdir, ix, name)
|
|
png_file_name = '%s/%d_%s.png' % (self.outdir, ix, name)
|
|
sub_title = self.pad_info[ix]
|
|
ypos_max = (2 + len(self.ev_ypos[ix])) * -10
|
|
script += _PLOT_SCRIPT_BODY.substitute(self.params, title=name,
|
|
subtitle=sub_title, buf_file_name=buf_file_name,
|
|
ev_file_name=ev_file_name, png_file_name=png_file_name,
|
|
ypos_max=ypos_max)
|
|
# plot PNGs
|
|
p = Popen(['gnuplot'], stdout=DEVNULL, stdin=PIPE)
|
|
p.communicate(input=script.encode('utf-8'))
|
|
|
|
# cleanup
|
|
for ix, pad_file in self.buf_files.items():
|
|
name = self.pad_names[ix]
|
|
buf_file_name = '%s/buf_%d_%s.dat' % (self.outdir, ix, name)
|
|
os.unlink(buf_file_name)
|
|
for ix, pad_file in self.ev_files.items():
|
|
name = self.pad_names[ix]
|
|
ev_file_name = '%s/ev_%d_%s.dat' % (self.outdir, ix, name)
|
|
os.unlink(ev_file_name)
|
|
|
|
|
|
if __name__ == '__main__':
|
|
import argparse
|
|
parser = argparse.ArgumentParser()
|
|
parser.add_argument('file', nargs='?', default='debug.log')
|
|
parser.add_argument('outdir', nargs='?', default='tsplot')
|
|
parser.add_argument('-g', '--ghost-pads', action='store_true',
|
|
help='also plot data for ghost-pads')
|
|
parser.add_argument('-s', '--size', action='store', default='1600x600',
|
|
help='graph size as WxH')
|
|
args = parser.parse_args()
|
|
|
|
os.makedirs(args.outdir, exist_ok=True)
|
|
size = [int(s) for s in args.size.split('x')]
|
|
|
|
with Parser(args.file) as log:
|
|
tsplot = TsPlot(args.outdir, args.ghost_pads, size)
|
|
runner = AnalysisRunner(log)
|
|
runner.add_analyzer(tsplot)
|
|
runner.run()
|
|
|
|
tsplot.report()
|