stats: improve the handling of parentage
[platform/upstream/gstreamer.git] / plugins / tracers / gststats.c
1 /* GStreamer
2  * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
3  *
4  * gststats.c: tracing module that logs events
5  *
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.
10  *
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.
15  *
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.
20  */
21
22 #ifdef HAVE_CONFIG_H
23 #  include "config.h"
24 #endif
25
26 #include "gststats.h"
27
28 #include <stdio.h>
29
30 GST_DEBUG_CATEGORY_STATIC (gst_stats_debug);
31 #define GST_CAT_DEFAULT gst_stats_debug
32
33 static GQuark data_quark;
34 G_LOCK_DEFINE (_stats);
35
36 #define _do_init \
37     GST_DEBUG_CATEGORY_INIT (gst_stats_debug, "stats", 0, "stats tracer"); \
38     data_quark = g_quark_from_static_string ("gststats:data");
39 #define gst_stats_tracer_parent_class parent_class
40 G_DEFINE_TYPE_WITH_CODE (GstStatsTracer, gst_stats_tracer, GST_TYPE_TRACER,
41     _do_init);
42
43 typedef struct
44 {
45   /* we can't rely on the address to be unique over time */
46   guint index;
47   /* for pre + post */
48   GstClockTime last_ts;
49   /* hierarchy */
50   guint parent_ix;
51 } GstPadStats;
52
53 typedef struct
54 {
55   /* we can't rely on the address to be unique over time */
56   guint index;
57   /* for pre + post */
58   GstClockTime last_ts;
59   /* time spend in this element */
60   GstClockTime treal;
61   /* hierarchy */
62   guint parent_ix;
63 } GstElementStats;
64
65 /* logging */
66
67 static void
68 log_trace (GstStructure * s)
69 {
70   gchar *data;
71
72   // TODO(ensonic): use a GVariant?
73   data = gst_structure_to_string (s);
74   GST_TRACE ("%s", data);
75   g_free (data);
76   gst_structure_free (s);
77 }
78
79 /* data helper */
80
81 static GstElementStats no_elem_stats = { 0, };
82
83 static GstElementStats *
84 fill_element_stats (GstStatsTracer * self, GstElement * element)
85 {
86   GstElementStats *stats = g_slice_new0 (GstElementStats);
87
88   stats->index = self->num_elements++;
89   stats->parent_ix = G_MAXUINT;
90   return stats;
91 }
92
93 static void
94 log_new_element_stats (GstElementStats * stats, GstElement * element)
95 {
96   log_trace (gst_structure_new ("new-element",
97           "ix", G_TYPE_UINT, stats->index,
98           "parent-ix", G_TYPE_UINT, stats->parent_ix,
99           "name", G_TYPE_STRING, GST_OBJECT_NAME (element),
100           "type", G_TYPE_STRING, G_OBJECT_TYPE_NAME (element),
101           "is-bin", G_TYPE_BOOLEAN, GST_IS_BIN (element), NULL));
102 }
103
104 static inline GstElementStats *
105 get_element_stats (GstStatsTracer * self, GstElement * element)
106 {
107   GstElementStats *stats;
108   gboolean is_new = FALSE;
109
110   if (!element) {
111     no_elem_stats.index = G_MAXUINT;
112     return &no_elem_stats;
113   }
114
115   G_LOCK (_stats);
116   if (!(stats = g_object_get_qdata ((GObject *) element, data_quark))) {
117     stats = fill_element_stats (self, element);
118     g_object_set_qdata ((GObject *) element, data_quark, stats);
119     if (self->elements->len <= stats->index)
120       g_ptr_array_set_size (self->elements, stats->index + 1);
121     g_ptr_array_index (self->elements, stats->index) = stats;
122     is_new = TRUE;
123   }
124   G_UNLOCK (_stats);
125   if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
126     GstElement *parent = GST_ELEMENT_PARENT (element);
127     if (parent) {
128       GstElementStats *parent_stats = get_element_stats (self, parent);
129       stats->parent_ix = parent_stats->index;
130     }
131   }
132   if (G_UNLIKELY (is_new)) {
133     log_new_element_stats (stats, element);
134   }
135   return stats;
136 }
137
138 static void
139 free_element_stats (gpointer data)
140 {
141   g_slice_free (GstElementStats, data);
142 }
143
144 /*
145  * Get the element/bin owning the pad. 
146  *
147  * in: a normal pad
148  * out: the element
149  *
150  * in: a proxy pad
151  * out: the element that contains the peer of the proxy
152  *
153  * in: a ghost pad
154  * out: the bin owning the ghostpad
155  */
156 /* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
157  * add this as new api, e.g. gst_pad_find_parent_element();
158  */
159 static GstElement *
160 get_real_pad_parent (GstPad * pad)
161 {
162   GstObject *parent;
163
164   if (!pad)
165     return NULL;
166
167   parent = GST_OBJECT_PARENT (pad);
168
169   /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
170   if (parent && GST_IS_GHOST_PAD (parent)) {
171     pad = GST_PAD_CAST (parent);
172     parent = GST_OBJECT_PARENT (pad);
173   }
174   /* if pad is a ghost-pad, then parent is a bin and it is the parent of a
175    * proxy_pad */
176   while (parent && GST_IS_GHOST_PAD (pad)) {
177     pad = gst_ghost_pad_get_target (GST_GHOST_PAD (pad));
178     parent = pad ? GST_OBJECT_PARENT (pad) : NULL;
179   }
180   return GST_ELEMENT_CAST (parent);
181 }
182
183 static GstPadStats no_pad_stats = { 0, };
184
185 static GstPadStats *
186 fill_pad_stats (GstStatsTracer * self, GstPad * pad)
187 {
188   GstPadStats *stats = g_slice_new0 (GstPadStats);
189
190   stats->index = self->num_pads++;
191   stats->parent_ix = G_MAXUINT;
192
193   return stats;
194 }
195
196 static void
197 log_new_pad_stats (GstPadStats * stats, GstPad * pad)
198 {
199   log_trace (gst_structure_new ("new-pad",
200           "ix", G_TYPE_UINT, stats->index,
201           "parent-ix", G_TYPE_UINT, stats->parent_ix,
202           "name", G_TYPE_STRING, GST_OBJECT_NAME (pad),
203           "type", G_TYPE_STRING, G_OBJECT_TYPE_NAME (pad),
204           "is-ghostpad", G_TYPE_BOOLEAN, GST_IS_GHOST_PAD (pad),
205           "pad-direction", GST_TYPE_PAD_DIRECTION, GST_PAD_DIRECTION (pad),
206           "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (g_thread_self ()), NULL));
207 }
208
209 static GstPadStats *
210 get_pad_stats (GstStatsTracer * self, GstPad * pad)
211 {
212   GstPadStats *stats;
213   gboolean is_new = FALSE;
214
215   if (!pad) {
216     no_pad_stats.index = G_MAXUINT;
217     return &no_pad_stats;
218   }
219
220   G_LOCK (_stats);
221   if (!(stats = g_object_get_qdata ((GObject *) pad, data_quark))) {
222     stats = fill_pad_stats (self, pad);
223     g_object_set_qdata ((GObject *) pad, data_quark, stats);
224     if (self->pads->len <= stats->index)
225       g_ptr_array_set_size (self->pads, stats->index + 1);
226     g_ptr_array_index (self->pads, stats->index) = stats;
227     is_new = TRUE;
228   }
229   G_UNLOCK (_stats);
230   if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
231     GstElement *elem = get_real_pad_parent (pad);
232     if (elem) {
233       GstElementStats *elem_stats = get_element_stats (self, elem);
234
235       stats->parent_ix = elem_stats->index;
236     }
237   }
238   if (G_UNLIKELY (is_new)) {
239     log_new_pad_stats (stats, pad);
240   }
241   return stats;
242 }
243
244 static void
245 free_pad_stats (gpointer data)
246 {
247   g_slice_free (GstPadStats, data);
248 }
249
250 static void
251 do_buffer_stats (GstStatsTracer * self, GstPad * this_pad,
252     GstPadStats * this_pad_stats, GstPad * that_pad,
253     GstPadStats * that_pad_stats, GstBuffer * buf, GstClockTime elapsed)
254 {
255   GstElement *this_elem = get_real_pad_parent (this_pad);
256   GstElementStats *this_elem_stats = get_element_stats (self, this_elem);
257   GstElement *that_elem = get_real_pad_parent (that_pad);
258   GstElementStats *that_elem_stats = get_element_stats (self, that_elem);
259
260   /* TODO(ensonic): need a quark-table (shared with the tracer-front-ends?) */
261   log_trace (gst_structure_new ("buffer",
262           "ts", G_TYPE_UINT64, elapsed,
263           "pad-ix", G_TYPE_UINT, this_pad_stats->index,
264           "elem-ix", G_TYPE_UINT, this_elem_stats->index,
265           "peer-pad-ix", G_TYPE_UINT, that_pad_stats->index,
266           "peer-elem-ix", G_TYPE_UINT, that_elem_stats->index,
267           "buffer-size", G_TYPE_UINT, gst_buffer_get_size (buf),
268           "buffer-ts", G_TYPE_UINT64, GST_BUFFER_TIMESTAMP (buf),
269           "buffer-duration", G_TYPE_UINT64, GST_BUFFER_DURATION (buf),
270           "buffer-flags", GST_TYPE_BUFFER_FLAGS, GST_BUFFER_FLAGS (buf),
271           /*
272              scheduling-jitter: for this we need the last_ts on the pad
273            */
274           NULL));
275 }
276
277 static void
278 do_element_stats (GstStatsTracer * self, GstPad * pad, GstClockTime elapsed1,
279     GstClockTime elapsed2)
280 {
281   GstClockTimeDiff elapsed = GST_CLOCK_DIFF (elapsed1, elapsed2);
282   GstObject *parent = GST_OBJECT_PARENT (pad);
283   GstElement *this =
284       GST_ELEMENT_CAST (GST_IS_PAD (parent) ? GST_OBJECT_PARENT (parent) :
285       parent);
286   GstElementStats *this_stats = get_element_stats (self, this);
287   GstPad *peer_pad = GST_PAD_PEER (pad);
288   GstElementStats *peer_stats;
289
290   if (!peer_pad)
291     return;
292
293   /* walk the ghost pad chain downstream to get the real pad */
294   /* if parent of peer_pad is a ghost-pad, then peer_pad is a proxy_pad */
295   parent = GST_OBJECT_PARENT (peer_pad);
296   if (parent && GST_IS_GHOST_PAD (parent)) {
297     peer_pad = GST_PAD_CAST (parent);
298     /* if this is now the ghost pad, get the peer of this */
299     get_pad_stats (self, peer_pad);
300     if ((parent = GST_OBJECT_PARENT (peer_pad))) {
301       get_element_stats (self, GST_ELEMENT_CAST (parent));
302     }
303     peer_pad = GST_PAD_PEER (GST_GHOST_PAD_CAST (peer_pad));
304     parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
305   }
306   /* walk the ghost pad chain upstream to get the real pad */
307   /* if peer_pad is a ghost-pad, then parent is a bin and it is the parent of
308    * a proxy_pad */
309   while (peer_pad && GST_IS_GHOST_PAD (peer_pad)) {
310     get_pad_stats (self, peer_pad);
311     get_element_stats (self, GST_ELEMENT_CAST (parent));
312     peer_pad = gst_ghost_pad_get_target (GST_GHOST_PAD_CAST (peer_pad));
313     parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
314   }
315
316   if (!parent) {
317     printf ("%" GST_TIME_FORMAT
318         " transmission on unparented target pad %s_%s -> %s_%s\n",
319         GST_TIME_ARGS (elapsed), GST_DEBUG_PAD_NAME (pad),
320         GST_DEBUG_PAD_NAME (peer_pad));
321     return;
322   }
323   peer_stats = get_element_stats (self, GST_ELEMENT_CAST (parent));
324
325   /* we'd like to gather time spend in each element, but this does not make too
326    * much sense yet
327    * pure push/pull-based:
328    *   - the time spend in the push/pull_range is accounted for the peer and
329    *     removed from the current element
330    *   - this works for chains
331    *   - drawback is sink elements that block to sync have a high time usage
332    *     - we could rerun the ests with sync=false
333    * both:
334    *   - a.g. demuxers both push and pull. thus we subtract time for the pull
335    *     and the push operations, but never add anything.
336    *   - can we start a counter after push/pull in such elements and add then
337    *     time to the element upon next pad activity?
338    */
339 #if 1
340   /* this does not make sense for demuxers */
341   this_stats->treal -= elapsed;
342   peer_stats->treal += elapsed;
343 #else
344   /* this creates several >100% figures */
345   this_stats->treal += GST_CLOCK_DIFF (this_stats->last_ts, elapsed2) - elapsed;
346   peer_stats->treal += elapsed;
347   this_stats->last_ts = elapsed2;
348   peer_stats->last_ts = elapsed2;
349 #endif
350 }
351
352 /* tracer class */
353
354 static void gst_stats_tracer_finalize (GObject * obj);
355 static void gst_stats_tracer_invoke (GstTracer * obj, GstTracerHookId id,
356     GstTracerMessageId mid, va_list var_args);
357
358 static void
359 gst_stats_tracer_class_init (GstStatsTracerClass * klass)
360 {
361   GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
362   GstTracerClass *gst_tracer_class = GST_TRACER_CLASS (klass);
363
364   gobject_class->finalize = gst_stats_tracer_finalize;
365
366   gst_tracer_class->invoke = gst_stats_tracer_invoke;
367 }
368
369 static void
370 gst_stats_tracer_init (GstStatsTracer * self)
371 {
372   g_object_set (self, "mask",
373       GST_TRACER_HOOK_BUFFERS | GST_TRACER_HOOK_EVENTS |
374       GST_TRACER_HOOK_MESSAGES | GST_TRACER_HOOK_QUERIES, NULL);
375   self->elements = g_ptr_array_new_with_free_func (free_element_stats);
376   self->pads = g_ptr_array_new_with_free_func (free_pad_stats);
377 }
378
379 /* hooks */
380
381 static void
382 do_push_buffer_pre (GstStatsTracer * self, va_list var_args)
383 {
384   guint64 ts = va_arg (var_args, guint64);
385   GstPad *this_pad = va_arg (var_args, GstPad *);
386   GstBuffer *buffer = va_arg (var_args, GstBuffer *);
387   GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
388   GstPad *that_pad = GST_PAD_PEER (this_pad);
389   GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
390
391   do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
392       buffer, ts);
393 }
394
395 static void
396 do_push_buffer_post (GstStatsTracer * self, va_list var_args)
397 {
398   guint64 ts = va_arg (var_args, guint64);
399   GstPad *pad = va_arg (var_args, GstPad *);
400   GstPadStats *stats = get_pad_stats (self, pad);
401
402   do_element_stats (self, pad, stats->last_ts, ts);
403 }
404
405 typedef struct
406 {
407   GstStatsTracer *self;
408   GstPad *this_pad;
409   GstPadStats *this_pad_stats;
410   GstPad *that_pad;
411   GstPadStats *that_pad_stats;
412   guint64 ts;
413 } DoPushBufferListArgs;
414
415 static gboolean
416 do_push_buffer_list_item (GstBuffer ** buffer, guint idx, gpointer user_data)
417 {
418   DoPushBufferListArgs *args = (DoPushBufferListArgs *) user_data;
419
420   do_buffer_stats (args->self, args->this_pad, args->this_pad_stats,
421       args->that_pad, args->that_pad_stats, *buffer, args->ts);
422   return TRUE;
423 }
424
425 static void
426 do_push_buffer_list_pre (GstStatsTracer * self, va_list var_args)
427 {
428   guint64 ts = va_arg (var_args, guint64);
429   GstPad *this_pad = va_arg (var_args, GstPad *);
430   GstBufferList *list = va_arg (var_args, GstBufferList *);
431   GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
432   GstPad *that_pad = GST_PAD_PEER (this_pad);
433   GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
434   DoPushBufferListArgs args = { self, this_pad, this_pad_stats, that_pad,
435     that_pad_stats, ts
436   };
437
438   gst_buffer_list_foreach (list, do_push_buffer_list_item, &args);
439 }
440
441 static void
442 do_push_buffer_list_post (GstStatsTracer * self, va_list var_args)
443 {
444   guint64 ts = va_arg (var_args, guint64);
445   GstPad *pad = va_arg (var_args, GstPad *);
446   GstPadStats *stats = get_pad_stats (self, pad);
447
448   do_element_stats (self, pad, stats->last_ts, ts);
449 }
450
451 static void
452 do_pull_range_pre (GstStatsTracer * self, va_list var_args)
453 {
454   guint64 ts = va_arg (var_args, guint64);
455   GstPad *pad = va_arg (var_args, GstPad *);
456   GstPadStats *stats = get_pad_stats (self, pad);
457   stats->last_ts = ts;
458 }
459
460 static void
461 do_pull_range_post (GstStatsTracer * self, va_list var_args)
462 {
463   guint64 ts = va_arg (var_args, guint64);
464   GstPad *this_pad = va_arg (var_args, GstPad *);
465   GstBuffer *buffer = va_arg (var_args, GstBuffer *);
466   GstPadStats *this_pad_stats = get_pad_stats (self, this_pad);
467   guint64 last_ts = this_pad_stats->last_ts;
468   GstPad *that_pad = GST_PAD_PEER (this_pad);
469   GstPadStats *that_pad_stats = get_pad_stats (self, that_pad);
470
471   if (buffer != NULL) {
472     do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
473         buffer, ts);
474   }
475   do_element_stats (self, this_pad, last_ts, ts);
476 }
477
478 static void
479 do_push_event_pre (GstStatsTracer * self, va_list var_args)
480 {
481   guint64 ts = va_arg (var_args, guint64);
482   GstPad *pad = va_arg (var_args, GstPad *);
483   GstEvent *ev = va_arg (var_args, GstEvent *);
484   GstElement *elem = get_real_pad_parent (pad);
485   GstElementStats *elem_stats = get_element_stats (self, elem);
486   GstPadStats *pad_stats = get_pad_stats (self, pad);
487
488   elem_stats->last_ts = ts;
489   log_trace (gst_structure_new ("event",
490           "ts", G_TYPE_UINT64, ts,
491           "pad-ix", G_TYPE_UINT, pad_stats->index,
492           "elem-ix", G_TYPE_UINT, elem_stats->index,
493           "name", G_TYPE_STRING, GST_EVENT_TYPE_NAME (ev), NULL));
494 }
495
496 static void
497 do_push_event_post (GstStatsTracer * self, va_list var_args)
498 {
499 #if 0
500   guint64 ts = va_arg (var_args, guint64);
501   GstPad *pad = va_arg (var_args, GstPad *);
502 #endif
503 }
504
505 static void
506 do_post_message_pre (GstStatsTracer * self, va_list var_args)
507 {
508   guint64 ts = va_arg (var_args, guint64);
509   GstElement *elem = va_arg (var_args, GstElement *);
510   GstMessage *msg = va_arg (var_args, GstMessage *);
511   GstElementStats *stats = get_element_stats (self, elem);
512
513   stats->last_ts = ts;
514   log_trace (gst_structure_new ("message",
515           "ts", G_TYPE_UINT64, ts,
516           "elem-ix", G_TYPE_UINT, stats->index,
517           "name", G_TYPE_STRING, GST_MESSAGE_TYPE_NAME (msg), NULL));
518 }
519
520 static void
521 do_post_message_post (GstStatsTracer * self, va_list var_args)
522 {
523 #if 0
524   guint64 ts = va_arg (var_args, guint64);
525   GstElement *elem = va_arg (var_args, GstElement *);
526 #endif
527 }
528
529 static void
530 do_query_pre (GstStatsTracer * self, va_list var_args)
531 {
532   guint64 ts = va_arg (var_args, guint64);
533   GstElement *elem = va_arg (var_args, GstElement *);
534   GstQuery *qry = va_arg (var_args, GstQuery *);
535   GstElementStats *stats = get_element_stats (self, elem);
536
537   stats->last_ts = ts;
538   log_trace (gst_structure_new ("query",
539           "ts", G_TYPE_UINT64, ts,
540           "elem-ix", G_TYPE_UINT, stats->index,
541           "name", G_TYPE_STRING, GST_QUERY_TYPE_NAME (qry), NULL));
542 }
543
544 static void
545 do_query_post (GstStatsTracer * self, va_list var_args)
546 {
547 #if 0
548   guint64 ts = va_arg (var_args, guint64);
549   GstElement *elem = va_arg (var_args, GstElement *);
550 #endif
551 }
552
553 static void
554 gst_stats_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
555     GstTracerMessageId mid, va_list var_args)
556 {
557   GstStatsTracer *self = GST_STATS_TRACER_CAST (obj);
558
559   switch (mid) {
560     case GST_TRACER_MESSAGE_ID_PAD_PUSH_PRE:
561       do_push_buffer_pre (self, var_args);
562       break;
563     case GST_TRACER_MESSAGE_ID_PAD_PUSH_POST:
564       do_push_buffer_post (self, var_args);
565       break;
566     case GST_TRACER_MESSAGE_ID_PAD_PUSH_LIST_PRE:
567       do_push_buffer_list_pre (self, var_args);
568       break;
569     case GST_TRACER_MESSAGE_ID_PAD_PUSH_LIST_POST:
570       do_push_buffer_list_post (self, var_args);
571       break;
572     case GST_TRACER_MESSAGE_ID_PAD_PULL_RANGE_PRE:
573       do_pull_range_pre (self, var_args);
574       break;
575     case GST_TRACER_MESSAGE_ID_PAD_PULL_RANGE_POST:
576       do_pull_range_post (self, var_args);
577       break;
578     case GST_TRACER_MESSAGE_ID_PAD_PUSH_EVENT_PRE:
579       do_push_event_pre (self, var_args);
580       break;
581     case GST_TRACER_MESSAGE_ID_PAD_PUSH_EVENT_POST:
582       do_push_event_post (self, var_args);
583       break;
584     case GST_TRACER_MESSAGE_ID_ELEMENT_POST_MESSAGE_PRE:
585       do_post_message_pre (self, var_args);
586       break;
587     case GST_TRACER_MESSAGE_ID_ELEMENT_POST_MESSAGE_POST:
588       do_post_message_post (self, var_args);
589       break;
590     case GST_TRACER_MESSAGE_ID_ELEMENT_QUERY_PRE:
591       do_query_pre (self, var_args);
592       break;
593     case GST_TRACER_MESSAGE_ID_ELEMENT_QUERY_POST:
594       do_query_post (self, var_args);
595       break;
596     default:
597       break;
598   }
599 }
600
601 static void
602 gst_stats_tracer_finalize (GObject * obj)
603 {
604   //GstStatsTracer *self = GST_STATS_TRACER_CAST (obj);
605
606   G_OBJECT_CLASS (parent_class)->finalize (obj);
607 }