stats: TIMESTAMP -> PTS
[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  * SECTION:gststats
23  * @short_description: log event stats
24  *
25  * A tracing module that builds usage statistic for elements and pads. 
26  */
27
28 #ifdef HAVE_CONFIG_H
29 #  include "config.h"
30 #endif
31
32 #include "gststats.h"
33
34 #include <stdio.h>
35
36 GST_DEBUG_CATEGORY_STATIC (gst_stats_debug);
37 #define GST_CAT_DEFAULT gst_stats_debug
38
39 static GQuark data_quark;
40 G_LOCK_DEFINE (_elem_stats);
41 G_LOCK_DEFINE (_pad_stats);
42
43 #define _do_init \
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,
48     _do_init);
49
50 typedef struct
51 {
52   /* we can't rely on the address to be unique over time */
53   guint index;
54   /* for pre + post */
55   GstClockTime last_ts;
56   /* hierarchy */
57   guint parent_ix;
58 } GstPadStats;
59
60 typedef struct
61 {
62   /* we can't rely on the address to be unique over time */
63   guint index;
64   /* for pre + post */
65   GstClockTime last_ts;
66   /* time spend in this element */
67   GstClockTime treal;
68   /* hierarchy */
69   guint parent_ix;
70 } GstElementStats;
71
72 /* data helper */
73
74 static GstElementStats no_elem_stats = { 0, };
75
76 static GstElementStats *
77 fill_element_stats (GstStatsTracer * self, GstElement * element)
78 {
79   GstElementStats *stats = g_slice_new0 (GstElementStats);
80
81   stats->index = self->num_elements++;
82   stats->parent_ix = G_MAXUINT;
83   return stats;
84 }
85
86 static void
87 log_new_element_stats (GstElementStats * stats, GstElement * element)
88 {
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));
95 }
96
97 static void
98 free_element_stats (gpointer data)
99 {
100   g_slice_free (GstElementStats, data);
101 }
102
103 static inline GstElementStats *
104 get_element_stats (GstStatsTracer * self, GstElement * element)
105 {
106   GstElementStats *stats;
107   gboolean is_new = FALSE;
108
109   if (!element) {
110     no_elem_stats.index = G_MAXUINT;
111     return &no_elem_stats;
112   }
113
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,
118         free_element_stats);
119     is_new = TRUE;
120   }
121   G_UNLOCK (_elem_stats);
122   if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
123     GstElement *parent = GST_ELEMENT_PARENT (element);
124     if (parent) {
125       GstElementStats *parent_stats = get_element_stats (self, parent);
126       stats->parent_ix = parent_stats->index;
127     }
128   }
129   if (G_UNLIKELY (is_new)) {
130     log_new_element_stats (stats, element);
131   }
132   return stats;
133 }
134
135 /*
136  * Get the element/bin owning the pad. 
137  *
138  * in: a normal pad
139  * out: the element
140  *
141  * in: a proxy pad
142  * out: the element that contains the peer of the proxy
143  *
144  * in: a ghost pad
145  * out: the bin owning the ghostpad
146  */
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();
149  */
150 static GstElement *
151 get_real_pad_parent (GstPad * pad)
152 {
153   GstObject *parent;
154
155   if (!pad)
156     return NULL;
157
158   parent = GST_OBJECT_PARENT (pad);
159
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);
164   }
165   return GST_ELEMENT_CAST (parent);
166 }
167
168 static GstPadStats no_pad_stats = { 0, };
169
170 static GstPadStats *
171 fill_pad_stats (GstStatsTracer * self, GstPad * pad)
172 {
173   GstPadStats *stats = g_slice_new0 (GstPadStats);
174
175   stats->index = self->num_pads++;
176   stats->parent_ix = G_MAXUINT;
177
178   return stats;
179 }
180
181 static void
182 log_new_pad_stats (GstPadStats * stats, GstPad * pad)
183 {
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));
192 }
193
194 static void
195 free_pad_stats (gpointer data)
196 {
197   g_slice_free (GstPadStats, data);
198 }
199
200 static GstPadStats *
201 get_pad_stats (GstStatsTracer * self, GstPad * pad)
202 {
203   GstPadStats *stats;
204   gboolean is_new = FALSE;
205
206   if (!pad) {
207     no_pad_stats.index = G_MAXUINT;
208     return &no_pad_stats;
209   }
210
211   G_LOCK (_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,
215         free_pad_stats);
216     is_new = TRUE;
217   }
218   G_UNLOCK (_pad_stats);
219   if (G_UNLIKELY (stats->parent_ix == G_MAXUINT)) {
220     GstElement *elem = get_real_pad_parent (pad);
221     if (elem) {
222       GstElementStats *elem_stats = get_element_stats (self, elem);
223
224       stats->parent_ix = elem_stats->index;
225     }
226   }
227   if (G_UNLIKELY (is_new)) {
228     log_new_pad_stats (stats, pad);
229   }
230   return stats;
231 }
232
233 static void
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)
237 {
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);
242
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),
255           /*
256              scheduling-jitter: for this we need the last_ts on the pad
257            */
258           NULL));
259 }
260
261 static void
262 do_element_stats (GstStatsTracer * self, GstPad * pad, GstClockTime elapsed1,
263     GstClockTime elapsed2)
264 {
265   GstClockTimeDiff elapsed = GST_CLOCK_DIFF (elapsed1, elapsed2);
266   GstObject *parent = GST_OBJECT_PARENT (pad);
267   GstElement *this =
268       GST_ELEMENT_CAST (GST_IS_PAD (parent) ? GST_OBJECT_PARENT (parent) :
269       parent);
270   GstElementStats *this_stats = get_element_stats (self, this);
271   GstPad *peer_pad = GST_PAD_PEER (pad);
272   GstElementStats *peer_stats;
273
274   if (!peer_pad)
275     return;
276
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));
286     }
287     peer_pad = GST_PAD_PEER (GST_GHOST_PAD_CAST (peer_pad));
288     parent = peer_pad ? GST_OBJECT_PARENT (peer_pad) : NULL;
289   }
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
292    * a proxy_pad */
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;
298   }
299
300   if (!parent) {
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));
305     return;
306   }
307   peer_stats = get_element_stats (self, GST_ELEMENT_CAST (parent));
308
309   /* we'd like to gather time spend in each element, but this does not make too
310    * much sense yet
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
317    * both:
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?
322    */
323 #if 1
324   /* this does not make sense for demuxers */
325   this_stats->treal -= elapsed;
326   peer_stats->treal += elapsed;
327 #else
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;
333 #endif
334 }
335
336 /* hooks */
337
338 static void
339 do_push_buffer_pre (GstStatsTracer * self, guint64 ts, GstPad * this_pad,
340     GstBuffer * buffer)
341 {
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);
345
346   do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
347       buffer, ts);
348 }
349
350 static void
351 do_push_buffer_post (GstStatsTracer * self, guint64 ts, GstPad * pad)
352 {
353   GstPadStats *stats = get_pad_stats (self, pad);
354
355   do_element_stats (self, pad, stats->last_ts, ts);
356 }
357
358 typedef struct
359 {
360   GstStatsTracer *self;
361   GstPad *this_pad;
362   GstPadStats *this_pad_stats;
363   GstPad *that_pad;
364   GstPadStats *that_pad_stats;
365   guint64 ts;
366 } DoPushBufferListArgs;
367
368 static gboolean
369 do_push_buffer_list_item (GstBuffer ** buffer, guint idx, gpointer user_data)
370 {
371   DoPushBufferListArgs *args = (DoPushBufferListArgs *) user_data;
372
373   do_buffer_stats (args->self, args->this_pad, args->this_pad_stats,
374       args->that_pad, args->that_pad_stats, *buffer, args->ts);
375   return TRUE;
376 }
377
378 static void
379 do_push_buffer_list_pre (GstStatsTracer * self, guint64 ts, GstPad * this_pad,
380     GstBufferList * list)
381 {
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,
386     that_pad_stats, ts
387   };
388
389   gst_buffer_list_foreach (list, do_push_buffer_list_item, &args);
390 }
391
392 static void
393 do_push_buffer_list_post (GstStatsTracer * self, guint64 ts, GstPad * pad)
394 {
395   GstPadStats *stats = get_pad_stats (self, pad);
396
397   do_element_stats (self, pad, stats->last_ts, ts);
398 }
399
400 static void
401 do_pull_range_pre (GstStatsTracer * self, guint64 ts, GstPad * pad)
402 {
403   GstPadStats *stats = get_pad_stats (self, pad);
404   stats->last_ts = ts;
405 }
406
407 static void
408 do_pull_range_post (GstStatsTracer * self, guint64 ts, GstPad * this_pad,
409     GstBuffer * buffer)
410 {
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);
415
416   if (buffer != NULL) {
417     do_buffer_stats (self, this_pad, this_pad_stats, that_pad, that_pad_stats,
418         buffer, ts);
419   }
420   do_element_stats (self, this_pad, last_ts, ts);
421 }
422
423 static void
424 do_push_event_pre (GstStatsTracer * self, guint64 ts, GstPad * pad,
425     GstEvent * ev)
426 {
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);
430
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));
437 }
438
439 static void
440 do_post_message_pre (GstStatsTracer * self, guint64 ts, GstElement * elem,
441     GstMessage * msg)
442 {
443   GstElementStats *stats = get_element_stats (self, elem);
444
445   stats->last_ts = ts;
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));
450 }
451
452 static void
453 do_query_pre (GstStatsTracer * self, guint64 ts, GstElement * elem,
454     GstQuery * qry)
455 {
456   GstElementStats *stats = get_element_stats (self, elem);
457
458   stats->last_ts = ts;
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));
463 }
464
465 /* tracer class */
466
467 static void
468 gst_stats_tracer_class_init (GstStatsTracerClass * klass)
469 {
470   /* announce trace formats */
471   /* *INDENT-OFF* */
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 */
475           NULL),
476       "element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
477           "related-to", G_TYPE_STRING, "element",  /* TODO: use genum */
478           NULL),
479       "peer-pad-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
480           "related-to", G_TYPE_STRING, "pad",  /* TODO: use genum */
481           NULL),
482       "peer-element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
483           "related-to", G_TYPE_STRING, "element",  /* TODO: use genum */
484           NULL),
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,
491           NULL),
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,
498           NULL),
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,
505           NULL),
506       /* TODO(ensonic): "buffer-flags" */
507       NULL));
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 */
511           NULL),
512       "element-ix", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
513           "related-to", G_TYPE_STRING, "element",  /* TODO: use genum */
514           NULL),
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 */ 
519           NULL),
520       NULL));
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 */
524           NULL),
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 */ 
529           NULL),
530       NULL));
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 */
534           NULL),
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 */ 
539           NULL),
540       NULL));
541   /* *INDENT-ON* */
542 }
543
544 static void
545 gst_stats_tracer_init (GstStatsTracer * self)
546 {
547   GstTracer *tracer = GST_TRACER (self);
548
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));
567 }