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