plotting: add a all-in-one plot

Refine pad logging to produce same output in all paths. Make splitlog create
one log for all pad transfers. Add a new plot script.

5 files changed, 157 insertions, 32 deletions

diff --git a/src/Makefile.am b/src/Makefile.am
index ade7ad6..7490f8d 100644
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -7,7 +7,7 @@ libgsttracelib_la_CFLAGS = $(BASE_DEPS_CFLAGS)
 libgsttracelib_la_LDFLAGS = -module -avoid-version
 libgsttracelib_la_LIBTOOLFLAGS = --tag=disable-static
 
-dist_bin_SCRIPTS = gsttl gsttl_splitlog.py gsttl_plot.sh
+dist_bin_SCRIPTS = gsttl gsttl_splitlog.py gsttl_plot.sh gsttl_plot1.sh
 
 EXTRA_DIST = gsttl.in
 
diff --git a/src/gsttl_plot.sh b/src/gsttl_plot.sh
index 7ef50f9..5496437 100755
--- a/src/gsttl_plot.sh
+++ b/src/gsttl_plot.sh
@@ -60,7 +60,7 @@ plt_ev_origin=`echo "scale=4;1.0-($height1*9.0)" | bc`
 plt_msg_origin=`echo "scale=4;1.0-($height1*11.0)" | bc`
 plt_qry_origin=`echo "scale=4;1.0-($height1*13.0)" | bc`
 
-last_ts=`tail -qn1 $base/*.log | cut -d' ' -f2 | sort -n | tail -n1`
+last_ts=`grep -v "sync_times" ${base}.log | cut -d' ' -f3 | sort -n | tail -n1`
 
 # debugging
 cat <<EOF
@@ -125,7 +125,8 @@ plot \\
   '' using 2:3 axes x1y1 with points title 'bytes', \\
   '' using 2:4 axes x1y1 with points title 'offset', \\
   '' using 2:5 axes x1y2 with points title 'ts', \\
-  '' using 2:6 axes x1y2 with dots smooth frequency title 'scheduling'
+  '' using 2:(0):(0):(\$6*20000) axes x1y1 with vectors title 'discont', \\
+  '' using 2:7 axes x1y2 with dots smooth frequency title 'scheduling'
 
 # some failed attempts to get averages into the dot plots
 #  sum = init(0), \\
diff --git a/src/gsttl_plot1.sh b/src/gsttl_plot1.sh
new file mode 100755
index 0000000..3dfa4c3
--- /dev/null
+++ b/src/gsttl_plot1.sh
@@ -0,0 +1,106 @@
+#!/bin/bash
+# dumps a gnuplot script to stdout that does a multiplot of the given logs
+#
+# TODO:
+# - show more statistics:
+#   http://gnuplot-tricks.blogspot.com/2009/11/some-basic-statistics-with-gnuplot.html
+#
+
+usage="\
+Usage: gsttl_plot.sh [--title=<title>] [--base==<basedir>] [--format={png,pdf,ps,svg}] [--pagesize={a3,a4}]| gnuplot"
+
+# default options
+title="GStreamer profile"
+base="/tmp/gsttl"
+format="svg"
+pagesize="a3"
+
+# process commandline options
+# @todo: add support for single letter options
+while true; do
+  case "X$1" in
+    X--version) echo "0.1"; exit 0;;
+    X--help) echo "$usage"; exit 0;;
+    X--title=*) title=`echo $1 | sed s/.*=//`; shift;;
+    X--base=*) base=`echo $1 | sed s/.*=//`; shift;;
+    X--format=*) format=`echo $1 | sed s/.*=//`; shift;;
+    X--pagesize=*) pagesize=`echo $1 | sed s/.*=//`; shift;;
+    X--*) shift;;
+    X*) break;;
+  esac
+done
+
+# sanity checks
+if [ ! -e $base ]; then
+  echo "Error: No datafiles in $base";
+  echo "${usage}" 1>&2
+  exit 1
+fi
+
+num_padlogs=`ls -1 $base/pad*.log | wc -l`
+
+#  layout
+plot_width=6400
+plot_height=600
+
+last_ts=`grep -v "sync_times" ${base}.log | cut -d' ' -f3 | sort -n | tail -n1`
+
+# configure output
+# http://en.wikipedia.org/wiki/Paper_size
+case $pagesize in
+  a3) page_with="29.7 cm";page_height="42.0 cm";;
+  a4) page_with="21.0 cm";page_height="29.7 cm";;
+esac
+# http://www.gnuplot.info/docs/node341.html (terminal options)
+case $format in
+  # this doen't like fonts
+  png) echo "set term png truecolor font \"Sans,5\" size $plot_width,$plot_height";;
+  # pdf makes a new page for each plot :/
+  pdf) echo "set term pdf color font \"Sans,5\" size $page_with,$page_height";;
+  ps) echo "set term postscript portrait color solid \"Sans\" 7 size $page_with,$page_height";;
+  svg) echo "set term svg size $plot_width,$plot_height font \"Sans,7\"";;
+esac
+cat <<EOF
+set output '$base.$format'
+
+set lmargin 20
+set rmargin 20
+
+set pointsize 1.0
+
+unset xlabel
+unset xtics
+set xlabel "Time (sec.msec)"
+set ytics nomirror autofreq
+set xtics format "%g"
+set xrange [0:$last_ts]
+set ylabel "Pads"
+set ytics nomirror autofreq
+set yrange [*:*]
+set grid
+set key box
+
+plot \\
+  '$base/data.log' using 2:8:yticlabels(9) axes x1y1 with points title 'data', \\
+  '$base/caps_get.log' using 2:3:yticlabels(4) axes x1y1 with points title 'get', \\
+  '$base/caps_set.log' using 2:3:yticlabels(4) axes x1y1 with points title 'set', \\
+  '$base/ev_eos.log' using 2:3:(0):(\$5-\$3):yticlabels(4) axes x1y1 with vectors title 'eos', \\
+  '$base/ev_newsegment.log' using 2:3:(0):(\$5-\$3):yticlabels(4) axes x1y1 with vectors title 'newsegment', \\
+  '$base/ev_seek.log' using 2:3:(0):(\$5-\$3):yticlabels(4) axes x1y1 with vectors title 'seek', \\
+  '$base/ev_tag.log' using 2:3:(0):(\$5-\$3):yticlabels(4) axes x1y1 with vectors title 'tag', \\
+  '$base/msg_async-done.log' using 2:3:yticlabels(4) axes x1y1 with points title 'async-done', \\
+  '$base/msg_async-start.log' using 2:3:yticlabels(4) axes x1y1 with points title 'async-start', \\
+  '$base/msg_clock-lost.log' using 2:3:yticlabels(4) axes x1y1 with points title 'clock-lost', \\
+  '$base/msg_clock-provide.log' using 2:3:yticlabels(4) axes x1y1 with points title 'clock-provide', \\
+  '$base/msg_duration.log' using 2:3:yticlabels(4) axes x1y1 with points title 'duration', \\
+  '$base/msg_element.log' using 2:3:yticlabels(4) axes x1y1 with points title 'element', \\
+  '$base/msg_eos.log' using 2:3:yticlabels(4) axes x1y1 with points title 'eos', \\
+  '$base/msg_new-clock.log' using 2:3:yticlabels(4) axes x1y1 with points title 'new-clock', \\
+  '$base/msg_state-changed.log' using 2:3:yticlabels(4) axes x1y1 with points title 'state-changed', \\
+  '$base/msg_structure-change.log' using 2:3:yticlabels(4) axes x1y1 with points title 'structure-change', \\
+  '$base/msg_tag.log' using 2:3:yticlabels(4) axes x1y1 with points title 'tag', \\
+  '$base/qry_duration.log' using 2:3:yticlabels(4) axes x1y1 with points title 'duration', \\
+  '$base/qry_latency.log' using 2:3:yticlabels(4) axes x1y1 with points title 'latency', \\
+  '$base/qry_position.log' using 2:3:yticlabels(4) axes x1y1 with points title 'position'
+
+EOF
diff --git a/src/gsttl_splitlog.py b/src/gsttl_splitlog.py
index 6bf2003..6c9a2c4 100755
--- a/src/gsttl_splitlog.py
+++ b/src/gsttl_splitlog.py
@@ -19,38 +19,46 @@ def main():
     file_name=sys.argv[1]
   else:
     file_name='/tmp/gsttl.log'
-    
+
   # get directory name and create dir for results
   (dir_name,ext)=os.path.splitext(file_name)
   if not os.path.exists(dir_name):
     os.mkdir(dir_name)
-  
+
   try:
     f=open(file_name, 'r')
   except IOError, e:              # catch IOErrors, e is the instance
     print "Can't open log file %s for reading: " % file_name, e # print exception info if thrown
     exit(1);
-  
+
   # iterate over log and split
-  fds = {};
+  fds = {}
   for line in f:
     (key,sep,data)=line.partition(' ');
-  
+
     fd=fds.get(key)
     if fd == None:
       fd=open("%s/%s.log" % (dir_name,key), 'w')
       fds[key]=fd
-  
+
     # hack to ensure locale independent float format
     data=str.replace(data, ",", ".")
     fd.write(data)
-  
+
+    if key.startswith('pad_'):
+      fd=fds.get('data')
+      if fd == None:
+        fd=open("%s/data.log" % dir_name, 'w')
+        fds['data']=fd
+      fd.write("%s %s\n" % (data[:-1],key[4:]))
+
   print "splitted %s into %d separate logs under %s" % (file_name, len(fds), dir_name)
   # close all files
   f.close()
   for fd in fds.values():
     fd.close()
-  
+
+  # iterate over logs and sort by ts
   for key in fds.keys():
     f=open("%s/%s.log" % (dir_name,key), 'r')
     lines = []
@@ -63,7 +71,7 @@ def main():
     for line in lines:
       f.write(line)
     f.close();
-  
+
   print "sorted all logs by timestamp"
 
 if __name__ == '__main__':
diff --git a/src/gsttracelib.c b/src/gsttracelib.c
index 46cd715..567008c 100644
--- a/src/gsttracelib.c
+++ b/src/gsttracelib.c
@@ -1115,17 +1115,21 @@ gst_pad_push (GstPad *pad, GstBuffer *buffer)
     if (GST_CLOCK_TIME_IS_VALID (stats->last_ts)) {
       sched_jitter = GST_CLOCK_DIFF (stats->last_ts, elapsed1);
       _log_entry(
-        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT " %lf %lf\n",
+        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT " %lf %d %lf %d\n",
         stats->name, GST_TIME_ARGS (elapsed1), GSTTL_TIME_AS_SECOND (elapsed1),
         GST_BUFFER_SIZE (buffer), GST_BUFFER_OFFSET (buffer),
         GSTTL_TIME_AS_SECOND (GST_BUFFER_TIMESTAMP (buffer)),
-        GSTTL_TIME_AS_SECOND (sched_jitter));
+        GST_BUFFER_IS_DISCONT(buffer),
+        GSTTL_TIME_AS_SECOND (sched_jitter),
+        stats->index);
     } else {
       _log_entry(
-        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT " %lf \n",
+        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT " %lf %d 0.0 %d\n",
         stats->name, GST_TIME_ARGS (elapsed1), GSTTL_TIME_AS_SECOND (elapsed1),
         GST_BUFFER_SIZE (buffer), GST_BUFFER_OFFSET (buffer),
-        GSTTL_TIME_AS_SECOND (GST_BUFFER_TIMESTAMP (buffer)));
+        GSTTL_TIME_AS_SECOND (GST_BUFFER_TIMESTAMP (buffer)),
+        GST_BUFFER_IS_DISCONT(buffer),
+        stats->index);
     }
   }
 
@@ -1171,22 +1175,6 @@ gst_pad_pull_range (GstPad * pad, guint64 offset, guint size, GstBuffer ** buffe
   if(!stats)
     return orig_pad_pull_range (pad, offset, size, buffer);
 
-  if (gsttl_do_log_pad) {
-    if (GST_CLOCK_TIME_IS_VALID (stats->last_ts)) {
-      sched_jitter = GST_CLOCK_DIFF (stats->last_ts, elapsed1);
-      _log_entry(
-        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT" 0.0 %lf\n",
-        stats->name, GST_TIME_ARGS (elapsed1), GSTTL_TIME_AS_SECOND (elapsed1),
-        size, offset,
-        GSTTL_TIME_AS_SECOND (sched_jitter));
-    } else {
-      _log_entry(
-        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT " 0.0\n",
-        stats->name, GST_TIME_ARGS (elapsed1), GSTTL_TIME_AS_SECOND (elapsed1),
-        size, offset);
-    }
-  }
-
   /* switch cpu-load logging on/off */
   parent = GST_OBJECT_PARENT (pad);
   if (parent && GST_IS_PAD (parent)) {
@@ -1199,6 +1187,28 @@ gst_pad_pull_range (GstPad * pad, guint64 offset, guint size, GstBuffer ** buffe
   elapsed2 = _get_elapsed();
   _log_common (elapsed2);
 
+  if (gsttl_do_log_pad) {
+    if (GST_CLOCK_TIME_IS_VALID (stats->last_ts)) {
+      sched_jitter = GST_CLOCK_DIFF (stats->last_ts, elapsed1);
+      _log_entry(
+        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT" %lf %d %lf %d\n",
+        stats->name, GST_TIME_ARGS (elapsed1), GSTTL_TIME_AS_SECOND (elapsed1),
+        size, offset,
+        GSTTL_TIME_AS_SECOND (GST_BUFFER_TIMESTAMP (buffer)),
+        GST_BUFFER_IS_DISCONT (buffer),
+        GSTTL_TIME_AS_SECOND (sched_jitter),
+        stats->index);
+    } else {
+      _log_entry(
+        "pad_%s %" GST_TIME_FORMAT " %lf %u %" G_GUINT64_FORMAT " %lf %d 0.0 %d\n",
+        stats->name, GST_TIME_ARGS (elapsed1), GSTTL_TIME_AS_SECOND (elapsed1),
+        size, offset,
+        GSTTL_TIME_AS_SECOND (GST_BUFFER_TIMESTAMP (buffer)),
+        GST_BUFFER_IS_DISCONT(buffer),
+        stats->index);
+    }
+  }
+
   /* statistics */
   if(!gsttl_no_stats) {
     if(*buffer) {