2 * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
4 * gststats.c: tracing module that logs events
6 * This library is free software; you can redistribute it and/or
7 * modify it under the terms of the GNU Library General Public
8 * License as published by the Free Software Foundation; either
9 * version 2 of the License, or (at your option) any later version.
11 * This library is distributed in the hope that it will be useful,
12 * but WITHOUT ANY WARRANTY; without even the implied warranty of
13 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
14 * Library General Public License for more details.
16 * You should have received a copy of the GNU Library General Public
17 * License along with this library; if not, write to the
18 * Free Software Foundation, Inc., 51 Franklin St, Fifth Floor,
19 * Boston, MA 02110-1301, USA.
23 * @short_description: log event stats
25 * A tracing module that builds usage statistic for elements and pads.
36 GST_DEBUG_CATEGORY_STATIC (gst_stats_debug);
37 #define GST_CAT_DEFAULT gst_stats_debug
39 static GQuark data_quark;
40 G_LOCK_DEFINE (_elem_stats);
41 G_LOCK_DEFINE (_pad_stats);
44 GST_DEBUG_CATEGORY_INIT (gst_stats_debug, "stats", 0, "stats tracer"); \
45 data_quark = g_quark_from_static_string ("gststats:data");
46 #define gst_stats_tracer_parent_class parent_class
47 G_DEFINE_TYPE_WITH_CODE (GstStatsTracer, gst_stats_tracer, GST_TYPE_TRACER,
52 /* we can't rely on the address to be unique over time */
62 /* we can't rely on the address to be unique over time */
66 /* time spend in this element */
74 static GstElementStats no_elem_stats = { 0, };
76 static GstElementStats *
77 fill_element_stats (GstStatsTracer * self, GstElement * element)
79 GstElementStats *stats = g_slice_new0 (GstElementStats);
81 stats->index = self->num_elements++;
82 stats->parent_ix = G_MAXUINT;
87 log_new_element_stats (GstElementStats * stats, GstElement * element)
89 gst_tracer_log_trace (gst_structure_new ("new-element",
90 "ix", G_TYPE_UINT, stats->index,
91 "parent-ix", G_TYPE_UINT, stats->parent_ix,
92 "name", G_TYPE_STRING, GST_OBJECT_NAME (element),
93 "type", G_TYPE_STRING, G_OBJECT_TYPE_NAME (element),
94 "is-bin", G_TYPE_BOOLEAN, GST_IS_BIN (element), NULL));
98 free_element_stats (gpointer data)
100 g_slice_free (GstElementStats, data);
103 static inline GstElementStats *
104 get_element_stats (GstStatsTracer * self, GstElement * element)
106 GstElementStats *stats;
107 gboolean is_new = FALSE;
110 no_elem_stats.index = G_MAXUINT;
111 return &no_elem_stats;
114 G_LOCK (_elem_stats);
115 if (!(stats = g_object_get_qdata ((GObject *) element, data_quark))) {
116 stats = fill_element_stats (self, element);
117 g_object_set_qdata_full ((GObject *) element, data_quark, stats,
121 G_UNLOCK (_elem_stats);
122 if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
123 GstElement *parent = GST_ELEMENT_PARENT (element);
125 GstElementStats *parent_stats = get_element_stats (self, parent);
126 stats->parent_ix = parent_stats->index;
129 if (G_UNLIKELY (is_new)) {
130 log_new_element_stats (stats, element);
136 * Get the element/bin owning the pad.
142 * out: the element that contains the peer of the proxy
145 * out: the bin owning the ghostpad
147 /* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
148 * add this as new api, e.g. gst_pad_find_parent_element();
151 get_real_pad_parent (GstPad * pad)
158 parent = GST_OBJECT_PARENT (pad);
160 /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
161 if (parent && GST_IS_GHOST_PAD (parent)) {
162 pad = GST_PAD_CAST (parent);
163 parent = GST_OBJECT_PARENT (pad);
165 return GST_ELEMENT_CAST (parent);
168 static GstPadStats no_pad_stats = { 0, };
171 fill_pad_stats (GstStatsTracer * self, GstPad * pad)
173 GstPadStats *stats = g_slice_new0 (GstPadStats);
175 stats->index = self->num_pads++;
176 stats->parent_ix = G_MAXUINT;
182 log_new_pad_stats (GstPadStats * stats, GstPad * pad)
184 gst_tracer_log_trace (gst_structure_new ("new-pad",
185 "ix", G_TYPE_UINT, stats->index,
186 "parent-ix", G_TYPE_UINT, stats->parent_ix,
187 "name", G_TYPE_STRING, GST_OBJECT_NAME (pad),
188 "type", G_TYPE_STRING, G_OBJECT_TYPE_NAME (pad),
189 "is-ghostpad", G_TYPE_BOOLEAN, GST_IS_GHOST_PAD (pad),
190 "pad-direction", GST_TYPE_PAD_DIRECTION, GST_PAD_DIRECTION (pad),
191 "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (g_thread_self ()), NULL));
195 free_pad_stats (gpointer data)
197 g_slice_free (GstPadStats, data);
201 get_pad_stats (GstStatsTracer * self, GstPad * pad)
204 gboolean is_new = FALSE;
207 no_pad_stats.index = G_MAXUINT;
208 return &no_pad_stats;
212 if (!(stats = g_object_get_qdata ((GObject *) pad, data_quark))) {
213 stats = fill_pad_stats (self, pad);
214 g_object_set_qdata_full ((GObject *) pad, data_quark, stats,
218 G_UNLOCK (_pad_stats);
219 if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
220 GstElement *elem = get_real_pad_parent (pad);
222 GstElementStats *elem_stats = get_element_stats (self, elem);
224 stats->parent_ix = elem_stats->index;
227 if (G_UNLIKELY (is_new)) {
228 log_new_pad_stats (stats, pad);
234 do_buffer_stats (GstStatsTracer * self, GstPad * this_pad,
235 GstPadStats * this_pad_stats, GstPad * that_pad,
236 GstPadStats * that_pad_stats, GstBuffer * buf, GstClockTime elapsed)
238 GstElement *this_elem = get_real_pad_parent (this_pad);
239 GstElementStats *this_elem_stats = get_element_stats (self, this_elem);
240 GstElement *that_elem = get_real_pad_parent (that_pad);
241 GstElementStats *that_elem_stats = get_element_stats (self, that_elem);
243 /* TODO(ensonic): need a quark-table (shared with the tracer-front-ends?) */
244 gst_tracer_log_trace (gst_structure_new ("buffer",
245 "ts", G_TYPE_UINT64, elapsed,
246 "pad-ix", G_TYPE_UINT, this_pad_stats->index,
247 "elem-ix", G_TYPE_UINT, this_elem_stats->index,
248 "peer-pad-ix", G_TYPE_UINT, that_pad_stats->index,
249 "peer-elem-ix", G_TYPE_UINT, that_elem_stats->index,
250 "buffer-size", G_TYPE_UINT, gst_buffer_get_size (buf),
251 "buffer-pts", G_TYPE_UINT64, GST_BUFFER_PTS (buf),
252 "buffer-dts", G_TYPE_UINT64, GST_BUFFER_DTS (buf),
253 "buffer-duration", G_TYPE_UINT64, GST_BUFFER_DURATION (buf),
254 "buffer-flags", GST_TYPE_BUFFER_FLAGS, GST_BUFFER_FLAGS (buf),
256 scheduling-jitter: for this we need the last_ts on the pad
262 do_element_stats (GstStatsTracer * self, GstPad * pad, GstClockTime elapsed1,
263 GstClockTime elapsed2)
265 GstClockTimeDiff elapsed = GST_CLOCK_DIFF (elapsed1, elapsed2);
266 GstObject *parent = GST_OBJECT_PARENT (pad);
268 GST_ELEMENT_CAST (GST_IS_PAD (parent) ? GST_OBJECT_PARENT (parent) :
270 GstElementStats *this_stats = get_element_stats (self, this);
271 GstPad *peer_pad = GST_PAD_PEER (pad);
272 GstElementStats *peer_stats;
277 /* walk the ghost pad chain downstream to get the real pad */
278 /* if parent of peer_pad is a ghost-pad, then peer_pad is a proxy_pad */
279 parent = GST_OBJECT_PARENT (peer_pad);
280 if (parent && GST_IS_GHOST_PAD (parent)) {
281 peer_pad = GST_PAD_CAST (parent);
282 /* if this is now the ghost pad, get the peer of this */
283 get_pad_stats (self, peer_pad);
284 if ((parent = GST_OBJECT_PARENT (peer_pad))) {
285 get_element_stats (self, GST_ELEMENT_CAST (parent));
287 peer_pad = GST_PAD_PEER (GST_GHOST_PAD_CAST (peer_pad));
288 parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
290 /* walk the ghost pad chain upstream to get the real pad */
291 /* if peer_pad is a ghost-pad, then parent is a bin and it is the parent of
293 while (peer_pad && GST_IS_GHOST_PAD (peer_pad)) {
294 get_pad_stats (self, peer_pad);
295 get_element_stats (self, GST_ELEMENT_CAST (parent));
296 peer_pad = gst_ghost_pad_get_target (GST_GHOST_PAD_CAST (peer_pad));
297 parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
301 printf ("%" GST_TIME_FORMAT
302 " transmission on unparented target pad %s_%s -> %s_%s\n",
303 GST_TIME_ARGS (elapsed), GST_DEBUG_PAD_NAME (pad),
304 GST_DEBUG_PAD_NAME (peer_pad));
307 peer_stats = get_element_stats (self, GST_ELEMENT_CAST (parent));
309 /* we'd like to gather time spend in each element, but this does not make too
311 * pure push/pull-based:
312 * - the time spend in the push/pull_range is accounted for the peer and
313 * removed from the current element
314 * - this works for chains
315 * - drawback is sink elements that block to sync have a high time usage
316 * - we could rerun the ests with sync=false
318 * - a.g. demuxers both push and pull. thus we subtract time for the pull
319 * and the push operations, but never add anything.
320 * - can we start a counter after push/pull in such elements and add then
321 * time to the element upon next pad activity?
324 /* this does not make sense for demuxers */
325 this_stats->treal -= elapsed;
326 peer_stats->treal += elapsed;
328 /* this creates several >100% figures */
329 this_stats->treal += GST_CLOCK_DIFF (this_stats->last_ts, elapsed2) - elapsed;
330 peer_stats->treal += elapsed;
331 this_stats->last_ts = elapsed2;
332 peer_stats->last_ts = elapsed2;
339 do_push_buffer_pre (GstStatsTracer * self, guint64 ts, GstPad * this_pad,
342 GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
343 GstPad *that_pad = GST_PAD_PEER (this_pad);
344 GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
346 do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
351 do_push_buffer_post (GstStatsTracer * self, guint64 ts, GstPad * pad)
353 GstPadStats *stats = get_pad_stats (self, pad);
355 do_element_stats (self, pad, stats->last_ts, ts);
360 GstStatsTracer *self;
362 GstPadStats *this_pad_stats;
364 GstPadStats *that_pad_stats;
366 } DoPushBufferListArgs;
369 do_push_buffer_list_item (GstBuffer ** buffer, guint idx, gpointer user_data)
371 DoPushBufferListArgs *args = (DoPushBufferListArgs *) user_data;
373 do_buffer_stats (args->self, args->this_pad, args->this_pad_stats,
374 args->that_pad, args->that_pad_stats, *buffer, args->ts);
379 do_push_buffer_list_pre (GstStatsTracer * self, guint64 ts, GstPad * this_pad,
380 GstBufferList * list)
382 GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
383 GstPad *that_pad = GST_PAD_PEER (this_pad);
384 GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
385 DoPushBufferListArgs args = { self, this_pad, this_pad_stats, that_pad,
389 gst_buffer_list_foreach (list, do_push_buffer_list_item, &args);
393 do_push_buffer_list_post (GstStatsTracer * self, guint64 ts, GstPad * pad)
395 GstPadStats *stats = get_pad_stats (self, pad);
397 do_element_stats (self, pad, stats->last_ts, ts);
401 do_pull_range_pre (GstStatsTracer * self, guint64 ts, GstPad * pad)
403 GstPadStats *stats = get_pad_stats (self, pad);
408 do_pull_range_post (GstStatsTracer * self, guint64 ts, GstPad * this_pad,
411 GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
412 guint64 last_ts = this_pad_stats->last_ts;
413 GstPad *that_pad = GST_PAD_PEER (this_pad);
414 GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
416 if (buffer != NULL) {
417 do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
420 do_element_stats (self, this_pad, last_ts, ts);
424 do_push_event_pre (GstStatsTracer * self, guint64 ts, GstPad * pad,
427 GstElement *elem = get_real_pad_parent (pad);
428 GstElementStats *elem_stats = get_element_stats (self, elem);
429 GstPadStats *pad_stats = get_pad_stats (self, pad);
431 elem_stats->last_ts = ts;
432 gst_tracer_log_trace (gst_structure_new ("event",
433 "ts", G_TYPE_UINT64, ts,
434 "pad-ix", G_TYPE_UINT, pad_stats->index,
435 "elem-ix", G_TYPE_UINT, elem_stats->index,
436 "name", G_TYPE_STRING, GST_EVENT_TYPE_NAME (ev), NULL));
440 do_post_message_pre (GstStatsTracer * self, guint64 ts, GstElement * elem,
443 GstElementStats *stats = get_element_stats (self, elem);
446 gst_tracer_log_trace (gst_structure_new ("message",
447 "ts", G_TYPE_UINT64, ts,
448 "elem-ix", G_TYPE_UINT, stats->index,
449 "name", G_TYPE_STRING, GST_MESSAGE_TYPE_NAME (msg), NULL));
453 do_query_pre (GstStatsTracer * self, guint64 ts, GstElement * elem,
456 GstElementStats *stats = get_element_stats (self, elem);
459 gst_tracer_log_trace (gst_structure_new ("query",
460 "ts", G_TYPE_UINT64, ts,
461 "elem-ix", G_TYPE_UINT, stats->index,
462 "name", G_TYPE_STRING, GST_QUERY_TYPE_NAME (qry), NULL));
468 gst_stats_tracer_class_init (GstStatsTracerClass * klass)
470 /* announce trace formats */
472 gst_tracer_log_trace (gst_structure_new ("buffer.class",
473 "pad-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
474 "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
476 "element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
477 "related-to", G_TYPE_STRING, "element", /* TODO: use genum */
479 "peer-pad-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
480 "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
482 "peer-element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
483 "related-to", G_TYPE_STRING, "element", /* TODO: use genum */
485 "buffer-size", GST_TYPE_STRUCTURE, gst_structure_new ("value",
486 "type", G_TYPE_GTYPE, G_TYPE_UINT,
487 "description", G_TYPE_STRING, "size of buffer in bytes",
488 "flags", G_TYPE_STRING, "", /* TODO: use gflags */
489 "min", G_TYPE_UINT, 0,
490 "max", G_TYPE_UINT, G_MAXUINT,
492 "buffer-ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
493 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
494 "description", G_TYPE_STRING, "timestamp of the buffer in ns",
495 "flags", G_TYPE_STRING, "", /* TODO: use gflags */
496 "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
497 "max", G_TYPE_UINT64, G_MAXUINT64,
499 "buffer-duration", GST_TYPE_STRUCTURE, gst_structure_new ("value",
500 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
501 "description", G_TYPE_STRING, "duration of the buffer in ns",
502 "flags", G_TYPE_STRING, "", /* TODO: use gflags */
503 "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
504 "max", G_TYPE_UINT64, G_MAXUINT64,
506 /* TODO(ensonic): "buffer-flags" */
508 gst_tracer_log_trace (gst_structure_new ("event.class",
509 "pad-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
510 "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
512 "element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
513 "related-to", G_TYPE_STRING, "element", /* TODO: use genum */
515 "name", GST_TYPE_STRUCTURE, gst_structure_new ("value",
516 "type", G_TYPE_GTYPE, G_TYPE_STRING,
517 "description", G_TYPE_STRING, "name of the event",
518 "flags", G_TYPE_STRING, "", /* TODO: use gflags */
521 gst_tracer_log_trace (gst_structure_new ("message.class",
522 "element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
523 "related-to", G_TYPE_STRING, "element", /* TODO: use genum */
525 "name", GST_TYPE_STRUCTURE, gst_structure_new ("value",
526 "type", G_TYPE_GTYPE, G_TYPE_STRING,
527 "description", G_TYPE_STRING, "name of the message",
528 "flags", G_TYPE_STRING, "", /* TODO: use gflags */
531 gst_tracer_log_trace (gst_structure_new ("query.class",
532 "element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
533 "related-to", G_TYPE_STRING, "element", /* TODO: use genum */
535 "name", GST_TYPE_STRUCTURE, gst_structure_new ("value",
536 "type", G_TYPE_GTYPE, G_TYPE_STRING,
537 "description", G_TYPE_STRING, "name of the query",
538 "flags", G_TYPE_STRING, "", /* TODO: use gflags */
545 gst_stats_tracer_init (GstStatsTracer * self)
547 GstTracer *tracer = GST_TRACER (self);
549 gst_tracing_register_hook (tracer, "pad-push-pre",
550 G_CALLBACK (do_push_buffer_pre));
551 gst_tracing_register_hook (tracer, "pad-push-post",
552 G_CALLBACK (do_push_buffer_post));
553 gst_tracing_register_hook (tracer, "pad-push-list-pre",
554 G_CALLBACK (do_push_buffer_list_pre));
555 gst_tracing_register_hook (tracer, "pad-push-list-post",
556 G_CALLBACK (do_push_buffer_list_post));
557 gst_tracing_register_hook (tracer, "pad-pull-range-pre",
558 G_CALLBACK (do_pull_range_pre));
559 gst_tracing_register_hook (tracer, "pad-pull-range-post",
560 G_CALLBACK (do_pull_range_post));
561 gst_tracing_register_hook (tracer, "pad-push-event-pre",
562 G_CALLBACK (do_push_event_pre));
563 gst_tracing_register_hook (tracer, "element-post-message-pre",
564 G_CALLBACK (do_post_message_pre));
565 gst_tracing_register_hook (tracer, "element-query-pre",
566 G_CALLBACK (do_query_pre));