tools/gst-stats.c

   1 /* GStreamer
   2  * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
   3  *
   4  * gst-stats.c: statistics tracing front end
   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 <stdlib.h>
  27 #include <stdio.h>
  28 #include <string.h>
  29
  30 #include "tools.h"
  31
  32 /* log parser */
  33 static GRegex *raw_log = NULL;
  34 static GRegex *ansi_log = NULL;
  35
  36 /* global statistics */
  37 static GHashTable *threads = NULL;
  38 static GPtrArray *elements = NULL;
  39 static GPtrArray *pads = NULL;
  40 static guint64 num_buffers = 0, num_events = 0, num_messages = 0, num_queries =
  41     0;
  42 static guint num_elements = 0, num_bins = 0, num_pads = 0, num_ghostpads = 0;
  43 static GstClockTime last_ts = G_GUINT64_CONSTANT (0);
  44 static guint total_cpuload = 0;
  45 static gboolean have_cpuload = FALSE;
  46
  47 typedef struct
  48 {
  49   /* human readable pad name and details */
  50   gchar *name, *type_name;
  51   guint index;
  52   gboolean is_ghost_pad;
  53   GstPadDirection dir;
  54   /* buffer statistics */
  55   guint num_buffers;
  56   guint num_live, num_decode_only, num_discont, num_resync, num_corrupted,
  57       num_marker, num_header, num_gap, num_droppable, num_delta;
  58   guint min_size, max_size, avg_size;
  59   /* first and last activity on the pad, expected next_ts */
  60   GstClockTime first_ts, last_ts, next_ts;
  61   /* in which thread does it operate */
  62   gpointer thread_id;
  63   /* hierarchy */
  64   guint parent_ix;
  65 } GstPadStats;
  66
  67 typedef struct
  68 {
  69   /* human readable element name */
  70   gchar *name, *type_name;
  71   guint index;
  72   gboolean is_bin;
  73   /* buffer statistics */
  74   guint recv_buffers, sent_buffers;
  75   guint64 recv_bytes, sent_bytes;
  76   /* event, message statistics */
  77   guint num_events, num_messages, num_queries;
  78   /* first activity on the element */
  79   GstClockTime first_ts, last_ts;
  80   /* hierarchy */
  81   guint parent_ix;
  82 } GstElementStats;
  83
  84 typedef struct
  85 {
  86   /* time spend in this thread */
  87   GstClockTime tthread;
  88   guint cpuload;
  89 } GstThreadStats;
  90
  91 /* stats helper */
  92
  93 static void
  94 free_element_stats (gpointer data)
  95 {
  96   g_slice_free (GstElementStats, data);
  97 }
  98
  99 static inline GstElementStats *
 100 get_element_stats (guint ix)
 101 {
 102   return (ix != G_MAXUINT && ix < elements->len) ?
 103       g_ptr_array_index (elements, ix) : NULL;
 104 }
 105
 106 static inline GstPadStats *
 107 get_pad_stats (guint ix)
 108 {
 109   return (ix != G_MAXUINT && ix < pads->len) ?
 110       g_ptr_array_index (pads, ix) : NULL;
 111 }
 112
 113 static void
 114 free_pad_stats (gpointer data)
 115 {
 116   g_slice_free (GstPadStats, data);
 117 }
 118
 119 static inline GstThreadStats *
 120 get_thread_stats (gpointer id)
 121 {
 122   GstThreadStats *stats = g_hash_table_lookup (threads, id);
 123
 124   if (G_UNLIKELY (!stats)) {
 125     stats = g_slice_new0 (GstThreadStats);
 126     stats->tthread = GST_CLOCK_TIME_NONE;
 127     g_hash_table_insert (threads, id, stats);
 128   }
 129   return stats;
 130 }
 131
 132 static void
 133 new_pad_stats (GstStructure * s)
 134 {
 135   GstPadStats *stats;
 136   guint ix, parent_ix;
 137   gchar *type, *name;
 138   gboolean is_ghost_pad;
 139   GstPadDirection dir;
 140   guint64 thread_id;
 141
 142   gst_structure_get (s,
 143       "ix", G_TYPE_UINT, &ix,
 144       "parent-ix", G_TYPE_UINT, &parent_ix,
 145       "name", G_TYPE_STRING, &name,
 146       "type", G_TYPE_STRING, &type,
 147       "is-ghostpad", G_TYPE_BOOLEAN, &is_ghost_pad,
 148       "pad-direction", GST_TYPE_PAD_DIRECTION, &dir,
 149       "thread-id", G_TYPE_UINT64, &thread_id, NULL);
 150
 151   stats = g_slice_new0 (GstPadStats);
 152   if (is_ghost_pad)
 153     num_ghostpads++;
 154   num_pads++;
 155   stats->name = name;
 156   stats->type_name = type;
 157   stats->index = ix;
 158   stats->is_ghost_pad = is_ghost_pad;
 159   stats->dir = dir;
 160   stats->min_size = G_MAXUINT;
 161   stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE;
 162   stats->thread_id = (gpointer) (guintptr) thread_id;
 163   stats->parent_ix = parent_ix;
 164
 165   if (pads->len <= ix)
 166     g_ptr_array_set_size (pads, ix + 1);
 167   g_ptr_array_index (pads, ix) = stats;
 168 }
 169
 170 static void
 171 new_element_stats (GstStructure * s)
 172 {
 173   GstElementStats *stats;
 174   guint ix, parent_ix;
 175   gchar *type, *name;
 176   gboolean is_bin;
 177
 178   gst_structure_get (s,
 179       "ix", G_TYPE_UINT, &ix,
 180       "parent-ix", G_TYPE_UINT, &parent_ix,
 181       "name", G_TYPE_STRING, &name,
 182       "type", G_TYPE_STRING, &type, "is-bin", G_TYPE_BOOLEAN, &is_bin, NULL);
 183
 184   stats = g_slice_new0 (GstElementStats);
 185   if (is_bin)
 186     num_bins++;
 187   num_elements++;
 188   stats->index = ix;
 189   stats->name = name;
 190   stats->type_name = type;
 191   stats->is_bin = is_bin;
 192   stats->first_ts = GST_CLOCK_TIME_NONE;
 193   stats->parent_ix = parent_ix;
 194
 195   if (elements->len <= ix)
 196     g_ptr_array_set_size (elements, ix + 1);
 197   g_ptr_array_index (elements, ix) = stats;
 198 }
 199
 200 static void
 201 free_thread_stats (gpointer data)
 202 {
 203   g_slice_free (GstThreadStats, data);
 204 }
 205
 206 static void
 207 do_pad_stats (GstPadStats * stats, guint elem_ix, guint size, guint64 ts,
 208     guint64 buffer_ts, guint64 buffer_dur, GstBufferFlags buffer_flags)
 209 {
 210   gulong avg_size;
 211
 212   /* parentage */
 213   if (stats->parent_ix == G_MAXUINT) {
 214     stats->parent_ix = elem_ix;
 215   }
 216
 217   if (stats->thread_id) {
 218     get_thread_stats (stats->thread_id);
 219   }
 220
 221   /* size stats */
 222   avg_size = (((gulong) stats->avg_size * (gulong) stats->num_buffers) + size);
 223   stats->num_buffers++;
 224   stats->avg_size = (guint) (avg_size / stats->num_buffers);
 225   if (size < stats->min_size)
 226     stats->min_size = size;
 227   else if (size > stats->max_size)
 228     stats->max_size = size;
 229   /* time stats */
 230   if (!GST_CLOCK_TIME_IS_VALID (stats->last_ts))
 231     stats->first_ts = ts;
 232   stats->last_ts = ts;
 233   /* flag stats */
 234   if (buffer_flags & GST_BUFFER_FLAG_LIVE)
 235     stats->num_live++;
 236   if (buffer_flags & GST_BUFFER_FLAG_DECODE_ONLY)
 237     stats->num_decode_only++;
 238   if (buffer_flags & GST_BUFFER_FLAG_DISCONT)
 239     stats->num_discont++;
 240   if (buffer_flags & GST_BUFFER_FLAG_RESYNC)
 241     stats->num_resync++;
 242   if (buffer_flags & GST_BUFFER_FLAG_CORRUPTED)
 243     stats->num_corrupted++;
 244   if (buffer_flags & GST_BUFFER_FLAG_MARKER)
 245     stats->num_marker++;
 246   if (buffer_flags & GST_BUFFER_FLAG_HEADER)
 247     stats->num_header++;
 248   if (buffer_flags & GST_BUFFER_FLAG_GAP)
 249     stats->num_gap++;
 250   if (buffer_flags & GST_BUFFER_FLAG_DROPPABLE)
 251     stats->num_droppable++;
 252   if (buffer_flags & GST_BUFFER_FLAG_DELTA_UNIT)
 253     stats->num_delta++;
 254   /* update timestamps */
 255   if (GST_CLOCK_TIME_IS_VALID (buffer_ts) &&
 256       GST_CLOCK_TIME_IS_VALID (buffer_dur)) {
 257     stats->next_ts = buffer_ts + buffer_dur;
 258   } else {
 259     stats->next_ts = GST_CLOCK_TIME_NONE;
 260   }
 261 }
 262
 263 static void
 264 do_element_stats (GstElementStats * stats, GstElementStats * peer_stats,
 265     guint size, guint64 ts)
 266 {
 267   stats->sent_buffers++;
 268   peer_stats->recv_buffers++;
 269   stats->sent_bytes += size;
 270   peer_stats->recv_bytes += size;
 271   /* time stats */
 272   if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (stats->first_ts))) {
 273     stats->first_ts = ts;
 274   }
 275   if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (peer_stats->first_ts))) {
 276     peer_stats->first_ts = ts + 1;
 277   }
 278 }
 279
 280 static void
 281 do_buffer_stats (GstStructure * s)
 282 {
 283   guint64 ts;
 284   guint64 buffer_pts = GST_CLOCK_TIME_NONE, buffer_dur = GST_CLOCK_TIME_NONE;
 285   guint pad_ix, elem_ix, peer_elem_ix;
 286   guint size;
 287   GstBufferFlags buffer_flags;
 288   GstPadStats *pad_stats;
 289   GstElementStats *elem_stats, *peer_elem_stats;
 290
 291   num_buffers++;
 292   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 293       "pad-ix", G_TYPE_UINT, &pad_ix,
 294       "element-ix", G_TYPE_UINT, &elem_ix,
 295       "peer-element-ix", G_TYPE_UINT, &peer_elem_ix,
 296       "buffer-size", G_TYPE_UINT, &size,
 297       "buffer-flags", GST_TYPE_BUFFER_FLAGS, &buffer_flags, NULL);
 298   gst_structure_get_uint64 (s, "buffer-pts", &buffer_pts);
 299   gst_structure_get_uint64 (s, "buffer-duration", &buffer_dur);
 300   last_ts = MAX (last_ts, ts);
 301   if (!(pad_stats = get_pad_stats (pad_ix))) {
 302     GST_WARNING ("no pad stats found for ix=%u", pad_ix);
 303     return;
 304   }
 305   if (!(elem_stats = get_element_stats (elem_ix))) {
 306     GST_WARNING ("no element stats found for ix=%u", elem_ix);
 307     return;
 308   }
 309   if (!(peer_elem_stats = get_element_stats (peer_elem_ix))) {
 310     GST_WARNING ("no element stats found for ix=%u", peer_elem_ix);
 311     return;
 312   }
 313   do_pad_stats (pad_stats, elem_ix, size, ts, buffer_pts, buffer_dur,
 314       buffer_flags);
 315   if (pad_stats->dir == GST_PAD_SRC) {
 316     /* push */
 317     do_element_stats (elem_stats, peer_elem_stats, size, ts);
 318   } else {
 319     /* pull */
 320     do_element_stats (peer_elem_stats, elem_stats, size, ts);
 321   }
 322 }
 323
 324 static void
 325 do_event_stats (GstStructure * s)
 326 {
 327   guint64 ts;
 328   guint pad_ix, elem_ix;
 329   GstPadStats *pad_stats;
 330   GstElementStats *elem_stats;
 331
 332   num_events++;
 333   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 334       "pad-ix", G_TYPE_UINT, &pad_ix, "element-ix", G_TYPE_UINT, &elem_ix,
 335       NULL);
 336   last_ts = MAX (last_ts, ts);
 337   if (!(pad_stats = get_pad_stats (pad_ix))) {
 338     GST_WARNING ("no pad stats found for ix=%u", pad_ix);
 339     return;
 340   }
 341   if (!(elem_stats = get_element_stats (elem_ix))) {
 342     // e.g. reconfigure events are send over unparented pads
 343     GST_INFO ("no element stats found for ix=%u", elem_ix);
 344     return;
 345   }
 346   elem_stats->num_events++;
 347 }
 348
 349 static void
 350 do_message_stats (GstStructure * s)
 351 {
 352   guint64 ts;
 353   guint elem_ix;
 354   GstElementStats *elem_stats;
 355
 356   num_messages++;
 357   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 358       "element-ix", G_TYPE_UINT, &elem_ix, NULL);
 359   last_ts = MAX (last_ts, ts);
 360   if (!(elem_stats = get_element_stats (elem_ix))) {
 361     GST_WARNING ("no element stats found for ix=%u", elem_ix);
 362     return;
 363   }
 364   elem_stats->num_messages++;
 365 }
 366
 367 static void
 368 do_query_stats (GstStructure * s)
 369 {
 370   guint64 ts;
 371   guint elem_ix;
 372   GstElementStats *elem_stats;
 373
 374   num_queries++;
 375   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 376       "element-ix", G_TYPE_UINT, &elem_ix, NULL);
 377   last_ts = MAX (last_ts, ts);
 378   if (!(elem_stats = get_element_stats (elem_ix))) {
 379     GST_WARNING ("no element stats found for ix=%u", elem_ix);
 380     return;
 381   }
 382   elem_stats->num_queries++;
 383 }
 384
 385 static void
 386 do_thread_rusage_stats (GstStructure * s)
 387 {
 388   guint64 ts, tthread, thread_id;
 389   guint cpuload;
 390   GstThreadStats *thread_stats;
 391
 392   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 393       "thread-id", G_TYPE_UINT64, &thread_id,
 394       "average-cpuload", G_TYPE_UINT, &cpuload, "time", G_TYPE_UINT64, &tthread,
 395       NULL);
 396   thread_stats = get_thread_stats ((gpointer) (guintptr) thread_id);
 397   thread_stats->cpuload = cpuload;
 398   thread_stats->tthread = tthread;
 399   last_ts = MAX (last_ts, ts);
 400 }
 401
 402 static void
 403 do_proc_rusage_stats (GstStructure * s)
 404 {
 405   guint64 ts;
 406
 407   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 408       "average-cpuload", G_TYPE_UINT, &total_cpuload, NULL);
 409   last_ts = MAX (last_ts, ts);
 410   have_cpuload = TRUE;
 411 }
 412
 413 /* reporting */
 414
 415 static gint
 416 find_pad_stats_for_thread (gconstpointer value, gconstpointer user_data)
 417 {
 418   const GstPadStats *stats = (const GstPadStats *) value;
 419
 420   if ((stats->thread_id == user_data) && (stats->num_buffers)) {
 421     return 0;
 422   }
 423   return 1;
 424 }
 425
 426 static void
 427 print_pad_stats (gpointer value, gpointer user_data)
 428 {
 429   GstPadStats *stats = (GstPadStats *) value;
 430
 431   if (stats->thread_id == user_data) {
 432     /* there seem to be some temporary pads */
 433     if (stats->num_buffers) {
 434       GstClockTimeDiff running =
 435           GST_CLOCK_DIFF (stats->first_ts, stats->last_ts);
 436       GstElementStats *elem_stats = get_element_stats (stats->parent_ix);
 437       gchar fullname[30 + 1];
 438
 439       g_snprintf (fullname, 30, "%s.%s", elem_stats->name, stats->name);
 440
 441       printf
 442           ("    %c %-30.30s: buffers %7u (live %5u,dec %5u,dis %5u,res %5u,"
 443           "cor %5u,mar %5u,hdr %5u,gap %5u,drop %5u,dlt %5u),",
 444           (stats->dir == GST_PAD_SRC) ? '>' : '<', fullname, stats->num_buffers,
 445           stats->num_live, stats->num_decode_only, stats->num_discont,
 446           stats->num_resync, stats->num_corrupted, stats->num_marker,
 447           stats->num_header, stats->num_gap, stats->num_droppable,
 448           stats->num_delta);
 449       if (stats->min_size == stats->max_size) {
 450         printf (" size (min/avg/max) ......./%7u/.......,", stats->avg_size);
 451       } else {
 452         printf (" size (min/avg/max) %7u/%7u/%7u,",
 453             stats->min_size, stats->avg_size, stats->max_size);
 454       }
 455       printf (" time %" GST_TIME_FORMAT ","
 456           " bytes/sec %lf\n",
 457           GST_TIME_ARGS (running),
 458           ((gdouble) (stats->num_buffers * stats->avg_size) * GST_SECOND) /
 459           ((gdouble) running));
 460     }
 461   }
 462 }
 463
 464 static void
 465 print_thread_stats (gpointer key, gpointer value, gpointer user_data)
 466 {
 467   GSList *list = user_data;
 468   GSList *node = g_slist_find_custom (list, key, find_pad_stats_for_thread);
 469   GstThreadStats *stats = (GstThreadStats *) value;
 470
 471   /* skip stats if there are no pads for that thread (e.g. a pipeline) */
 472   if (!node)
 473     return;
 474
 475   printf ("Thread %p Statistics:\n", key);
 476   if (GST_CLOCK_TIME_IS_VALID (stats->tthread)) {
 477     printf ("  Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (stats->tthread));
 478     printf ("  Avg CPU load: %4.1f %%\n", (gfloat) stats->cpuload / 10.0);
 479   }
 480
 481   puts ("  Pad Statistics:");
 482   g_slist_foreach (node, print_pad_stats, key);
 483 }
 484
 485 static void
 486 print_element_stats (gpointer value, gpointer user_data)
 487 {
 488   GstElementStats *stats = (GstElementStats *) value;
 489
 490   /* skip temporary elements */
 491   if (stats->first_ts != GST_CLOCK_TIME_NONE) {
 492     gchar fullname[45 + 1];
 493
 494     g_snprintf (fullname, 45, "%s:%s", stats->type_name, stats->name);
 495
 496     printf ("  %-45s:", fullname);
 497     if (stats->recv_buffers)
 498       printf (" buffers in/out %7u", stats->recv_buffers);
 499     else
 500       printf (" buffers in/out %7s", "-");
 501     if (stats->sent_buffers)
 502       printf ("/%7u", stats->sent_buffers);
 503     else
 504       printf ("/%7s", "-");
 505     if (stats->recv_bytes)
 506       printf (" bytes in/out %12" G_GUINT64_FORMAT, stats->recv_bytes);
 507     else
 508       printf (" bytes in/out %12s", "-");
 509     if (stats->sent_bytes)
 510       printf ("/%12" G_GUINT64_FORMAT, stats->sent_bytes);
 511     else
 512       printf ("/%12s", "-");
 513     printf (" first activity %" GST_TIME_FORMAT ", "
 514         " ev/msg/qry sent %5u/%5u/%5u\n", GST_TIME_ARGS (stats->first_ts),
 515         stats->num_events, stats->num_messages, stats->num_queries);
 516   }
 517 }
 518
 519 static void
 520 accum_element_stats (gpointer value, gpointer user_data)
 521 {
 522   GstElementStats *stats = (GstElementStats *) value;
 523
 524   if (stats->parent_ix != G_MAXUINT) {
 525     GstElementStats *parent_stats = get_element_stats (stats->parent_ix);
 526
 527     parent_stats->num_events += stats->num_events;
 528     parent_stats->num_messages += stats->num_messages;
 529     parent_stats->num_queries += stats->num_queries;
 530     if (!GST_CLOCK_TIME_IS_VALID (parent_stats->first_ts)) {
 531       parent_stats->first_ts = stats->first_ts;
 532     } else if (GST_CLOCK_TIME_IS_VALID (stats->first_ts)) {
 533       parent_stats->first_ts = MIN (parent_stats->first_ts, stats->first_ts);
 534     }
 535     if (!GST_CLOCK_TIME_IS_VALID (parent_stats->last_ts)) {
 536       parent_stats->last_ts = stats->last_ts;
 537     } else if (GST_CLOCK_TIME_IS_VALID (stats->last_ts)) {
 538       parent_stats->last_ts = MAX (parent_stats->last_ts, stats->last_ts);
 539     }
 540   }
 541 }
 542
 543 /* sorting */
 544
 545 static gint
 546 sort_pad_stats_by_first_activity (gconstpointer ps1, gconstpointer ps2)
 547 {
 548   GstPadStats *s1 = (GstPadStats *) ps1;
 549   GstPadStats *s2 = (GstPadStats *) ps2;
 550
 551   gint order = GST_CLOCK_DIFF (s2->first_ts, s1->first_ts);
 552
 553   if (!order) {
 554     order = s1->dir - s2->dir;
 555   }
 556   return (order);
 557 }
 558
 559 static void
 560 sort_pad_stats (gpointer value, gpointer user_data)
 561 {
 562   GSList **list = user_data;
 563
 564   *list =
 565       g_slist_insert_sorted (*list, value, sort_pad_stats_by_first_activity);
 566 }
 567
 568 static gint
 569 sort_element_stats_by_first_activity (gconstpointer es1, gconstpointer es2)
 570 {
 571   return (GST_CLOCK_DIFF (((GstElementStats *) es2)->first_ts,
 572           ((GstElementStats *) es1)->first_ts));
 573 }
 574
 575 static void
 576 sort_bin_stats (gpointer value, gpointer user_data)
 577 {
 578   if (((GstElementStats *) value)->is_bin) {
 579     GSList **list = user_data;
 580
 581     *list =
 582         g_slist_insert_sorted (*list, value,
 583         sort_element_stats_by_first_activity);
 584   }
 585 }
 586
 587 static void
 588 sort_element_stats (gpointer value, gpointer user_data)
 589 {
 590   if (!(((GstElementStats *) value)->is_bin)) {
 591     GSList **list = user_data;
 592
 593     *list =
 594         g_slist_insert_sorted (*list, value,
 595         sort_element_stats_by_first_activity);
 596   }
 597 }
 598
 599 static gboolean
 600 check_bin_parent (gpointer key, gpointer value, gpointer user_data)
 601 {
 602   GstElementStats *stats = (GstElementStats *) value;
 603
 604   return (stats->parent_ix == GPOINTER_TO_UINT (user_data));
 605 }
 606
 607 static gboolean
 608 process_leaf_bins (gpointer key, gpointer value, gpointer user_data)
 609 {
 610   GHashTable *accum_bins = user_data;
 611
 612   /* if we find no bin that has this bin as a parent ... */
 613   if (!g_hash_table_find (accum_bins, check_bin_parent, key)) {
 614     /* accumulate stats to the parent and remove */
 615     accum_element_stats (value, NULL);
 616     return TRUE;
 617   }
 618   return FALSE;
 619 }
 620
 621 /* main */
 622
 623 static gboolean
 624 init (void)
 625 {
 626   /* compile the parser regexps */
 627   /* 0:00:00.004925027 31586      0x1c5c600 DEBUG           GST_REGISTRY gstregistry.c:463:gst_registry_add_plugin:<registry0> adding plugin 0x1c79160 for filename "/usr/lib/gstreamer-1.0/libgstxxx.so" */
 628   raw_log = g_regex_new (
 629       /* 1: ts */
 630       "^([0-9:.]+) +"
 631       /* 2: pid */
 632       "([0-9]+) +"
 633       /* 3: thread */
 634       "(0x[0-9a-fA-F]+) +"
 635       /* 4: level */
 636       "([A-Z]+) +"
 637       /* 5: category */
 638       "([a-zA-Z_-]+) +"
 639       /* 6: file:line:func: */
 640       "([^:]*:[0-9]+:[^:]*:) +"
 641       /* 7: (obj)? log-text */
 642       "(.*)$", 0, 0, NULL);
 643   if (!raw_log) {
 644     GST_WARNING ("failed to compile the 'raw' parser");
 645     return FALSE;
 646   }
 647
 648   ansi_log = g_regex_new (
 649       /* 1: ts */
 650       "^([0-9:.]+) +"
 651       /* 2: pid */
 652       "\\\x1b\\[[0-9;]+m *([0-9]+)\\\x1b\\[00m +"
 653       /* 3: thread */
 654       "(0x[0-9a-fA-F]+) +"
 655       /* 4: level */
 656       "(?:\\\x1b\\[[0-9;]+m)?([A-Z]+) +\\\x1b\\[00m +"
 657       /* 5: category */
 658       "\\\x1b\\[[0-9;]+m +([a-zA-Z_-]+) +"
 659       /* 6: file:line:func: */
 660       "([^:]*:[0-9]+:[^:]*:)(?:\\\x1b\\[00m)? +"
 661       /* 7: (obj)? log-text */
 662       "(.*)$", 0, 0, NULL);
 663   if (!raw_log) {
 664     GST_WARNING ("failed to compile the 'ansi' parser");
 665     return FALSE;
 666   }
 667
 668   elements = g_ptr_array_new_with_free_func (free_element_stats);
 669   pads = g_ptr_array_new_with_free_func (free_pad_stats);
 670   threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
 671
 672   return TRUE;
 673 }
 674
 675 static void
 676 done (void)
 677 {
 678   if (pads)
 679     g_ptr_array_free (pads, TRUE);
 680   if (elements)
 681     g_ptr_array_free (elements, TRUE);
 682   if (threads)
 683     g_hash_table_destroy (threads);
 684
 685   if (raw_log)
 686     g_regex_unref (raw_log);
 687   if (ansi_log)
 688     g_regex_unref (ansi_log);
 689 }
 690
 691 static void
 692 print_stats (void)
 693 {
 694   guint num_threads = g_hash_table_size (threads);
 695
 696   /* print overall stats */
 697   puts ("\nOverall Statistics:");
 698   printf ("Number of Threads: %u\n", num_threads);
 699   printf ("Number of Elements: %u\n", num_elements - num_bins);
 700   printf ("Number of Bins: %u\n", num_bins);
 701   printf ("Number of Pads: %u\n", num_pads - num_ghostpads);
 702   printf ("Number of GhostPads: %u\n", num_ghostpads);
 703   printf ("Number of Buffers passed: %" G_GUINT64_FORMAT "\n", num_buffers);
 704   printf ("Number of Events sent: %" G_GUINT64_FORMAT "\n", num_events);
 705   printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n", num_messages);
 706   printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", num_queries);
 707   printf ("Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (last_ts));
 708   if (have_cpuload) {
 709     printf ("Avg CPU load: %4.1f %%\n", (gfloat) total_cpuload / 10.0);
 710   }
 711   puts ("");
 712
 713   /* thread stats */
 714   if (num_threads) {
 715     GSList *list = NULL;
 716
 717     g_ptr_array_foreach (pads, sort_pad_stats, &list);
 718     g_hash_table_foreach (threads, print_thread_stats, list);
 719     puts ("");
 720     g_slist_free (list);
 721   }
 722
 723   /* element stats */
 724   if (num_elements) {
 725     GSList *list = NULL;
 726
 727     puts ("Element Statistics:");
 728     /* sort by first_activity */
 729     g_ptr_array_foreach (elements, sort_element_stats, &list);
 730     /* attribute element stats to bins */
 731     g_slist_foreach (list, accum_element_stats, NULL);
 732     g_slist_foreach (list, print_element_stats, NULL);
 733     puts ("");
 734     g_slist_free (list);
 735   }
 736
 737   /* bin stats */
 738   if (num_bins) {
 739     GSList *list = NULL;
 740     guint i;
 741     GHashTable *accum_bins = g_hash_table_new_full (NULL, NULL, NULL, NULL);
 742
 743     puts ("Bin Statistics:");
 744     /* attribute bin stats to parent-bins */
 745     for (i = 0; i < num_elements; i++) {
 746       GstElementStats *stats = g_ptr_array_index (elements, i);
 747       if (stats->is_bin) {
 748         g_hash_table_insert (accum_bins, GUINT_TO_POINTER (i), stats);
 749       }
 750     }
 751     while (g_hash_table_size (accum_bins)) {
 752       g_hash_table_foreach_remove (accum_bins, process_leaf_bins, accum_bins);
 753     }
 754     g_hash_table_destroy (accum_bins);
 755     /* sort by first_activity */
 756     g_ptr_array_foreach (elements, sort_bin_stats, &list);
 757     g_slist_foreach (list, print_element_stats, NULL);
 758     puts ("");
 759     g_slist_free (list);
 760   }
 761 }
 762
 763 static void
 764 collect_stats (const gchar * filename)
 765 {
 766   FILE *log;
 767
 768   if ((log = fopen (filename, "rt"))) {
 769     gchar line[5001];
 770
 771     /* probe format */
 772     if (fgets (line, 5000, log)) {
 773       GMatchInfo *match_info;
 774       GRegex *parser;
 775       GstStructure *s;
 776       guint lnr = 0;
 777       gchar *level, *data;
 778
 779       if (strchr (line, 27)) {
 780         parser = ansi_log;
 781         GST_INFO ("format is 'ansi'");
 782       } else {
 783         parser = raw_log;
 784         GST_INFO ("format is 'raw'");
 785       }
 786       rewind (log);
 787
 788       /* parse the log */
 789       while (!feof (log)) {
 790         if (fgets (line, 5000, log)) {
 791           if (g_regex_match (parser, line, 0, &match_info)) {
 792             /* filter by level */
 793             level = g_match_info_fetch (match_info, 4);
 794             if (!strcmp (level, "TRACE")) {
 795               data = g_match_info_fetch (match_info, 7);
 796               if ((s = gst_structure_from_string (data, NULL))) {
 797                 const gchar *name = gst_structure_get_name (s);
 798
 799                 if (!strcmp (name, "new-pad")) {
 800                   new_pad_stats (s);
 801                 } else if (!strcmp (name, "new-element")) {
 802                   new_element_stats (s);
 803                 } else if (!strcmp (name, "buffer")) {
 804                   do_buffer_stats (s);
 805                 } else if (!strcmp (name, "event")) {
 806                   do_event_stats (s);
 807                 } else if (!strcmp (name, "message")) {
 808                   do_message_stats (s);
 809                 } else if (!strcmp (name, "query")) {
 810                   do_query_stats (s);
 811                 } else if (!strcmp (name, "thread-rusage")) {
 812                   do_thread_rusage_stats (s);
 813                 } else if (!strcmp (name, "proc-rusage")) {
 814                   do_proc_rusage_stats (s);
 815                 } else {
 816                   // TODO(ensonic): parse the xxx.class log lines
 817                   if (!g_str_has_suffix (data, ".class")) {
 818                     GST_WARNING ("unknown log entry: '%s'", data);
 819                   }
 820                 }
 821                 gst_structure_free (s);
 822               } else {
 823                 GST_WARNING ("unknown log entry: '%s'", data);
 824               }
 825             }
 826           } else {
 827             if (*line) {
 828               GST_WARNING ("foreign log entry: %s:%d:'%s'", filename, lnr,
 829                   g_strchomp (line));
 830             }
 831           }
 832           g_match_info_free (match_info);
 833           match_info = NULL;
 834           lnr++;
 835         } else {
 836           if (!feof (log)) {
 837             // TODO(ensonic): run wc -L on the log file
 838             fprintf (stderr, "line too long");
 839           }
 840         }
 841       }
 842     } else {
 843       GST_WARNING ("empty log");
 844     }
 845     fclose (log);
 846   }
 847 }
 848
 849 gint
 850 main (gint argc, gchar * argv[])
 851 {
 852   gchar **filenames = NULL;
 853   guint num;
 854   GError *err = NULL;
 855   GOptionContext *ctx;
 856   GOptionEntry options[] = {
 857     GST_TOOLS_GOPTION_VERSION,
 858     // TODO(ensonic): add a summary flag, if set read the whole thing, print
 859     // stats once, and exit
 860     {G_OPTION_REMAINING, 0, 0, G_OPTION_ARG_FILENAME_ARRAY, &filenames, NULL}
 861     ,
 862     {NULL}
 863   };
 864
 865 #ifdef ENABLE_NLS
 866   bindtextdomain (GETTEXT_PACKAGE, LOCALEDIR);
 867   bind_textdomain_codeset (GETTEXT_PACKAGE, "UTF-8");
 868   textdomain (GETTEXT_PACKAGE);
 869 #endif
 870
 871   g_set_prgname ("gst-stats-" GST_API_VERSION);
 872
 873   ctx = g_option_context_new ("FILE");
 874   g_option_context_add_main_entries (ctx, options, GETTEXT_PACKAGE);
 875   g_option_context_add_group (ctx, gst_init_get_option_group ());
 876   if (!g_option_context_parse (ctx, &argc, &argv, &err)) {
 877     g_print ("Error initializing: %s\n", GST_STR_NULL (err->message));
 878     exit (1);
 879   }
 880   g_option_context_free (ctx);
 881
 882   gst_tools_print_version ();
 883
 884   if (filenames == NULL || *filenames == NULL) {
 885     g_print ("Please give one filename to %s\n\n", g_get_prgname ());
 886     return 1;
 887   }
 888   num = g_strv_length (filenames);
 889   if (num == 0 || num > 1) {
 890     g_print ("Please give exactly one filename to %s (%d given).\n\n",
 891         g_get_prgname (), num);
 892     return 1;
 893   }
 894
 895   if (init ()) {
 896     collect_stats (filenames[0]);
 897     print_stats ();
 898   }
 899   done ();
 900
 901   g_strfreev (filenames);
 902   return 0;
 903 }