tracer: tsplot: separate the event section

Place the events below the buffer-ts. This makes it more readable in many cases.

tracer/gsttr-tsplot.py

@@ -13,14 +13,12 @@ eog <outdir>/*.png
 '''
 
 # TODO:
-# - the event labels are still way too dense
+# - 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 separarate them by double new-lines,
+#   - 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
-#   - instead of just skipping duplicates, we could count them, store min/max ts
-#     and draw segments (is there something like labeled horizontal error bars?)
 
 import logging
 import os
@@ -44,8 +42,23 @@ _PLOT_SCRIPT_HEAD = Template(
     ''')
 _PLOT_SCRIPT_BODY = Template(
     '''set output '$png_file_name'
-       plot '$buf_file_name' using 1:2 with linespoints title '$pad_name', \
+       set multiplot layout 2,1 title '$pad_name'
-            '$ev_file_name' using 1:(0):2 with labels rotate center font ',7' notitle')
+       set style line 100 lc rgb '#dddddd' lt 0 lw 1
+       set grid back ls 100
+
+       set xlabel "Clock Time (sec.msec)"
+       set ylabel "Buffer Time (sec.msec)"
+       set yrange [*:*]
+       set ytics
+       plot '$buf_file_name' using 1:2 with linespoints notitle
+
+       set ylabel "Events"
+       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 notitle, \
+            '' using 2:4 with points notitle, \
+            '' using 2:4:5 with labels font ',7' offset char 0,-0.5 notitle
+       unset multiplot
        ''')
 
 class TsPlot(Analyzer):
@@ -69,6 +82,8 @@ class TsPlot(Analyzer):
         self.element_names = {}
         self.pad_names = {}
         self.ev_labels = {}
+        self.ev_data = {}
+        self.ev_ypos = {}
 
     def _get_data_file(self, files, key, name_template):
         data_file = files.get(key)
@@ -80,6 +95,75 @@ class TsPlot(Analyzer):
                 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
+        l = 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, l))
+        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, l, 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
+        l = s.values['name']
+        if l == 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 not ix in self.ev_ypos:
+                ypos = {}
+                self.ev_ypos[ix] = ypos
+            else:
+                ypos = self.ev_ypos[ix]
+            if l in ypos:
+                y = ypos[l]
+            else:
+                y = len(ypos)
+                ypos[l] = y
+            self.ev_labels[ix] = l
+            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
+        x = int(s.values['ts']) / 1e9
+        y = int(s.values['buffer-pts']) / 1e9
+        pad_file.write('%f %f\n' % (x, y))
+
     def handle_tracer_entry(self, event):
         if event[Parser.F_FUNCTION]:
             return
@@ -109,35 +193,13 @@ class TsPlot(Analyzer):
                 ix = int(s.values['ix'])
                 self.pad_names[ix] = "%s.%s" % (parent_name, s.values['name'])
         elif entry_name == 'event':
-            # build a [ts, event-name] data file
+            self._log_event(s)
-            ix = int(s.values['pad-ix'])
-            pad_file = self._get_data_file(self.ev_files, ix, '%s/ev_%d_%s.dat')
-            if pad_file:
-                # convert timestamps to seconds
-                x = int(s.values['ts']) / 1e9
-                l = s.values['name']
-                if l == self.ev_labels.get(ix):
-                    # omit repeated labels for readability
-                    pad_file.write('%f ""\n' % x)
-                else:
-                    pad_file.write('%f "%s"\n' % (x, l))
-                    self.ev_labels[ix] = l
         else:  # 'buffer'
-            if int(s.values['have-buffer-pts']):
+            self._log_buffer(s)
-                # 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 pad_file:
-                    flags = int(s.values['buffer-flags'])
-                    if flags & _GST_BUFFER_FLAG_DISCONT:
-                        pad_file.write('\n')
-                    # convert timestamps to e.g. seconds
-                    x = int(s.values['ts']) / 1e9
-                    y = int(s.values['buffer-pts']) / 1e9
-                    pad_file.write('%f %f\n' % (x, y))
 
     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)
@@ -147,9 +209,10 @@ class TsPlot(Analyzer):
             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)
+            ypos_max = (2 + len(self.ev_ypos[ix])) * -10
             script += _PLOT_SCRIPT_BODY.substitute(self.params, pad_name=name,
                 buf_file_name=buf_file_name, ev_file_name=ev_file_name,
-                png_file_name=png_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'))
@@ -172,7 +235,7 @@ if __name__ == '__main__':
     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='1600x300',
+    parser.add_argument('-s', '--size', action='store', default='1600x400',
                         help='graph size as WxH')
     args = parser.parse_args()