stats: add a stats frontend

Parse the log and collect data from tracer messages.

plugins/tracers/gststats.c

@@ -42,70 +42,71 @@ G_DEFINE_TYPE_WITH_CODE (GstStatsTracer, gst_stats_tracer, GST_TYPE_TRACER,
 
 typedef struct
 {
-  /* human readable pad name and details */
+  /* we can't rely on the address to be unique over time */
-  gchar *name;
   guint index;
-  GType type;
+  /* for pre + post */
-  GstPadDirection dir;
+  GstClockTime last_ts;
-  /* buffer statistics */
+  /* hierarchy */
-  guint num_buffers;
+  guint parent_ix;
-  guint num_discont, num_gap, num_delta;
-  guint min_size, max_size, avg_size;
-  /* first and last activity on the pad, expected next_ts */
-  GstClockTime first_ts, last_ts, next_ts;
-  /* in which thread does it operate */
-  gpointer thread_id;
 } GstPadStats;
 
 typedef struct
 {
-  /* human readable element name */
+  /* we can't rely on the address to be unique over time */
-  gchar *name;
   guint index;
-  GType type;
+  /* for pre + post */
-  /* buffer statistics */
+  GstClockTime last_ts;
-  guint recv_buffers, sent_buffers;
-  guint64 recv_bytes, sent_bytes;
-  /* event, message statistics */
-  guint num_events, num_messages, num_queries;
-  /* first activity on the element */
-  GstClockTime first_ts, last_ts;
   /* time spend in this element */
   GstClockTime treal;
   /* hierarchy */
   guint parent_ix;
 } GstElementStats;
 
+/* logging */
+
+static void
+log_trace (GstStructure * s)
+{
+  gchar *data;
+
+  // TODO(ensonic): use a GVariant?
+  data = gst_structure_to_string (s);
+  GST_TRACE ("%s", data);
+  g_free (data);
+  gst_structure_free (s);
+}
+
 /* data helper */
 
+static GstElementStats no_elem_stats = { 0, };
+
 static GstElementStats *
 fill_element_stats (GstStatsTracer * self, GstElement * element)
 {
   GstElementStats *stats = g_slice_new0 (GstElementStats);
 
-  if (GST_IS_BIN (element)) {
-    self->num_bins++;
-  }
   stats->index = self->num_elements++;
-  stats->type = G_OBJECT_TYPE (element);
-  stats->first_ts = GST_CLOCK_TIME_NONE;
   stats->parent_ix = G_MAXUINT;
+
+  log_trace (gst_structure_new ("new-element",
+          "ix", G_TYPE_UINT, stats->index,
+          "name", G_TYPE_STRING, GST_OBJECT_NAME (element),
+          "type", G_TYPE_STRING, G_OBJECT_TYPE_NAME (element),
+          "is-bin", G_TYPE_BOOLEAN, GST_IS_BIN (element), NULL));
+
   return stats;
 }
 
-#if 0
-static GstElementStats *
-get_element_stats_by_id (GstStatsTracer * self, guint ix)
-{
-  return g_ptr_array_index (self->elements, ix);
-}
-#endif
-
 static inline GstElementStats *
 get_element_stats (GstStatsTracer * self, GstElement * element)
 {
   GstElementStats *stats;
 
+  if (!element) {
+    no_elem_stats.index = G_MAXUINT;
+    return &no_elem_stats;
+  }
+
   G_LOCK (_stats);
   if (!(stats = g_object_get_qdata ((GObject *) element, data_quark))) {
     stats = fill_element_stats (self, element);
@@ -122,11 +123,6 @@ get_element_stats (GstStatsTracer * self, GstElement * element)
       stats->parent_ix = parent_stats->index;
     }
   }
-  if (G_UNLIKELY (!stats->name)) {
-    if (GST_OBJECT_NAME (element)) {
-      stats->name = g_strdup (GST_OBJECT_NAME (element));
-    }
-  }
   return stats;
 }
 
@@ -136,30 +132,75 @@ free_element_stats (gpointer data)
   g_slice_free (GstElementStats, data);
 }
 
+static GstPadStats no_pad_stats = { 0, };
+
 static GstPadStats *
 fill_pad_stats (GstStatsTracer * self, GstPad * pad)
 {
   GstPadStats *stats = g_slice_new0 (GstPadStats);
 
-  if (GST_IS_GHOST_PAD (pad)) {
-    self->num_ghostpads++;
-  }
   stats->index = self->num_pads++;
-  stats->type = G_OBJECT_TYPE (pad);
+  stats->parent_ix = G_MAXUINT;
-  stats->dir = GST_PAD_DIRECTION (pad);
+
-  stats->min_size = G_MAXUINT;
+  log_trace (gst_structure_new ("new-pad",
-  stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE;
+          "ix", G_TYPE_UINT, stats->index,
-  stats->thread_id = g_thread_self ();
+          "name", G_TYPE_STRING, GST_OBJECT_NAME (pad),
+          "type", G_TYPE_STRING, G_OBJECT_TYPE_NAME (pad),
+          "is-ghostpad", G_TYPE_BOOLEAN, GST_IS_GHOST_PAD (pad),
+          "pad-direction", GST_TYPE_PAD_DIRECTION, GST_PAD_DIRECTION (pad),
+          "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (g_thread_self ()), NULL));
+
   return stats;
 }
 
+/*
+ * Get the element/bin owning the pad. 
+ *
+ * in: a normal pad
+ * out: the element
+ *
+ * in: a proxy pad
+ * out: the element that contains the peer of the proxy
+ *
+ * in: a ghost pad
+ * out: the bin owning the ghostpad
+ */
+/* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
+ * add this as new api, e.g. gst_pad_find_parent_element();
+ */
+static GstElement *
+get_real_pad_parent (GstPad * pad)
+{
+  GstObject *parent;
+
+  if (!pad)
+    return NULL;
+
+  parent = GST_OBJECT_PARENT (pad);
+
+  /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
+  if (parent && GST_IS_GHOST_PAD (parent)) {
+    pad = GST_PAD_CAST (parent);
+    parent = GST_OBJECT_PARENT (pad);
+  }
+  /* if pad is a ghost-pad, then parent is a bin and it is the parent of a
+   * proxy_pad */
+  while (parent && GST_IS_GHOST_PAD (pad)) {
+    pad = gst_ghost_pad_get_target (GST_GHOST_PAD (pad));
+    parent = pad ? GST_OBJECT_PARENT (pad) : NULL;
+  }
+  return GST_ELEMENT_CAST (parent);
+}
+
 static GstPadStats *
 get_pad_stats (GstStatsTracer * self, GstPad * pad)
 {
   GstPadStats *stats;
 
-  if (!pad)
+  if (!pad) {
-    return NULL;
+    no_pad_stats.index = G_MAXUINT;
+    return &no_pad_stats;
+  }
 
   G_LOCK (_stats);
   if (!(stats = g_object_get_qdata ((GObject *) pad, data_quark))) {
@@ -170,25 +211,12 @@ get_pad_stats (GstStatsTracer * self, GstPad * pad)
     g_ptr_array_index (self->pads, stats->index) = stats;
   }
   G_UNLOCK (_stats);
-  if (G_UNLIKELY (!stats->name)) {
+  if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
-    GstObject *parent = GST_OBJECT_PARENT (pad);
+    GstElement *elem = get_real_pad_parent (pad);
-    /* yes we leak the names right now ... */
+    if (elem) {
-    if (GST_IS_ELEMENT (parent)) {
+      GstElementStats *elem_stats = get_element_stats (self, elem);
-      /* pad is regular pad */
+
-      get_element_stats (self, GST_ELEMENT_CAST (parent));
+      stats->parent_ix = elem_stats->index;
-      if (GST_OBJECT_NAME (parent) && GST_OBJECT_NAME (pad)) {
-        stats->name =
-            g_strdup_printf ("%s_%s", GST_OBJECT_NAME (parent),
-            GST_OBJECT_NAME (pad));
-      }
-    } else if (GST_IS_GHOST_PAD (parent)) {
-      /* pad is proxy pad */
-      get_pad_stats (self, GST_PAD_CAST (parent));
-      if (GST_OBJECT_NAME (parent) && GST_OBJECT_NAME (pad)) {
-        stats->name =
-            g_strdup_printf ("%s_%s", GST_OBJECT_NAME (parent),
-            GST_OBJECT_NAME (pad));
-      }
     }
   }
   return stats;
@@ -201,161 +229,30 @@ free_pad_stats (gpointer data)
 }
 
 static void
-do_pad_stats (GstStatsTracer * self, GstPad * pad, GstPadStats * stats,
+do_buffer_stats (GstStatsTracer * self, GstPad * this_pad,
-    GstBuffer * buffer, GstClockTime elapsed)
+    GstPadStats * this_pad_stats, GstPad * that_pad,
+    GstPadStats * that_pad_stats, GstBuffer * buf, GstClockTime elapsed)
 {
-  guint size = gst_buffer_get_size (buffer);
+  GstElement *this_elem = get_real_pad_parent (this_pad);
-  gulong avg_size;
+  GstElementStats *this_elem_stats = get_element_stats (self, this_elem);
+  GstElement *that_elem = get_real_pad_parent (that_pad);
+  GstElementStats *that_elem_stats = get_element_stats (self, that_elem);
 
-  self->num_buffers++;
+  /* TODO(ensonic): need a quark-table (shared with the tracer-front-ends?) */
-  /* size stats */
+  log_trace (gst_structure_new ("buffer",
-  avg_size = (((gulong) stats->avg_size * (gulong) stats->num_buffers) + size);
+          "ts", G_TYPE_UINT64, elapsed,
-  stats->num_buffers++;
+          "pad-ix", G_TYPE_UINT, this_pad_stats->index,
-  stats->avg_size = (guint) (avg_size / stats->num_buffers);
+          "elem-ix", G_TYPE_UINT, this_elem_stats->index,
-  if (size < stats->min_size)
+          "peer-pad-ix", G_TYPE_UINT, that_pad_stats->index,
-    stats->min_size = size;
+          "peer-elem-ix", G_TYPE_UINT, that_elem_stats->index,
-  else if (size > stats->max_size)
+          "buffer-size", G_TYPE_UINT, gst_buffer_get_size (buf),
-    stats->max_size = size;
+          "buffer-ts", G_TYPE_UINT64, GST_BUFFER_TIMESTAMP (buf),
-  /* time stats */
+          "buffer-duration", G_TYPE_UINT64, GST_BUFFER_DURATION (buf),
-  if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (stats->first_ts)))
+          "buffer-flags", GST_TYPE_BUFFER_FLAGS, GST_BUFFER_FLAGS (buf),
-    stats->first_ts = elapsed;
+          /*
-  stats->last_ts = elapsed;
+             scheduling-jitter: for this we need the last_ts on the pad
-  /* flag stats */
+           */
-  if (GST_BUFFER_FLAG_IS_SET (buffer, GST_BUFFER_FLAG_GAP))
+          NULL));
-    stats->num_gap++;
-  if (GST_BUFFER_FLAG_IS_SET (buffer, GST_BUFFER_FLAG_DELTA_UNIT))
-    stats->num_delta++;
-  if (GST_BUFFER_FLAG_IS_SET (buffer, GST_BUFFER_FLAG_DISCONT))
-    stats->num_discont++;
-  /* TODO(ensonic): there is a bunch of new flags in 1.0 */
-
-  /* update timestamps */
-  if (GST_BUFFER_TIMESTAMP_IS_VALID (buffer) +
-      GST_BUFFER_DURATION_IS_VALID (buffer)) {
-    stats->next_ts =
-        GST_BUFFER_TIMESTAMP (buffer) + GST_BUFFER_DURATION (buffer);
-  } else {
-    stats->next_ts = GST_CLOCK_TIME_NONE;
-  }
-}
-
-static void
-do_transmission_stats (GstStatsTracer * self, GstPad * pad, GstBuffer * buf,
-    GstClockTime elapsed)
-{
-  GstObject *parent = GST_OBJECT_PARENT (pad);
-  GstElement *this =
-      GST_ELEMENT_CAST (GST_IS_PAD (parent) ? GST_OBJECT_PARENT (parent) :
-      parent);
-  GstElementStats *this_stats = get_element_stats (self, this);
-  GstPad *peer_pad = GST_PAD_PEER (pad);
-  GstElementStats *peer_stats;
-  GSList *bin_i_stats = NULL, *bin_o_stats = NULL;
-  GstPadStats *peer_pad_stats;
-
-  if (!peer_pad)
-    return;
-
-  parent = GST_OBJECT_PARENT (peer_pad);
-#ifdef _ENABLE_BLACK_MAGIC_
-  /* walk the ghost pad chain downstream to get the real pad */
-  /* if parent of peer_pad is a ghost-pad, then peer_pad is a proxy_pad */
-  while (parent && GST_IS_GHOST_PAD (parent)) {
-    peer_pad = GST_PAD_CAST (parent);
-    /* if this is now the ghost pad, get the peer of this */
-    get_pad_stats (self, peer_pad);
-    if (parent = GST_OBJECT_PARENT (peer_pad)) {
-      peer_stats = get_element_stats (self, GST_ELEMENT_CAST (parent));
-      bin_o_stats = g_slist_prepend (bin_o_stats, peer_stats);
-    }
-    peer_pad = GST_PAD_PEER (GST_GHOST_PAD_CAST (peer_pad));
-    parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
-  }
-  /* walk the ghost pad chain upstream to get the real pad */
-  /* if peer_pad is a ghost-pad, then parent is a bin adn it is the parent of
-   * a proxy_pad */
-  while (peer_pad && GST_IS_GHOST_PAD (peer_pad)) {
-    get_pad_stats (self, peer_pad);
-    peer_stats = get_element_stats (self, GST_ELEMENT_CAST (parent));
-    bin_i_stats = g_slist_prepend (bin_i_stats, peer_stats);
-    peer_pad = gst_ghost_pad_get_target (GST_GHOST_PAD_CAST (peer_pad));
-    parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
-  }
-#else
-  if (parent && GST_IS_GHOST_PAD (parent)) {
-    peer_pad = GST_PAD_CAST (parent);
-    parent = GST_OBJECT_PARENT (peer_pad);
-  }
-#endif
-
-  if (!parent) {
-    fprintf (stderr,
-        "%" GST_TIME_FORMAT " transmission on unparented target pad%s_%s\n",
-        GST_TIME_ARGS (elapsed), GST_DEBUG_PAD_NAME (peer_pad));
-    return;
-  }
-  peer_stats = get_element_stats (self, GST_ELEMENT_CAST (parent));
-
-  peer_pad_stats = get_pad_stats (self, peer_pad);
-  do_pad_stats (self, peer_pad, peer_pad_stats, buf, elapsed);
-
-  if (GST_PAD_DIRECTION (pad) == GST_PAD_SRC) {
-    /* push */
-    this_stats->sent_buffers++;
-    peer_stats->recv_buffers++;
-    this_stats->sent_bytes += gst_buffer_get_size (buf);
-    peer_stats->recv_bytes += gst_buffer_get_size (buf);
-    /* time stats */
-    if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (this_stats->first_ts))) {
-      this_stats->first_ts = elapsed;
-      //printf("%" GST_TIME_FORMAT " %s pushes on %s\n",GST_TIME_ARGS(elapsed),this_stats->name,peer_stats->name);
-    }
-    if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (peer_stats->first_ts))) {
-      peer_stats->first_ts = elapsed + 1;
-      //printf("%" GST_TIME_FORMAT " %s is beeing pushed from %s\n",GST_TIME_ARGS(elapsed),peer_stats->name,this_stats->name);
-    }
-#ifdef _ENABLE_BLACK_MAGIC_
-    for (node = bin_o_stats; node; node = g_slist_next (node)) {
-      peer_stats = node->data;
-      peer_stats->sent_buffers++;
-      peer_stats->sent_bytes += gst_buffer_get_size (buf);
-    }
-    for (node = bin_i_stats; node; node = g_slist_next (node)) {
-      peer_stats = node->data;
-      peer_stats->recv_buffers++;
-      peer_stats->recv_bytes += gst_buffer_get_size (buf);
-    }
-#endif
-  } else {
-    /* pull */
-    peer_stats->sent_buffers++;
-    this_stats->recv_buffers++;
-    peer_stats->sent_bytes += gst_buffer_get_size (buf);
-    this_stats->recv_bytes += gst_buffer_get_size (buf);
-    /* time stats */
-    if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (this_stats->first_ts))) {
-      this_stats->first_ts = elapsed + 1;
-      //printf("%" GST_TIME_FORMAT " %s pulls from %s\n",GST_TIME_ARGS(elapsed),this_stats->name,peer_stats->name);
-    }
-    if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (peer_stats->first_ts))) {
-      peer_stats->first_ts = elapsed;
-      //printf("%" GST_TIME_FORMAT " %s is beeing pulled from %s\n",GST_TIME_ARGS(elapsed),peer_stats->name,this_stats->name);
-    }
-#ifdef _ENABLE_BLACK_MAGIC_
-    for (node = bin_i_stats; node; node = g_slist_next (node)) {
-      peer_stats = node->data;
-      peer_stats->sent_buffers++;
-      peer_stats->sent_bytes += gst_buffer_get_size (buf);
-    }
-    for (node = bin_o_stats; node; node = g_slist_next (node)) {
-      peer_stats = node->data;
-      peer_stats->recv_buffers++;
-      peer_stats->recv_bytes += gst_buffer_get_size (buf);
-    }
-#endif
-  }
-  g_slist_free (bin_o_stats);
-  g_slist_free (bin_i_stats);
 }
 
 static void
@@ -398,11 +295,9 @@ do_element_stats (GstStatsTracer * self, GstPad * pad, GstClockTime elapsed1,
   }
 
   if (!parent) {
-    GstPadStats *pad_stats = get_pad_stats (self, pad);
-
     printf ("%" GST_TIME_FORMAT
-        " transmission on unparented target pad %s -> %s_%s\n",
+        " transmission on unparented target pad %s_%s -> %s_%s\n",
-        GST_TIME_ARGS (elapsed), pad_stats->name,
+        GST_TIME_ARGS (elapsed), GST_DEBUG_PAD_NAME (pad),
         GST_DEBUG_PAD_NAME (peer_pad));
     return;
   }
@@ -435,36 +330,6 @@ do_element_stats (GstStatsTracer * self, GstPad * pad, GstClockTime elapsed1,
 #endif
 }
 
-/* FIXME: this looks a bit weired, check that we really want to do this
- *
- * in: a normal pad
- * out: the element
- *
- * in: a proxy pad
- * out: the element that contains the peer of the proxy
- *
- * in: a ghost pad
- * out: the bin owning the ghostpad
- */
-static GstObject *
-get_real_pad_parent (GstPad * pad)
-{
-  GstObject *parent = GST_OBJECT_PARENT (pad);
-
-  /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
-  if (parent && GST_IS_GHOST_PAD (parent)) {
-    pad = GST_PAD_CAST (parent);
-    parent = GST_OBJECT_PARENT (pad);
-  }
-  /* if pad is a ghost-pad, then parent is a bin and it is the parent of a
-   * proxy_pad */
-  while (parent && GST_IS_GHOST_PAD (pad)) {
-    pad = gst_ghost_pad_get_target (GST_GHOST_PAD (pad));
-    parent = pad ? GST_OBJECT_PARENT (pad) : NULL;
-  }
-  return parent;
-}
-
 /* tracer class */
 
 static void gst_stats_tracer_finalize (GObject * obj);
@@ -492,16 +357,20 @@ gst_stats_tracer_init (GstStatsTracer * self)
   self->pads = g_ptr_array_new_with_free_func (free_pad_stats);
 }
 
+/* hooks */
+
 static void
 do_push_buffer_pre (GstStatsTracer * self, va_list var_args)
 {
   guint64 ts = va_arg (var_args, guint64);
-  GstPad *pad = va_arg (var_args, GstPad *);
+  GstPad *this_pad = va_arg (var_args, GstPad *);
   GstBuffer *buffer = va_arg (var_args, GstBuffer *);
-  GstPadStats *stats = get_pad_stats (self, pad);
+  GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
+  GstPad *that_pad = GST_PAD_PEER (this_pad);
+  GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
 
-  do_pad_stats (self, pad, stats, buffer, ts);
+  do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
-  do_transmission_stats (self, pad, buffer, ts);
+      buffer, ts);
 }
 
 static void
@@ -517,8 +386,10 @@ do_push_buffer_post (GstStatsTracer * self, va_list var_args)
 typedef struct
 {
   GstStatsTracer *self;
-  GstPad *pad;
+  GstPad *this_pad;
-  GstPadStats *stats;
+  GstPadStats *this_pad_stats;
+  GstPad *that_pad;
+  GstPadStats *that_pad_stats;
   guint64 ts;
 } DoPushBufferListArgs;
 
@@ -527,8 +398,8 @@ do_push_buffer_list_item (GstBuffer ** buffer, guint idx, gpointer user_data)
 {
   DoPushBufferListArgs *args = (DoPushBufferListArgs *) user_data;
 
-  do_pad_stats (args->self, args->pad, args->stats, *buffer, args->ts);
+  do_buffer_stats (args->self, args->this_pad, args->this_pad_stats,
-  do_transmission_stats (args->self, args->pad, *buffer, args->ts);
+      args->that_pad, args->that_pad_stats, *buffer, args->ts);
   return TRUE;
 }
 
@@ -536,10 +407,14 @@ static void
 do_push_buffer_list_pre (GstStatsTracer * self, va_list var_args)
 {
   guint64 ts = va_arg (var_args, guint64);
-  GstPad *pad = va_arg (var_args, GstPad *);
+  GstPad *this_pad = va_arg (var_args, GstPad *);
   GstBufferList *list = va_arg (var_args, GstBufferList *);
-  GstPadStats *stats = get_pad_stats (self, pad);
+  GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
-  DoPushBufferListArgs args = { self, pad, stats, ts };
+  GstPad *that_pad = GST_PAD_PEER (this_pad);
+  GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
+  DoPushBufferListArgs args = { self, this_pad, this_pad_stats, that_pad,
+    that_pad_stats, ts
+  };
 
   gst_buffer_list_foreach (list, do_push_buffer_list_item, &args);
 }
@@ -555,7 +430,7 @@ do_push_buffer_list_post (GstStatsTracer * self, va_list var_args)
 }
 
 static void
-do_pull_range_list_pre (GstStatsTracer * self, va_list var_args)
+do_pull_range_pre (GstStatsTracer * self, va_list var_args)
 {
   guint64 ts = va_arg (var_args, guint64);
   GstPad *pad = va_arg (var_args, GstPad *);
@@ -564,19 +439,21 @@ do_pull_range_list_pre (GstStatsTracer * self, va_list var_args)
 }
 
 static void
-do_pull_range_list_post (GstStatsTracer * self, va_list var_args)
+do_pull_range_post (GstStatsTracer * self, va_list var_args)
 {
   guint64 ts = va_arg (var_args, guint64);
-  GstPad *pad = va_arg (var_args, GstPad *);
+  GstPad *this_pad = va_arg (var_args, GstPad *);
   GstBuffer *buffer = va_arg (var_args, GstBuffer *);
-  GstPadStats *stats = get_pad_stats (self, pad);
+  GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
-  guint64 last_ts = stats->last_ts;
+  guint64 last_ts = this_pad_stats->last_ts;
+  GstPad *that_pad = GST_PAD_PEER (this_pad);
+  GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
 
   if (buffer != NULL) {
-    do_pad_stats (self, pad, stats, buffer, ts);
+    do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
-    do_transmission_stats (self, pad, buffer, ts);
+        buffer, ts);
   }
-  do_element_stats (self, pad, last_ts, ts);
+  do_element_stats (self, this_pad, last_ts, ts);
 }
 
 static void
@@ -584,18 +461,15 @@ do_push_event_pre (GstStatsTracer * self, va_list var_args)
 {
   guint64 ts = va_arg (var_args, guint64);
   GstPad *pad = va_arg (var_args, GstPad *);
-  GstObject *parent;
+  GstElement *elem = get_real_pad_parent (pad);
-  GstElement *elem;
+  GstPadStats *pad_stats = get_pad_stats (self, pad);
+  GstElementStats *elem_stats = get_element_stats (self, elem);
 
-  parent = get_real_pad_parent (pad);
+  elem_stats->last_ts = ts;
-  if ((elem = GST_ELEMENT (parent))) {
+  log_trace (gst_structure_new ("event",
-    GstElementStats *stats = get_element_stats (self, elem);
+          "ts", G_TYPE_UINT64, ts,
-    get_pad_stats (self, pad);
+          "pad-ix", G_TYPE_UINT, pad_stats->index,
-
+          "elem-ix", G_TYPE_UINT, elem_stats->index, NULL));
-    stats->last_ts = ts;
-    stats->num_events++;
-    self->num_events++;
-  }
 }
 
 static void
@@ -615,8 +489,8 @@ do_post_message_pre (GstStatsTracer * self, va_list var_args)
   GstElementStats *stats = get_element_stats (self, elem);
 
   stats->last_ts = ts;
-  stats->num_messages++;
+  log_trace (gst_structure_new ("message",
-  self->num_messages++;
+          "ts", G_TYPE_UINT64, ts, "elem-ix", G_TYPE_UINT, stats->index, NULL));
 }
 
 static void
@@ -636,8 +510,8 @@ do_query_pre (GstStatsTracer * self, va_list var_args)
   GstElementStats *stats = get_element_stats (self, elem);
 
   stats->last_ts = ts;
-  stats->num_queries++;
+  log_trace (gst_structure_new ("query",
-  self->num_queries++;
+          "ts", G_TYPE_UINT64, ts, "elem-ix", G_TYPE_UINT, stats->index, NULL));
 }
 
 static void
@@ -669,10 +543,10 @@ gst_stats_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
       do_push_buffer_list_post (self, var_args);
       break;
     case GST_TRACER_MESSAGE_ID_PAD_PULL_RANGE_PRE:
-      do_pull_range_list_pre (self, var_args);
+      do_pull_range_pre (self, var_args);
       break;
     case GST_TRACER_MESSAGE_ID_PAD_PULL_RANGE_POST:
-      do_pull_range_list_post (self, var_args);
+      do_pull_range_post (self, var_args);
       break;
     case GST_TRACER_MESSAGE_ID_PAD_PUSH_EVENT_PRE:
       do_push_event_pre (self, var_args);
@@ -700,21 +574,7 @@ gst_stats_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
 static void
 gst_stats_tracer_finalize (GObject * obj)
 {
-  GstStatsTracer *self = GST_STATS_TRACER_CAST (obj);
+  //GstStatsTracer *self = GST_STATS_TRACER_CAST (obj);
-
-  /* print overall stats */
-  puts ("\nOverall Statistics:");
-  printf ("Number of Elements: %u\n", self->num_elements - self->num_bins);
-  printf ("Number of Bins: %u\n", self->num_bins);
-  printf ("Number of Pads: %u\n", self->num_pads - self->num_ghostpads);
-  printf ("Number of GhostPads: %u\n", self->num_ghostpads);
-  printf ("Number of Buffers passed: %" G_GUINT64_FORMAT "\n",
-      self->num_buffers);
-  printf ("Number of Events sent: %" G_GUINT64_FORMAT "\n", self->num_events);
-  printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n",
-      self->num_messages);
-  printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", self->num_queries);
-  //printf("Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (self->last_ts));
 
   G_OBJECT_CLASS (parent_class)->finalize (obj);
 }

plugins/tracers/gststats.h

@@ -52,8 +52,7 @@ struct _GstStatsTracer {
   /*< private >*/
   GPtrArray *elements;
   GPtrArray *pads;
-  guint64 num_buffers, num_events, num_messages, num_queries;
+  guint num_elements, num_pads;
-  guint num_elements, num_bins, num_pads, num_ghostpads;
 };
 
 struct _GstStatsTracerClass {

tools/.gitignore

@@ -20,5 +20,6 @@ gst-typefind.1
 
 gst-inspect-?.?*
 gst-launch-?.?*
+gst-stats-?.?*
 gst-typefind-?.?*
 

tools/Makefile.am

@@ -1,12 +1,17 @@
 
 bin_PROGRAMS = \
 	gst-inspect-@GST_API_VERSION@ \
+	gst-stats-@GST_API_VERSION@ \
 	gst-typefind-@GST_API_VERSION@
 
 gst_inspect_@GST_API_VERSION@_SOURCES = gst-inspect.c tools.h
 gst_inspect_@GST_API_VERSION@_CFLAGS = $(GST_OBJ_CFLAGS)
 gst_inspect_@GST_API_VERSION@_LDADD = $(GST_OBJ_LIBS)
 
+gst_stats_@GST_API_VERSION@_SOURCES = gst-stats.c tools.h
+gst_stats_@GST_API_VERSION@_CFLAGS = $(GST_OBJ_CFLAGS)
+gst_stats_@GST_API_VERSION@_LDADD = $(GST_OBJ_LIBS)
+
 gst_typefind_@GST_API_VERSION@_SOURCES = gst-typefind.c tools.h
 gst_typefind_@GST_API_VERSION@_CFLAGS = $(GST_OBJ_CFLAGS)
 gst_typefind_@GST_API_VERSION@_LDADD = $(GST_OBJ_LIBS)

tools/gst-stats.c

@@ -0,0 +1,834 @@
+/* GStreamer
+ * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
+ *
+ * gst-stats.c: statistics tracing front end
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Library General Public
+ * License as published by the Free Software Foundation; either
+ * version 2 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Library General Public License for more details.
+ *
+ * You should have received a copy of the GNU Library General Public
+ * License along with this library; if not, write to the
+ * Free Software Foundation, Inc., 51 Franklin St, Fifth Floor,
+ * Boston, MA 02110-1301, USA.
+ */
+
+#ifdef HAVE_CONFIG_H
+#  include "config.h"
+#endif
+
+#include <stdlib.h>
+#include <stdio.h>
+#include <string.h>
+
+#include "tools.h"
+
+/* log parser */
+static GRegex *raw_log = NULL;
+static GRegex *ansi_log = NULL;
+
+/* global statistics */
+static GHashTable *threads = NULL;
+static GPtrArray *elements = NULL;
+static GPtrArray *pads = NULL;
+static guint64 num_buffers = 0, num_events = 0, num_messages = 0, num_queries =
+    0;
+static guint num_elements = 0, num_bins = 0, num_pads = 0, num_ghostpads = 0;
+
+typedef struct
+{
+  /* human readable pad name and details */
+  gchar *name, *type_name;
+  guint index;
+  gboolean is_ghost_pad;
+  GstPadDirection dir;
+  /* buffer statistics */
+  guint num_buffers;
+  guint num_readonly, num_preroll, num_discont, num_gap, num_delta;
+  guint min_size, max_size, avg_size;
+  /* first and last activity on the pad, expected next_ts */
+  GstClockTime first_ts, last_ts, next_ts;
+  /* in which thread does it operate */
+  guint thread_id;
+  /* hierarchy */
+  guint parent_ix;
+} GstPadStats;
+
+typedef struct
+{
+  /* human readable element name */
+  gchar *name, *type_name;
+  guint index;
+  gboolean is_bin;
+  /* buffer statistics */
+  guint recv_buffers, sent_buffers;
+  guint64 recv_bytes, sent_bytes;
+  /* event, message statistics */
+  guint num_events, num_messages, num_queries;
+  /* first activity on the element */
+  GstClockTime first_ts, last_ts;
+  /* time spend in this element */
+  GstClockTime treal;
+  /* hierarchy */
+  guint parent_ix;
+} GstElementStats;
+
+typedef struct
+{
+  /* time spend in this thread */
+  GstClockTime treal;
+  guint max_cpuload;
+} GstThreadStats;
+
+/* stats helper */
+
+static void
+free_element_stats (gpointer data)
+{
+  g_slice_free (GstElementStats, data);
+}
+
+static inline GstElementStats *
+get_element_stats (guint ix)
+{
+  return (ix != G_MAXUINT) ? g_ptr_array_index (elements, ix) : NULL;
+}
+
+static inline GstPadStats *
+get_pad_stats (guint ix)
+{
+  return (ix != G_MAXUINT) ? g_ptr_array_index (pads, ix) : NULL;
+}
+
+static void
+free_pad_stats (gpointer data)
+{
+  g_slice_free (GstPadStats, data);
+}
+
+static void
+new_pad_stats (GstStructure * s)
+{
+  GstPadStats *stats;
+  guint ix;
+  gchar *type, *name;
+  gboolean is_ghost_pad;
+  GstPadDirection dir;
+  guint thread_id;
+
+  gst_structure_get (s,
+      "ix", G_TYPE_UINT, &ix,
+      "name", G_TYPE_STRING, &name,
+      "type", G_TYPE_STRING, &type,
+      "is-ghostpad", G_TYPE_BOOLEAN, &is_ghost_pad,
+      "pad-direction", GST_TYPE_PAD_DIRECTION, &dir,
+      "thread-id", G_TYPE_UINT, &thread_id, NULL);
+
+  stats = g_slice_new0 (GstPadStats);
+  if (is_ghost_pad)
+    num_ghostpads++;
+  num_pads++;
+  stats->name = name;
+  stats->type_name = type;
+  stats->index = ix;
+  stats->is_ghost_pad = is_ghost_pad;
+  stats->dir = dir;
+  stats->min_size = G_MAXUINT;
+  stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE;
+  stats->thread_id = thread_id;
+
+  if (pads->len <= ix)
+    g_ptr_array_set_size (pads, ix + 1);
+  g_ptr_array_index (pads, ix) = stats;
+
+  if (thread_id) {
+    GstThreadStats *thread_stats;
+    if (!(thread_stats = g_hash_table_lookup (threads,
+                GUINT_TO_POINTER (thread_id)))) {
+      thread_stats = g_slice_new0 (GstThreadStats);
+      g_hash_table_insert (threads, GUINT_TO_POINTER (thread_id), thread_stats);
+    }
+  }
+}
+
+static void
+new_element_stats (GstStructure * s)
+{
+  GstElementStats *stats;
+  guint ix;
+  gchar *type, *name;
+  gboolean is_bin;
+
+  gst_structure_get (s,
+      "ix", G_TYPE_UINT, &ix,
+      "name", G_TYPE_STRING, &name,
+      "type", G_TYPE_STRING, &type, "is-bin", G_TYPE_BOOLEAN, &is_bin, NULL);
+
+  stats = g_slice_new0 (GstElementStats);
+  if (is_bin)
+    num_bins++;
+  num_elements++;
+  stats->index = ix;
+  stats->name = name;
+  stats->type_name = type;
+  stats->is_bin = is_bin;
+  stats->first_ts = GST_CLOCK_TIME_NONE;
+  stats->parent_ix = G_MAXUINT;
+
+  if (elements->len <= ix)
+    g_ptr_array_set_size (elements, ix + 1);
+  g_ptr_array_index (elements, ix) = stats;
+}
+
+static void
+free_thread_stats (gpointer data)
+{
+  g_slice_free (GstThreadStats, data);
+}
+
+static void
+do_pad_stats (GstPadStats * stats, guint elem_ix, guint size, guint64 ts,
+    guint64 buffer_ts, guint64 buffer_dur, GstBufferFlags buffer_flags)
+{
+  gulong avg_size;
+
+  /* parentage */
+  if (stats->parent_ix == G_MAXUINT) {
+    stats->parent_ix = elem_ix;
+  }
+
+  /* size stats */
+  avg_size = (((gulong) stats->avg_size * (gulong) stats->num_buffers) + size);
+  stats->num_buffers++;
+  stats->avg_size = (guint) (avg_size / stats->num_buffers);
+  if (size < stats->min_size)
+    stats->min_size = size;
+  else if (size > stats->max_size)
+    stats->max_size = size;
+  /* time stats */
+  if (!GST_CLOCK_TIME_IS_VALID (stats->last_ts))
+    stats->first_ts = ts;
+  stats->last_ts = ts;
+  /* flag stats */
+  if (buffer_flags & GST_BUFFER_FLAG_GAP)
+    stats->num_gap++;
+  if (buffer_flags & GST_BUFFER_FLAG_DELTA_UNIT)
+    stats->num_delta++;
+  if (buffer_flags & GST_BUFFER_FLAG_DISCONT)
+    stats->num_discont++;
+  /* TODO(ensonic): there is a bunch of new flags in 1.0 */
+  /* update timestamps */
+  if (GST_CLOCK_TIME_IS_VALID (buffer_ts) &&
+      GST_CLOCK_TIME_IS_VALID (buffer_dur)) {
+    stats->next_ts = buffer_ts + buffer_dur;
+  } else {
+    stats->next_ts = GST_CLOCK_TIME_NONE;
+  }
+}
+
+static void
+do_element_stats (GstElementStats * stats, GstElementStats * peer_stats,
+    guint size, guint64 ts)
+{
+  stats->sent_buffers++;
+  peer_stats->recv_buffers++;
+  stats->sent_bytes += size;
+  peer_stats->recv_bytes += size;
+  /* time stats */
+  if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (stats->first_ts))) {
+    stats->first_ts = ts;
+  }
+  if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (peer_stats->first_ts))) {
+    peer_stats->first_ts = ts + 1;
+  }
+}
+
+static void
+do_buffer_stats (GstStructure * s)
+{
+  guint64 ts, buffer_ts, buffer_dur;
+  guint pad_ix, elem_ix, peer_elem_ix;
+  guint size;
+  GstBufferFlags buffer_flags;
+  GstPadStats *pad_stats;
+  GstElementStats *elem_stats, *peer_elem_stats;
+
+  num_buffers++;
+  gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+      "pad-ix", G_TYPE_UINT, &pad_ix,
+      "elem-ix", G_TYPE_UINT, &elem_ix,
+      "peer-elem-ix", G_TYPE_UINT, &peer_elem_ix,
+      "buffer-size", G_TYPE_UINT, &size,
+      "buffer-ts", G_TYPE_UINT64, &buffer_ts,
+      "buffer-duration", G_TYPE_UINT64, &buffer_dur,
+      "buffer-flags", GST_TYPE_BUFFER_FLAGS, &buffer_flags, NULL);
+  if (!(pad_stats = get_pad_stats (pad_ix))) {
+    GST_WARNING ("no pad stats found for ix=%u", pad_ix);
+    return;
+  }
+  if (!(elem_stats = get_element_stats (elem_ix))) {
+    GST_WARNING ("no element stats found for ix=%u", elem_ix);
+    return;
+  }
+  if (!(peer_elem_stats = get_element_stats (peer_elem_ix))) {
+    GST_WARNING ("no element stats found for ix=%u", peer_elem_ix);
+    return;
+  }
+  do_pad_stats (pad_stats, elem_ix, size, ts, buffer_ts, buffer_dur,
+      buffer_flags);
+  if (pad_stats->dir == GST_PAD_SRC) {
+    /* push */
+    do_element_stats (elem_stats, peer_elem_stats, size, ts);
+  } else {
+    /* pull */
+    do_element_stats (peer_elem_stats, elem_stats, size, ts);
+  }
+}
+
+static void
+do_event_stats (GstStructure * s)
+{
+  guint64 ts;
+  guint pad_ix, elem_ix;
+  GstPadStats *pad_stats;
+  GstElementStats *elem_stats;
+
+  num_events++;
+  gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+      "pad-ix", G_TYPE_UINT, &pad_ix, "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+  if (!(pad_stats = get_pad_stats (pad_ix))) {
+    GST_WARNING ("no pad stats found for ix=%u", pad_ix);
+    return;
+  }
+  if (!(elem_stats = get_element_stats (elem_ix))) {
+    GST_WARNING ("no element stats found for ix=%u", elem_ix);
+    return;
+  }
+  elem_stats->num_events++;
+}
+
+static void
+do_message_stats (GstStructure * s)
+{
+  guint64 ts;
+  guint elem_ix;
+  GstElementStats *elem_stats;
+
+  num_messages++;
+  gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+      "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+  if (!(elem_stats = get_element_stats (elem_ix))) {
+    GST_WARNING ("no element stats found for ix=%u", elem_ix);
+    return;
+  }
+  elem_stats->num_messages++;
+}
+
+static void
+do_query_stats (GstStructure * s)
+{
+  guint64 ts;
+  guint elem_ix;
+  GstElementStats *elem_stats;
+
+  num_queries++;
+  gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+      "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+  if (!(elem_stats = get_element_stats (elem_ix))) {
+    GST_WARNING ("no element stats found for ix=%u", elem_ix);
+    return;
+  }
+  elem_stats->num_queries++;
+}
+
+/* reporting */
+
+static void
+print_pad_stats (gpointer value, gpointer user_data)
+{
+  GstPadStats *stats = (GstPadStats *) value;
+
+  if (stats->thread_id == GPOINTER_TO_UINT (user_data)) {
+    /* there seem to be some temporary pads */
+    if (stats->num_buffers) {
+      GstClockTimeDiff running =
+          GST_CLOCK_DIFF (stats->first_ts, stats->last_ts);
+      GstElementStats *elem_stats = get_element_stats (stats->parent_ix);
+      gchar fullname[30 + 1];
+
+      g_snprintf (fullname, 30, "%s.%s", elem_stats->name, stats->name);
+
+      printf
+          ("    %c %-30.30s: buffers %7u (ro %5u,pre %3u,dis %5u,gap %5u,dlt %5u),",
+          (stats->dir == GST_PAD_SRC) ? '>' : '<', fullname,
+          stats->num_buffers, stats->num_readonly, stats->num_preroll,
+          stats->num_discont, stats->num_gap, stats->num_delta);
+      if (stats->min_size == stats->max_size) {
+        printf (" size (min/avg/max) ......./%7u/.......,", stats->avg_size);
+      } else {
+        printf (" size (min/avg/max) %7u/%7u/%7u,",
+            stats->min_size, stats->avg_size, stats->max_size);
+      }
+      printf (" time %" GST_TIME_FORMAT ","
+          " bytes/sec %lf\n",
+          GST_TIME_ARGS (running),
+          ((gdouble) (stats->num_buffers * stats->avg_size) * GST_SECOND) /
+          ((gdouble) running));
+    }
+  }
+}
+
+static void
+print_thread_stats (gpointer key, gpointer value, gpointer user_data)
+{
+  GSList *list = user_data;
+#if 0
+  GstThreadStats *stats = (GstThreadStats *) value;
+  guint cpuload = 0;
+  guint time_percent;
+
+  time_percent =
+      (guint) gst_util_uint64_scale (stats->treal, G_GINT64_CONSTANT (100),
+      last_ts);
+
+  if (tusersys) {
+    guint64 total;
+    /* cpuload for the process, scaled by the timeslice of this thread */
+    //cpuload = (guint) gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT(100) * stats->treal, last_ts * last_ts);
+
+    total = gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT (100), last_ts);
+    cpuload = gst_util_uint64_scale (total, stats->treal, last_ts);
+  }
+
+  printf ("Thread %p Statistics:\n", key);
+  printf ("  Time: %" GST_TIME_FORMAT ", %u %%\n", GST_TIME_ARGS (stats->treal),
+      (guint) time_percent);
+  printf ("  Avg/Max CPU load: %u %%, %u %%\n", cpuload, stats->max_cpuload);
+#endif
+  /* FIXME: would be nice to skip, if there are no pads for that thread
+   * (e.g. a pipeline), we would need to pass as struct to
+   * g_hash_table_foreach::user_data
+   */
+  puts ("  Pad Statistics:");
+  g_slist_foreach (list, print_pad_stats, key);
+}
+
+static void
+print_element_stats (gpointer value, gpointer user_data)
+{
+  GstElementStats *stats = (GstElementStats *) value;
+
+  /* skip temporary elements */
+  if (stats->first_ts != GST_CLOCK_TIME_NONE) {
+    //GstClockTimeDiff running = GST_CLOCK_DIFF (stats->first_ts, stats->last_ts);
+    gchar fullname[45 + 1];
+
+    g_snprintf (fullname, 45, "%s:%s", stats->type_name, stats->name);
+
+    printf ("  %-45s:", fullname);
+    if (stats->recv_buffers)
+      printf (" buffers in/out %7u", stats->recv_buffers);
+    else
+      printf (" buffers in/out %7s", "-");
+    if (stats->sent_buffers)
+      printf ("/%7u", stats->sent_buffers);
+    else
+      printf ("/%7s", "-");
+    if (stats->recv_bytes)
+      printf (" bytes in/out %12" G_GUINT64_FORMAT, stats->recv_bytes);
+    else
+      printf (" bytes in/out %12s", "-");
+    if (stats->sent_bytes)
+      printf ("/%12" G_GUINT64_FORMAT, stats->sent_bytes);
+    else
+      printf ("/%12s", "-");
+    printf (" first activity %" GST_TIME_FORMAT ", " " ev/msg/qry sent %5u/%5u/%5u"     /*", "
+                                                                                           " cpu usage %u %%" */
+        "\n", GST_TIME_ARGS (stats->first_ts), stats->num_events, stats->num_messages, stats->num_queries       /*,
+                                                                                                                   (guint)(100*stats->treal/last_ts) */ );
+  }
+}
+
+static void
+accum_element_stats (gpointer value, gpointer user_data)
+{
+  GstElementStats *stats = (GstElementStats *) value;
+
+  if (stats->parent_ix != G_MAXUINT) {
+    GstElementStats *parent_stats = get_element_stats (stats->parent_ix);
+
+    parent_stats->num_events += stats->num_events;
+    parent_stats->num_messages += stats->num_messages;
+    parent_stats->num_queries += stats->num_queries;
+    if (!GST_CLOCK_TIME_IS_VALID (parent_stats->first_ts)) {
+      parent_stats->first_ts = stats->first_ts;
+    } else if (GST_CLOCK_TIME_IS_VALID (stats->first_ts)) {
+      parent_stats->first_ts = MIN (parent_stats->first_ts, stats->first_ts);
+    }
+    if (!GST_CLOCK_TIME_IS_VALID (parent_stats->last_ts)) {
+      parent_stats->last_ts = stats->last_ts;
+    } else if (GST_CLOCK_TIME_IS_VALID (stats->last_ts)) {
+      parent_stats->last_ts = MAX (parent_stats->last_ts, stats->last_ts);
+    }
+  }
+}
+
+/* sorting */
+
+static gint
+sort_pad_stats_by_first_activity (gconstpointer ps1, gconstpointer ps2)
+{
+  GstPadStats *s1 = (GstPadStats *) ps1;
+  GstPadStats *s2 = (GstPadStats *) ps2;
+
+  gint order = GST_CLOCK_DIFF (s2->first_ts, s1->first_ts);
+
+  if (!order) {
+    order = s1->dir - s2->dir;
+  }
+  return (order);
+}
+
+static void
+sort_pad_stats (gpointer value, gpointer user_data)
+{
+  GSList **list = user_data;
+
+  *list =
+      g_slist_insert_sorted (*list, value, sort_pad_stats_by_first_activity);
+}
+
+static gint
+sort_element_stats_by_first_activity (gconstpointer es1, gconstpointer es2)
+{
+  return (GST_CLOCK_DIFF (((GstElementStats *) es2)->first_ts,
+          ((GstElementStats *) es1)->first_ts));
+}
+
+static void
+sort_bin_stats (gpointer value, gpointer user_data)
+{
+  if (((GstElementStats *) value)->is_bin) {
+    GSList **list = user_data;
+
+    *list =
+        g_slist_insert_sorted (*list, value,
+        sort_element_stats_by_first_activity);
+  }
+}
+
+static void
+sort_element_stats (gpointer value, gpointer user_data)
+{
+  if (!(((GstElementStats *) value)->is_bin)) {
+    GSList **list = user_data;
+
+    *list =
+        g_slist_insert_sorted (*list, value,
+        sort_element_stats_by_first_activity);
+  }
+}
+
+static gboolean
+check_bin_parent (gpointer key, gpointer value, gpointer user_data)
+{
+  GstElementStats *stats = (GstElementStats *) value;
+
+  return (stats->parent_ix == GPOINTER_TO_UINT (user_data));
+}
+
+static gboolean
+process_leaf_bins (gpointer key, gpointer value, gpointer user_data)
+{
+  GHashTable *accum_bins = user_data;
+
+  /* if we find no bin that has this bin as a parent ... */
+  if (!g_hash_table_find (accum_bins, check_bin_parent, key)) {
+    /* accumulate stats to the parent and remove */
+    accum_element_stats (value, NULL);
+    return TRUE;
+  }
+  return FALSE;
+}
+
+/* main */
+
+static gboolean
+init (void)
+{
+  /* compile the parser regexps */
+  /* 0:00:00.004925027 31586      0x1c5c600 DEBUG           GST_REGISTRY gstregistry.c:463:gst_registry_add_plugin:<registry0> adding plugin 0x1c79160 for filename "/usr/lib/gstreamer-1.0/libgstxxx.so" */
+  raw_log = g_regex_new (
+      /* 1: ts */
+      "^([0-9:.]+) +"
+      /* 2: pid */
+      "([0-9]+) +"
+      /* 3: thread */
+      "(0x[0-9a-fA-F]+) +"
+      /* 4: level */
+      "([A-Z]+) +"
+      /* 5: category */
+      "([a-zA-Z_-]+) +"
+      /* 6: file:line:func: */
+      "([^:]+:[0-9]+:[^:]+:)"
+      /* 7: (obj)? log-text */
+      "(.*)$", 0, 0, NULL);
+  if (!raw_log) {
+    GST_WARNING ("failed to compile the 'raw' parser");
+    return FALSE;
+  }
+
+  ansi_log = g_regex_new (
+      /* 1: ts */
+      "^([0-9:.]+) +"
+      /* 2: pid */
+      "\\\e\\\[[0-9;]+m *([0-9]+)\\\e\\\[00m +"
+      /* 3: thread */
+      "(0x[0-9a-fA-F]+) +"
+      /* 4: level */
+      "(?:\\\e\\\[[0-9;]+m)?([A-Z]+) +\\\e\\\[00m +"
+      /* 5: category */
+      "\\\e\\\[[0-9;]+m +([a-zA-Z_-]+) +"
+      /* 6: file:line:func: */
+      "([^:]+:[0-9]+:[^:]+:)(?:\\\e\\\[00m)?"
+      /* 7: (obj)? log-text */
+      "(.*)$", 0, 0, NULL);
+  if (!raw_log) {
+    GST_WARNING ("failed to compile the 'ansi' parser");
+    return FALSE;
+  }
+
+  elements = g_ptr_array_new_with_free_func (free_element_stats);
+  pads = g_ptr_array_new_with_free_func (free_pad_stats);
+  threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
+
+  return TRUE;
+}
+
+static void
+done (void)
+{
+  if (pads)
+    g_ptr_array_free (pads, TRUE);
+  if (elements)
+    g_ptr_array_free (elements, TRUE);
+  if (threads)
+    g_hash_table_destroy (threads);
+
+  if (raw_log)
+    g_regex_unref (raw_log);
+  if (ansi_log)
+    g_regex_unref (ansi_log);
+}
+
+static void
+print_stats (void)
+{
+  guint num_threads = g_hash_table_size (threads);
+
+  /* print overall stats */
+  puts ("\nOverall Statistics:");
+  printf ("Number of Threads: %u\n", num_threads);
+  printf ("Number of Elements: %u\n", num_elements - num_bins);
+  printf ("Number of Bins: %u\n", num_bins);
+  printf ("Number of Pads: %u\n", num_pads - num_ghostpads);
+  printf ("Number of GhostPads: %u\n", num_ghostpads);
+  printf ("Number of Buffers passed: %" G_GUINT64_FORMAT "\n", num_buffers);
+  printf ("Number of Events sent: %" G_GUINT64_FORMAT "\n", num_events);
+  printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n", num_messages);
+  printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", num_queries);
+  puts ("");
+
+  /* thread stats */
+  if (num_threads) {
+    GSList *list = NULL;
+
+    g_ptr_array_foreach (pads, sort_pad_stats, &list);
+    g_hash_table_foreach (threads, print_thread_stats, list);
+    puts ("");
+    g_slist_free (list);
+  }
+
+  /* element stats */
+  if (num_elements) {
+    GSList *list = NULL;
+
+    puts ("Element Statistics:");
+    /* sort by first_activity */
+    g_ptr_array_foreach (elements, sort_element_stats, &list);
+    /* attribute element stats to bins */
+    g_slist_foreach (list, accum_element_stats, NULL);
+    g_slist_foreach (list, print_element_stats, NULL);
+    puts ("");
+    g_slist_free (list);
+  }
+
+  /* bin stats */
+  if (num_bins) {
+    GSList *list = NULL;
+    guint i;
+    GHashTable *accum_bins = g_hash_table_new_full (NULL, NULL, NULL, NULL);
+
+    puts ("Bin Statistics:");
+    /* attribute bin stats to parent-bins */
+    for (i = 0; i < num_elements; i++) {
+      GstElementStats *stats = g_ptr_array_index (elements, i);
+      if (stats->is_bin) {
+        g_hash_table_insert (accum_bins, GUINT_TO_POINTER (i), stats);
+      }
+    }
+    while (g_hash_table_size (accum_bins)) {
+      g_hash_table_foreach_remove (accum_bins, process_leaf_bins, accum_bins);
+    }
+    g_hash_table_destroy (accum_bins);
+    /* sort by first_activity */
+    g_ptr_array_foreach (elements, sort_bin_stats, &list);
+    g_slist_foreach (list, print_element_stats, NULL);
+    puts ("");
+    g_slist_free (list);
+  }
+}
+
+static void
+collect_stats (const gchar * filename)
+{
+  FILE *log;
+
+  if ((log = fopen (filename, "rt"))) {
+    gchar line[5001];
+
+    /* probe format */
+    if (fgets (line, 5000, log)) {
+      GMatchInfo *match_info;
+      GRegex *parser;
+      GstStructure *s;
+      guint lnr = 0;
+      gchar *level, *data;
+
+      if (strchr (line, 27)) {
+        parser = ansi_log;
+        GST_INFO ("format is 'ansi'");
+      } else {
+        parser = raw_log;
+        GST_INFO ("format is 'raw'");
+      }
+      rewind (log);
+
+      /* parse the log */
+      while (!feof (log)) {
+        if (fgets (line, 5000, log)) {
+          if (g_regex_match (parser, line, 0, &match_info)) {
+            /* filter by level */
+            level = g_match_info_fetch (match_info, 4);
+            if (!strcmp (level, "TRACE")) {
+              data = g_match_info_fetch (match_info, 7);
+              if ((s = gst_structure_from_string (data, NULL))) {
+                const gchar *name = gst_structure_get_name (s);
+
+                // TODO(ensonic): add a function for each name-id quark
+                // these function will do the actual stats tracking
+                if (!strcmp (name, "new-pad")) {
+                  new_pad_stats (s);
+                } else if (!strcmp (name, "new-element")) {
+                  new_element_stats (s);
+                } else if (!strcmp (name, "buffer")) {
+                  do_buffer_stats (s);
+                } else if (!strcmp (name, "event")) {
+                  do_event_stats (s);
+                } else if (!strcmp (name, "message")) {
+                  do_message_stats (s);
+                } else if (!strcmp (name, "query")) {
+                  do_query_stats (s);
+                } else {
+                  GST_WARNING ("unknown log entry: '%s'", data);
+                }
+                gst_structure_free (s);
+              } else {
+                GST_WARNING ("unknown log entry: '%s'", data);
+              }
+            }
+          } else {
+            if (*line) {
+              GST_WARNING ("foreign log entry: %s:%d:'%s'", filename, lnr,
+                  g_strchomp (line));
+            }
+          }
+          g_match_info_free (match_info);
+          match_info = NULL;
+          lnr++;
+        } else {
+          if (!feof (log)) {
+            // TODO(ensonic): run wc -L on the log file
+            fprintf (stderr, "line too long");
+          }
+        }
+      }
+      fclose (log);
+      // TODO(ensonic): print stats
+    } else {
+      GST_WARNING ("empty log");
+    }
+  }
+}
+
+gint
+main (gint argc, gchar * argv[])
+{
+  gchar **filenames = NULL;
+  guint num;
+  GError *err = NULL;
+  GOptionContext *ctx;
+  GOptionEntry options[] = {
+    GST_TOOLS_GOPTION_VERSION,
+    // TODO(ensonic): add a summary flag, if set read the whole thing, print
+    // stats once, and exit
+    {G_OPTION_REMAINING, 0, 0, G_OPTION_ARG_FILENAME_ARRAY, &filenames, NULL}
+    ,
+    {NULL}
+  };
+
+#ifdef ENABLE_NLS
+  bindtextdomain (GETTEXT_PACKAGE, LOCALEDIR);
+  bind_textdomain_codeset (GETTEXT_PACKAGE, "UTF-8");
+  textdomain (GETTEXT_PACKAGE);
+#endif
+
+  g_set_prgname ("gst-stats-" GST_API_VERSION);
+
+  ctx = g_option_context_new ("FILE");
+  g_option_context_add_main_entries (ctx, options, GETTEXT_PACKAGE);
+  g_option_context_add_group (ctx, gst_init_get_option_group ());
+  if (!g_option_context_parse (ctx, &argc, &argv, &err)) {
+    g_print ("Error initializing: %s\n", GST_STR_NULL (err->message));
+    exit (1);
+  }
+  g_option_context_free (ctx);
+
+  gst_tools_print_version ();
+
+  if (filenames == NULL || *filenames == NULL) {
+    g_print ("Please give one filename to %s\n\n", g_get_prgname ());
+    return 1;
+  }
+  num = g_strv_length (filenames);
+  if (num == 0 || num > 1) {
+    g_print ("Please give exactly one filename to %s (%d given).\n\n",
+        g_get_prgname (), num);
+    return 1;
+  }
+
+  if (init ()) {
+    collect_stats (filenames[0]);
+    print_stats ();
+  }
+  done ();
+
+  g_strfreev (filenames);
+  return 0;
+}