From b8eef6ba2c79bef3a934bb0f2d1e4be7a337e0b7 Mon Sep 17 00:00:00 2001 From: Stefan Sauer Date: Mon, 4 Nov 2013 20:11:09 +0100 Subject: [PATCH] stats: add a stats frontend Parse the log and collect data from tracer messages. --- plugins/tracers/gststats.c | 478 +++++++++----------------- plugins/tracers/gststats.h | 3 +- tools/.gitignore | 1 + tools/Makefile.am | 5 + tools/gst-stats.c | 834 +++++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 1010 insertions(+), 311 deletions(-) create mode 100644 tools/gst-stats.c diff --git a/plugins/tracers/gststats.c b/plugins/tracers/gststats.c index 7b8ab7e..5c96a6b 100644 --- a/plugins/tracers/gststats.c +++ b/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 */ - gchar *name; + /* we can't rely on the address to be unique over time */ guint index; - GType type; - GstPadDirection dir; - /* buffer statistics */ - guint num_buffers; - 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; + /* for pre + post */ + GstClockTime last_ts; + /* hierarchy */ + guint parent_ix; } GstPadStats; typedef struct { - /* human readable element name */ - gchar *name; + /* we can't rely on the address to be unique over time */ guint index; - GType type; - /* 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; + /* for pre + post */ + GstClockTime 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; - return stats; -} -#if 0 -static GstElementStats * -get_element_stats_by_id (GstStatsTracer * self, guint ix) -{ - return g_ptr_array_index (self->elements, ix); + 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; } -#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->dir = GST_PAD_DIRECTION (pad); - stats->min_size = G_MAXUINT; - stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE; - stats->thread_id = g_thread_self (); + stats->parent_ix = G_MAXUINT; + + log_trace (gst_structure_new ("new-pad", + "ix", G_TYPE_UINT, stats->index, + "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) - return NULL; + if (!pad) { + 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)) { - GstObject *parent = GST_OBJECT_PARENT (pad); - /* yes we leak the names right now ... */ - if (GST_IS_ELEMENT (parent)) { - /* pad is regular pad */ - get_element_stats (self, GST_ELEMENT_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)); - } - } 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)); - } + if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) { + GstElement *elem = get_real_pad_parent (pad); + if (elem) { + GstElementStats *elem_stats = get_element_stats (self, elem); + + stats->parent_ix = elem_stats->index; } } return stats; @@ -201,161 +229,30 @@ free_pad_stats (gpointer data) } static void -do_pad_stats (GstStatsTracer * self, GstPad * pad, GstPadStats * stats, - GstBuffer * buffer, GstClockTime elapsed) -{ - guint size = gst_buffer_get_size (buffer); - gulong avg_size; - - self->num_buffers++; - /* 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 (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (stats->first_ts))) - stats->first_ts = elapsed; - stats->last_ts = elapsed; - /* flag stats */ - if (GST_BUFFER_FLAG_IS_SET (buffer, GST_BUFFER_FLAG_GAP)) - 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) +do_buffer_stats (GstStatsTracer * self, GstPad * this_pad, + GstPadStats * this_pad_stats, GstPad * that_pad, + GstPadStats * that_pad_stats, 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); + GstElement *this_elem = get_real_pad_parent (this_pad); + 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); + + /* TODO(ensonic): need a quark-table (shared with the tracer-front-ends?) */ + log_trace (gst_structure_new ("buffer", + "ts", G_TYPE_UINT64, elapsed, + "pad-ix", G_TYPE_UINT, this_pad_stats->index, + "elem-ix", G_TYPE_UINT, this_elem_stats->index, + "peer-pad-ix", G_TYPE_UINT, that_pad_stats->index, + "peer-elem-ix", G_TYPE_UINT, that_elem_stats->index, + "buffer-size", G_TYPE_UINT, gst_buffer_get_size (buf), + "buffer-ts", G_TYPE_UINT64, GST_BUFFER_TIMESTAMP (buf), + "buffer-duration", G_TYPE_UINT64, GST_BUFFER_DURATION (buf), + "buffer-flags", GST_TYPE_BUFFER_FLAGS, GST_BUFFER_FLAGS (buf), + /* + scheduling-jitter: for this we need the last_ts on the pad + */ + NULL)); } 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", - GST_TIME_ARGS (elapsed), pad_stats->name, + " transmission on unparented target pad %s_%s -> %s_%s\n", + 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_transmission_stats (self, pad, buffer, ts); + do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats, + buffer, ts); } static void @@ -517,8 +386,10 @@ do_push_buffer_post (GstStatsTracer * self, va_list var_args) typedef struct { GstStatsTracer *self; - GstPad *pad; - GstPadStats *stats; + GstPad *this_pad; + 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_transmission_stats (args->self, args->pad, *buffer, args->ts); + do_buffer_stats (args->self, args->this_pad, args->this_pad_stats, + 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); - DoPushBufferListArgs args = { self, pad, stats, ts }; + 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); + 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); - guint64 last_ts = stats->last_ts; + GstPadStats *this_pad_stats = get_pad_stats (self, this_pad); + 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_transmission_stats (self, pad, buffer, ts); + do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats, + 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; - - parent = get_real_pad_parent (pad); - if ((elem = GST_ELEMENT (parent))) { - GstElementStats *stats = get_element_stats (self, elem); - get_pad_stats (self, pad); - - stats->last_ts = ts; - stats->num_events++; - self->num_events++; - } + GstElement *elem = get_real_pad_parent (pad); + GstPadStats *pad_stats = get_pad_stats (self, pad); + GstElementStats *elem_stats = get_element_stats (self, elem); + + elem_stats->last_ts = ts; + log_trace (gst_structure_new ("event", + "ts", G_TYPE_UINT64, ts, + "pad-ix", G_TYPE_UINT, pad_stats->index, + "elem-ix", G_TYPE_UINT, elem_stats->index, NULL)); } 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++; - self->num_messages++; + log_trace (gst_structure_new ("message", + "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++; - self->num_queries++; + log_trace (gst_structure_new ("query", + "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); - - /* 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)); + //GstStatsTracer *self = GST_STATS_TRACER_CAST (obj); G_OBJECT_CLASS (parent_class)->finalize (obj); } diff --git a/plugins/tracers/gststats.h b/plugins/tracers/gststats.h index 5b8e611..97ae176 100644 --- a/plugins/tracers/gststats.h +++ b/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_bins, num_pads, num_ghostpads; + guint num_elements, num_pads; }; struct _GstStatsTracerClass { diff --git a/tools/.gitignore b/tools/.gitignore index 19293a9..2aa9fb9 100644 --- a/tools/.gitignore +++ b/tools/.gitignore @@ -20,5 +20,6 @@ gst-typefind.1 gst-inspect-?.?* gst-launch-?.?* +gst-stats-?.?* gst-typefind-?.?* diff --git a/tools/Makefile.am b/tools/Makefile.am index 46f814d..ffea17d 100644 --- a/tools/Makefile.am +++ b/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) diff --git a/tools/gst-stats.c b/tools/gst-stats.c new file mode 100644 index 0000000..92b39c2 --- /dev/null +++ b/tools/gst-stats.c @@ -0,0 +1,834 @@ +/* GStreamer + * Copyright (C) 2013 Stefan Sauer + * + * 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 +#include +#include + +#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: 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; +} -- 2.7.4