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 GHashTable *latencies = NULL;
  41 static GHashTable *element_latencies = NULL;
  42 static GQueue *element_reported_latencies = NULL;
  43 static guint64 num_buffers = 0, num_events = 0, num_messages = 0, num_queries =
  44     0;
  45 static guint num_elements = 0, num_bins = 0, num_pads = 0, num_ghostpads = 0;
  46 static GstClockTime last_ts = G_GUINT64_CONSTANT (0);
  47 static guint total_cpuload = 0;
  48 static gboolean have_cpuload = FALSE;
  49
  50 static gboolean have_latency = FALSE;
  51 static gboolean have_element_latency = FALSE;
  52 static gboolean have_element_reported_latency = FALSE;
  53
  54 typedef struct
  55 {
  56   /* the number of latencies counted  */
  57   guint64 count;
  58   /* the total of all latencies */
  59   guint64 total;
  60   /* the min of all latencies */
  61   guint64 min;
  62   /* the max of all latencies */
  63   guint64 max;
  64 } GstLatencyStats;
  65
  66 typedef struct
  67 {
  68   /* The element name */
  69   gchar *element;
  70   /* The timestamp of the reported latency */
  71   guint64 ts;
  72   /* the min reported latency */
  73   guint64 min;
  74   /* the max reported latency */
  75   guint64 max;
  76 } GstReportedLatency;
  77
  78 typedef struct
  79 {
  80   /* human readable pad name and details */
  81   gchar *name, *type_name;
  82   guint index;
  83   gboolean is_ghost_pad;
  84   GstPadDirection dir;
  85   /* buffer statistics */
  86   guint num_buffers;
  87   guint num_live, num_decode_only, num_discont, num_resync, num_corrupted,
  88       num_marker, num_header, num_gap, num_droppable, num_delta;
  89   guint min_size, max_size, avg_size;
  90   /* first and last activity on the pad, expected next_ts */
  91   GstClockTime first_ts, last_ts, next_ts;
  92   /* in which thread does it operate */
  93   gpointer thread_id;
  94   /* hierarchy */
  95   guint parent_ix;
  96 } GstPadStats;
  97
  98 typedef struct
  99 {
 100   /* human readable element name */
 101   gchar *name, *type_name;
 102   guint index;
 103   gboolean is_bin;
 104   /* buffer statistics */
 105   guint recv_buffers, sent_buffers;
 106   guint64 recv_bytes, sent_bytes;
 107   /* event, message statistics */
 108   guint num_events, num_messages, num_queries;
 109   /* first activity on the element */
 110   GstClockTime first_ts, last_ts;
 111   /* hierarchy */
 112   guint parent_ix;
 113 } GstElementStats;
 114
 115 typedef struct
 116 {
 117   /* time spend in this thread */
 118   GstClockTime tthread;
 119   guint cpuload;
 120 } GstThreadStats;
 121
 122 /* stats helper */
 123
 124 static void
 125 latencies_foreach_print_stats (gchar * key, GstLatencyStats * ls, gpointer data)
 126 {
 127   printf ("\t%s: mean=%" G_GUINT64_FORMAT " min=%" G_GUINT64_FORMAT " max=%"
 128       G_GUINT64_FORMAT "\n", key, ls->total / ls->count, ls->min, ls->max);
 129 }
 130
 131 static void
 132 reported_latencies_foreach_print_stats (GstReportedLatency * rl, gpointer data)
 133 {
 134   printf ("\t%s: min=%" G_GUINT64_FORMAT " max=%" G_GUINT64_FORMAT " ts=%"
 135       GST_TIME_FORMAT "\n", rl->element, rl->min,
 136       rl->max, GST_TIME_ARGS (rl->ts));
 137 }
 138
 139 static void
 140 free_latency_stats (gpointer data)
 141 {
 142   g_slice_free (GstLatencyStats, data);
 143 }
 144
 145 static void
 146 free_reported_latency (gpointer data)
 147 {
 148   GstReportedLatency *rl = data;
 149
 150   if (rl->element)
 151     g_free (rl->element);
 152
 153   g_free (data);
 154 }
 155
 156 static void
 157 free_element_stats (gpointer data)
 158 {
 159   g_slice_free (GstElementStats, data);
 160 }
 161
 162 static inline GstElementStats *
 163 get_element_stats (guint ix)
 164 {
 165   return (ix != G_MAXUINT && ix < elements->len) ?
 166       g_ptr_array_index (elements, ix) : NULL;
 167 }
 168
 169 static inline GstPadStats *
 170 get_pad_stats (guint ix)
 171 {
 172   return (ix != G_MAXUINT && ix < pads->len) ?
 173       g_ptr_array_index (pads, ix) : NULL;
 174 }
 175
 176 static void
 177 free_pad_stats (gpointer data)
 178 {
 179   g_slice_free (GstPadStats, data);
 180 }
 181
 182 static inline GstThreadStats *
 183 get_thread_stats (gpointer id)
 184 {
 185   GstThreadStats *stats = g_hash_table_lookup (threads, id);
 186
 187   if (G_UNLIKELY (!stats)) {
 188     stats = g_slice_new0 (GstThreadStats);
 189     stats->tthread = GST_CLOCK_TIME_NONE;
 190     g_hash_table_insert (threads, id, stats);
 191   }
 192   return stats;
 193 }
 194
 195 static void
 196 new_pad_stats (GstStructure * s)
 197 {
 198   GstPadStats *stats;
 199   guint ix, parent_ix;
 200   gchar *type, *name;
 201   gboolean is_ghost_pad;
 202   GstPadDirection dir;
 203   guint64 thread_id;
 204
 205   gst_structure_get (s,
 206       "ix", G_TYPE_UINT, &ix,
 207       "parent-ix", G_TYPE_UINT, &parent_ix,
 208       "name", G_TYPE_STRING, &name,
 209       "type", G_TYPE_STRING, &type,
 210       "is-ghostpad", G_TYPE_BOOLEAN, &is_ghost_pad,
 211       "pad-direction", GST_TYPE_PAD_DIRECTION, &dir,
 212       "thread-id", G_TYPE_UINT64, &thread_id, NULL);
 213
 214   stats = g_slice_new0 (GstPadStats);
 215   if (is_ghost_pad)
 216     num_ghostpads++;
 217   num_pads++;
 218   stats->name = name;
 219   stats->type_name = type;
 220   stats->index = ix;
 221   stats->is_ghost_pad = is_ghost_pad;
 222   stats->dir = dir;
 223   stats->min_size = G_MAXUINT;
 224   stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE;
 225   stats->thread_id = (gpointer) (guintptr) thread_id;
 226   stats->parent_ix = parent_ix;
 227
 228   if (pads->len <= ix)
 229     g_ptr_array_set_size (pads, ix + 1);
 230   g_ptr_array_index (pads, ix) = stats;
 231 }
 232
 233 static void
 234 new_element_stats (GstStructure * s)
 235 {
 236   GstElementStats *stats;
 237   guint ix, parent_ix;
 238   gchar *type, *name;
 239   gboolean is_bin;
 240
 241   gst_structure_get (s,
 242       "ix", G_TYPE_UINT, &ix,
 243       "parent-ix", G_TYPE_UINT, &parent_ix,
 244       "name", G_TYPE_STRING, &name,
 245       "type", G_TYPE_STRING, &type, "is-bin", G_TYPE_BOOLEAN, &is_bin, NULL);
 246
 247   stats = g_slice_new0 (GstElementStats);
 248   if (is_bin)
 249     num_bins++;
 250   num_elements++;
 251   stats->index = ix;
 252   stats->name = name;
 253   stats->type_name = type;
 254   stats->is_bin = is_bin;
 255   stats->first_ts = GST_CLOCK_TIME_NONE;
 256   stats->parent_ix = parent_ix;
 257
 258   if (elements->len <= ix)
 259     g_ptr_array_set_size (elements, ix + 1);
 260   g_ptr_array_index (elements, ix) = stats;
 261 }
 262
 263 static void
 264 free_thread_stats (gpointer data)
 265 {
 266   g_slice_free (GstThreadStats, data);
 267 }
 268
 269 static void
 270 do_pad_stats (GstPadStats * stats, guint elem_ix, guint size, guint64 ts,
 271     guint64 buffer_ts, guint64 buffer_dur, GstBufferFlags buffer_flags)
 272 {
 273   gulong avg_size;
 274
 275   /* parentage */
 276   if (stats->parent_ix == G_MAXUINT) {
 277     stats->parent_ix = elem_ix;
 278   }
 279
 280   if (stats->thread_id) {
 281     get_thread_stats (stats->thread_id);
 282   }
 283
 284   /* size stats */
 285   avg_size = (((gulong) stats->avg_size * (gulong) stats->num_buffers) + size);
 286   stats->num_buffers++;
 287   stats->avg_size = (guint) (avg_size / stats->num_buffers);
 288   if (size < stats->min_size)
 289     stats->min_size = size;
 290   else if (size > stats->max_size)
 291     stats->max_size = size;
 292   /* time stats */
 293   if (!GST_CLOCK_TIME_IS_VALID (stats->last_ts))
 294     stats->first_ts = ts;
 295   stats->last_ts = ts;
 296   /* flag stats */
 297   if (buffer_flags & GST_BUFFER_FLAG_LIVE)
 298     stats->num_live++;
 299   if (buffer_flags & GST_BUFFER_FLAG_DECODE_ONLY)
 300     stats->num_decode_only++;
 301   if (buffer_flags & GST_BUFFER_FLAG_DISCONT)
 302     stats->num_discont++;
 303   if (buffer_flags & GST_BUFFER_FLAG_RESYNC)
 304     stats->num_resync++;
 305   if (buffer_flags & GST_BUFFER_FLAG_CORRUPTED)
 306     stats->num_corrupted++;
 307   if (buffer_flags & GST_BUFFER_FLAG_MARKER)
 308     stats->num_marker++;
 309   if (buffer_flags & GST_BUFFER_FLAG_HEADER)
 310     stats->num_header++;
 311   if (buffer_flags & GST_BUFFER_FLAG_GAP)
 312     stats->num_gap++;
 313   if (buffer_flags & GST_BUFFER_FLAG_DROPPABLE)
 314     stats->num_droppable++;
 315   if (buffer_flags & GST_BUFFER_FLAG_DELTA_UNIT)
 316     stats->num_delta++;
 317   /* update timestamps */
 318   if (GST_CLOCK_TIME_IS_VALID (buffer_ts) &&
 319       GST_CLOCK_TIME_IS_VALID (buffer_dur)) {
 320     stats->next_ts = buffer_ts + buffer_dur;
 321   } else {
 322     stats->next_ts = GST_CLOCK_TIME_NONE;
 323   }
 324 }
 325
 326 static void
 327 do_element_stats (GstElementStats * stats, GstElementStats * peer_stats,
 328     guint size, guint64 ts)
 329 {
 330   stats->sent_buffers++;
 331   peer_stats->recv_buffers++;
 332   stats->sent_bytes += size;
 333   peer_stats->recv_bytes += size;
 334   /* time stats */
 335   if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (stats->first_ts))) {
 336     stats->first_ts = ts;
 337   }
 338   if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (peer_stats->first_ts))) {
 339     peer_stats->first_ts = ts + 1;
 340   }
 341 }
 342
 343 static void
 344 do_buffer_stats (GstStructure * s)
 345 {
 346   guint64 ts;
 347   guint64 buffer_pts = GST_CLOCK_TIME_NONE, buffer_dur = GST_CLOCK_TIME_NONE;
 348   guint pad_ix, elem_ix, peer_elem_ix;
 349   guint size;
 350   GstBufferFlags buffer_flags;
 351   GstPadStats *pad_stats;
 352   GstElementStats *elem_stats, *peer_elem_stats;
 353
 354   num_buffers++;
 355   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 356       "pad-ix", G_TYPE_UINT, &pad_ix,
 357       "element-ix", G_TYPE_UINT, &elem_ix,
 358       "peer-element-ix", G_TYPE_UINT, &peer_elem_ix,
 359       "buffer-size", G_TYPE_UINT, &size,
 360       "buffer-flags", GST_TYPE_BUFFER_FLAGS, &buffer_flags, NULL);
 361   gst_structure_get_uint64 (s, "buffer-pts", &buffer_pts);
 362   gst_structure_get_uint64 (s, "buffer-duration", &buffer_dur);
 363   last_ts = MAX (last_ts, ts);
 364   if (!(pad_stats = get_pad_stats (pad_ix))) {
 365     GST_WARNING ("no pad stats found for ix=%u", pad_ix);
 366     return;
 367   }
 368   if (!(elem_stats = get_element_stats (elem_ix))) {
 369     GST_WARNING ("no element stats found for ix=%u", elem_ix);
 370     return;
 371   }
 372   if (!(peer_elem_stats = get_element_stats (peer_elem_ix))) {
 373     GST_WARNING ("no element stats found for ix=%u", peer_elem_ix);
 374     return;
 375   }
 376   do_pad_stats (pad_stats, elem_ix, size, ts, buffer_pts, buffer_dur,
 377       buffer_flags);
 378   if (pad_stats->dir == GST_PAD_SRC) {
 379     /* push */
 380     do_element_stats (elem_stats, peer_elem_stats, size, ts);
 381   } else {
 382     /* pull */
 383     do_element_stats (peer_elem_stats, elem_stats, size, ts);
 384   }
 385 }
 386
 387 static void
 388 do_event_stats (GstStructure * s)
 389 {
 390   guint64 ts;
 391   guint pad_ix, elem_ix;
 392   GstPadStats *pad_stats;
 393   GstElementStats *elem_stats;
 394
 395   num_events++;
 396   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 397       "pad-ix", G_TYPE_UINT, &pad_ix, "element-ix", G_TYPE_UINT, &elem_ix,
 398       NULL);
 399   last_ts = MAX (last_ts, ts);
 400   if (!(pad_stats = get_pad_stats (pad_ix))) {
 401     GST_WARNING ("no pad stats found for ix=%u", pad_ix);
 402     return;
 403   }
 404   if (!(elem_stats = get_element_stats (elem_ix))) {
 405     // e.g. reconfigure events are send over unparented pads
 406     GST_INFO ("no element stats found for ix=%u", elem_ix);
 407     return;
 408   }
 409   elem_stats->num_events++;
 410 }
 411
 412 static void
 413 do_message_stats (GstStructure * s)
 414 {
 415   guint64 ts;
 416   guint elem_ix;
 417   GstElementStats *elem_stats;
 418
 419   num_messages++;
 420   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 421       "element-ix", G_TYPE_UINT, &elem_ix, NULL);
 422   last_ts = MAX (last_ts, ts);
 423   if (!(elem_stats = get_element_stats (elem_ix))) {
 424     GST_WARNING ("no element stats found for ix=%u", elem_ix);
 425     return;
 426   }
 427   elem_stats->num_messages++;
 428 }
 429
 430 static void
 431 do_query_stats (GstStructure * s)
 432 {
 433   guint64 ts;
 434   guint elem_ix;
 435   GstElementStats *elem_stats;
 436
 437   num_queries++;
 438   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 439       "element-ix", G_TYPE_UINT, &elem_ix, NULL);
 440   last_ts = MAX (last_ts, ts);
 441   if (!(elem_stats = get_element_stats (elem_ix))) {
 442     GST_WARNING ("no element stats found for ix=%u", elem_ix);
 443     return;
 444   }
 445   elem_stats->num_queries++;
 446 }
 447
 448 static void
 449 do_thread_rusage_stats (GstStructure * s)
 450 {
 451   guint64 ts, tthread, thread_id;
 452   guint cpuload;
 453   GstThreadStats *thread_stats;
 454
 455   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 456       "thread-id", G_TYPE_UINT64, &thread_id,
 457       "average-cpuload", G_TYPE_UINT, &cpuload, "time", G_TYPE_UINT64, &tthread,
 458       NULL);
 459   thread_stats = get_thread_stats ((gpointer) (guintptr) thread_id);
 460   thread_stats->cpuload = cpuload;
 461   thread_stats->tthread = tthread;
 462   last_ts = MAX (last_ts, ts);
 463 }
 464
 465 static void
 466 do_proc_rusage_stats (GstStructure * s)
 467 {
 468   guint64 ts;
 469
 470   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
 471       "average-cpuload", G_TYPE_UINT, &total_cpuload, NULL);
 472   last_ts = MAX (last_ts, ts);
 473   have_cpuload = TRUE;
 474 }
 475
 476 static void
 477 update_latency_table (GHashTable * table, const gchar * key, guint64 time)
 478 {
 479   /* Find the values in the hash table */
 480   GstLatencyStats *ls = g_hash_table_lookup (table, key);
 481   if (!ls) {
 482     /* Insert the new key if the value does not exist */
 483     ls = g_new0 (GstLatencyStats, 1);
 484     ls->count = 1;
 485     ls->total = time;
 486     ls->min = time;
 487     ls->max = time;
 488     g_hash_table_insert (table, g_strdup (key), ls);
 489   } else {
 490     /* Otherwise update the existing value */
 491     ls->count++;
 492     ls->total += time;
 493     if (ls->min > time)
 494       ls->min = time;
 495     if (ls->max < time)
 496       ls->max = time;
 497   }
 498 }
 499
 500 static void
 501 do_latency_stats (GstStructure * s)
 502 {
 503   gchar *key = NULL;
 504   const gchar *src = NULL, *sink = NULL, *src_element = NULL,
 505       *sink_element = NULL, *src_element_id = NULL, *sink_element_id = NULL;
 506   guint64 ts = 0, time = 0;
 507
 508   /* Get the values from the structure */
 509   src = gst_structure_get_string (s, "src");
 510   sink = gst_structure_get_string (s, "sink");
 511   src_element = gst_structure_get_string (s, "src-element");
 512   sink_element = gst_structure_get_string (s, "sink-element");
 513   src_element_id = gst_structure_get_string (s, "src-element-id");
 514   sink_element_id = gst_structure_get_string (s, "sink-element-id");
 515   gst_structure_get (s, "time", G_TYPE_UINT64, &time, NULL);
 516   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
 517
 518   /* Update last_ts */
 519   last_ts = MAX (last_ts, ts);
 520
 521   /* Get the key */
 522   key = g_strdup_printf ("%s.%s.%s|%s.%s.%s", src_element_id, src_element,
 523       src, sink_element_id, sink_element, sink);
 524
 525   /* Update the latency in the table */
 526   update_latency_table (latencies, key, time);
 527
 528   /* Clean up */
 529   g_free (key);
 530
 531   have_latency = TRUE;
 532 }
 533
 534 static void
 535 do_element_latency_stats (GstStructure * s)
 536 {
 537   gchar *key = NULL;
 538   const gchar *src = NULL, *element = NULL, *element_id = NULL;
 539   guint64 ts = 0, time = 0;
 540
 541   /* Get the values from the structure */
 542   src = gst_structure_get_string (s, "src");
 543   element = gst_structure_get_string (s, "element");
 544   element_id = gst_structure_get_string (s, "element-id");
 545   gst_structure_get (s, "time", G_TYPE_UINT64, &time, NULL);
 546   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
 547
 548   /* Update last_ts */
 549   last_ts = MAX (last_ts, ts);
 550
 551   /* Get the key */
 552   key = g_strdup_printf ("%s.%s.%s", element_id, element, src);
 553
 554   /* Update the latency in the table */
 555   update_latency_table (element_latencies, key, time);
 556
 557   /* Clean up */
 558   g_free (key);
 559
 560   have_element_latency = TRUE;
 561 }
 562
 563 static void
 564 do_element_reported_latency (GstStructure * s)
 565 {
 566   const gchar *element = NULL, *element_id = NULL;
 567   guint64 ts = 0, min = 0, max = 0;
 568   GstReportedLatency *rl = NULL;
 569
 570   /* Get the values from the structure */
 571   element_id = gst_structure_get_string (s, "element-id");
 572   element = gst_structure_get_string (s, "element");
 573   gst_structure_get (s, "min", G_TYPE_UINT64, &min, NULL);
 574   gst_structure_get (s, "max", G_TYPE_UINT64, &max, NULL);
 575   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
 576
 577   /* Update last_ts */
 578   last_ts = MAX (last_ts, ts);
 579
 580   /* Insert/Update the key in the table */
 581   rl = g_new0 (GstReportedLatency, 1);
 582   rl->element = g_strdup_printf ("%s.%s", element_id, element);
 583   rl->ts = ts;
 584   rl->min = min;
 585   rl->max = max;
 586   g_queue_push_tail (element_reported_latencies, rl);
 587
 588   have_element_reported_latency = TRUE;
 589 }
 590
 591 /* reporting */
 592
 593 static gint
 594 find_pad_stats_for_thread (gconstpointer value, gconstpointer user_data)
 595 {
 596   const GstPadStats *stats = (const GstPadStats *) value;
 597
 598   if ((stats->thread_id == user_data) && (stats->num_buffers)) {
 599     return 0;
 600   }
 601   return 1;
 602 }
 603
 604 static void
 605 print_pad_stats (gpointer value, gpointer user_data)
 606 {
 607   GstPadStats *stats = (GstPadStats *) value;
 608
 609   if (stats->thread_id == user_data) {
 610     /* there seem to be some temporary pads */
 611     if (stats->num_buffers) {
 612       GstClockTimeDiff running =
 613           GST_CLOCK_DIFF (stats->first_ts, stats->last_ts);
 614       GstElementStats *elem_stats = get_element_stats (stats->parent_ix);
 615       gchar fullname[30 + 1];
 616
 617       g_snprintf (fullname, 30, "%s.%s", elem_stats->name, stats->name);
 618
 619       printf
 620           ("    %c %-30.30s: buffers %7u (live %5u,dec %5u,dis %5u,res %5u,"
 621           "cor %5u,mar %5u,hdr %5u,gap %5u,drop %5u,dlt %5u),",
 622           (stats->dir == GST_PAD_SRC) ? '>' : '<', fullname, stats->num_buffers,
 623           stats->num_live, stats->num_decode_only, stats->num_discont,
 624           stats->num_resync, stats->num_corrupted, stats->num_marker,
 625           stats->num_header, stats->num_gap, stats->num_droppable,
 626           stats->num_delta);
 627       if (stats->min_size == stats->max_size) {
 628         printf (" size (min/avg/max) ......./%7u/.......,", stats->avg_size);
 629       } else {
 630         printf (" size (min/avg/max) %7u/%7u/%7u,",
 631             stats->min_size, stats->avg_size, stats->max_size);
 632       }
 633       printf (" time %" GST_TIME_FORMAT ","
 634           " bytes/sec %lf\n",
 635           GST_TIME_ARGS (running),
 636           ((gdouble) (stats->num_buffers * stats->avg_size) * GST_SECOND) /
 637           ((gdouble) running));
 638     }
 639   }
 640 }
 641
 642 static void
 643 print_thread_stats (gpointer key, gpointer value, gpointer user_data)
 644 {
 645   GSList *list = user_data;
 646   GSList *node = g_slist_find_custom (list, key, find_pad_stats_for_thread);
 647   GstThreadStats *stats = (GstThreadStats *) value;
 648
 649   /* skip stats if there are no pads for that thread (e.g. a pipeline) */
 650   if (!node)
 651     return;
 652
 653   printf ("Thread %p Statistics:\n", key);
 654   if (GST_CLOCK_TIME_IS_VALID (stats->tthread)) {
 655     printf ("  Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (stats->tthread));
 656     printf ("  Avg CPU load: %4.1f %%\n", (gfloat) stats->cpuload / 10.0);
 657   }
 658
 659   puts ("  Pad Statistics:");
 660   g_slist_foreach (node, print_pad_stats, key);
 661 }
 662
 663 static void
 664 print_element_stats (gpointer value, gpointer user_data)
 665 {
 666   GstElementStats *stats = (GstElementStats *) value;
 667
 668   /* skip temporary elements */
 669   if (stats->first_ts != GST_CLOCK_TIME_NONE) {
 670     gchar fullname[45 + 1];
 671
 672     g_snprintf (fullname, 45, "%s:%s", stats->type_name, stats->name);
 673
 674     printf ("  %-45s:", fullname);
 675     if (stats->recv_buffers)
 676       printf (" buffers in/out %7u", stats->recv_buffers);
 677     else
 678       printf (" buffers in/out %7s", "-");
 679     if (stats->sent_buffers)
 680       printf ("/%7u", stats->sent_buffers);
 681     else
 682       printf ("/%7s", "-");
 683     if (stats->recv_bytes)
 684       printf (" bytes in/out %12" G_GUINT64_FORMAT, stats->recv_bytes);
 685     else
 686       printf (" bytes in/out %12s", "-");
 687     if (stats->sent_bytes)
 688       printf ("/%12" G_GUINT64_FORMAT, stats->sent_bytes);
 689     else
 690       printf ("/%12s", "-");
 691     printf (" first activity %" GST_TIME_FORMAT ", "
 692         " ev/msg/qry sent %5u/%5u/%5u\n", GST_TIME_ARGS (stats->first_ts),
 693         stats->num_events, stats->num_messages, stats->num_queries);
 694   }
 695 }
 696
 697 static void
 698 accum_element_stats (gpointer value, gpointer user_data)
 699 {
 700   GstElementStats *stats = (GstElementStats *) value;
 701
 702   if (stats->parent_ix != G_MAXUINT) {
 703     GstElementStats *parent_stats = get_element_stats (stats->parent_ix);
 704
 705     parent_stats->num_events += stats->num_events;
 706     parent_stats->num_messages += stats->num_messages;
 707     parent_stats->num_queries += stats->num_queries;
 708     if (!GST_CLOCK_TIME_IS_VALID (parent_stats->first_ts)) {
 709       parent_stats->first_ts = stats->first_ts;
 710     } else if (GST_CLOCK_TIME_IS_VALID (stats->first_ts)) {
 711       parent_stats->first_ts = MIN (parent_stats->first_ts, stats->first_ts);
 712     }
 713     if (!GST_CLOCK_TIME_IS_VALID (parent_stats->last_ts)) {
 714       parent_stats->last_ts = stats->last_ts;
 715     } else if (GST_CLOCK_TIME_IS_VALID (stats->last_ts)) {
 716       parent_stats->last_ts = MAX (parent_stats->last_ts, stats->last_ts);
 717     }
 718   }
 719 }
 720
 721 /* sorting */
 722
 723 static gint
 724 sort_pad_stats_by_first_activity (gconstpointer ps1, gconstpointer ps2)
 725 {
 726   GstPadStats *s1 = (GstPadStats *) ps1;
 727   GstPadStats *s2 = (GstPadStats *) ps2;
 728
 729   gint order = GST_CLOCK_DIFF (s2->first_ts, s1->first_ts);
 730
 731   if (!order) {
 732     order = s1->dir - s2->dir;
 733   }
 734   return (order);
 735 }
 736
 737 static void
 738 sort_pad_stats (gpointer value, gpointer user_data)
 739 {
 740   GSList **list = user_data;
 741
 742   *list =
 743       g_slist_insert_sorted (*list, value, sort_pad_stats_by_first_activity);
 744 }
 745
 746 static gint
 747 sort_element_stats_by_first_activity (gconstpointer es1, gconstpointer es2)
 748 {
 749   return (GST_CLOCK_DIFF (((GstElementStats *) es2)->first_ts,
 750           ((GstElementStats *) es1)->first_ts));
 751 }
 752
 753 static void
 754 sort_bin_stats (gpointer value, gpointer user_data)
 755 {
 756   if (((GstElementStats *) value)->is_bin) {
 757     GSList **list = user_data;
 758
 759     *list =
 760         g_slist_insert_sorted (*list, value,
 761         sort_element_stats_by_first_activity);
 762   }
 763 }
 764
 765 static void
 766 sort_element_stats (gpointer value, gpointer user_data)
 767 {
 768   if (!(((GstElementStats *) value)->is_bin)) {
 769     GSList **list = user_data;
 770
 771     *list =
 772         g_slist_insert_sorted (*list, value,
 773         sort_element_stats_by_first_activity);
 774   }
 775 }
 776
 777 static gboolean
 778 check_bin_parent (gpointer key, gpointer value, gpointer user_data)
 779 {
 780   GstElementStats *stats = (GstElementStats *) value;
 781
 782   return (stats->parent_ix == GPOINTER_TO_UINT (user_data));
 783 }
 784
 785 static gboolean
 786 process_leaf_bins (gpointer key, gpointer value, gpointer user_data)
 787 {
 788   GHashTable *accum_bins = user_data;
 789
 790   /* if we find no bin that has this bin as a parent ... */
 791   if (!g_hash_table_find (accum_bins, check_bin_parent, key)) {
 792     /* accumulate stats to the parent and remove */
 793     accum_element_stats (value, NULL);
 794     return TRUE;
 795   }
 796   return FALSE;
 797 }
 798
 799 /* main */
 800
 801 static gboolean
 802 init (void)
 803 {
 804   /* compile the parser regexps */
 805   /* 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" */
 806   raw_log = g_regex_new (
 807       /* 1: ts */
 808       "^([0-9:.]+) +"
 809       /* 2: pid */
 810       "([0-9]+) +"
 811       /* 3: thread */
 812       "(0x[0-9a-fA-F]+) +"
 813       /* 4: level */
 814       "([A-Z]+) +"
 815       /* 5: category */
 816       "([a-zA-Z_-]+) +"
 817       /* 6: file:line:func: */
 818       "([^:]*:[0-9]+:[^:]*:) +"
 819       /* 7: (obj)? log-text */
 820       "(.*)$", 0, 0, NULL);
 821   if (!raw_log) {
 822     GST_WARNING ("failed to compile the 'raw' parser");
 823     return FALSE;
 824   }
 825
 826   ansi_log = g_regex_new (
 827       /* 1: ts */
 828       "^([0-9:.]+) +"
 829       /* 2: pid */
 830       "\\\x1b\\[[0-9;]+m *([0-9]+)\\\x1b\\[00m +"
 831       /* 3: thread */
 832       "(0x[0-9a-fA-F]+) +"
 833       /* 4: level */
 834       "(?:\\\x1b\\[[0-9;]+m)?([A-Z]+) +\\\x1b\\[00m +"
 835       /* 5: category */
 836       "\\\x1b\\[[0-9;]+m +([a-zA-Z_-]+) +"
 837       /* 6: file:line:func: */
 838       "([^:]*:[0-9]+:[^:]*:)(?:\\\x1b\\[00m)? +"
 839       /* 7: (obj)? log-text */
 840       "(.*)$", 0, 0, NULL);
 841   if (!raw_log) {
 842     GST_WARNING ("failed to compile the 'ansi' parser");
 843     return FALSE;
 844   }
 845
 846   elements = g_ptr_array_new_with_free_func (free_element_stats);
 847   pads = g_ptr_array_new_with_free_func (free_pad_stats);
 848   threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
 849   latencies = g_hash_table_new_full (g_str_hash, g_str_equal, g_free,
 850       free_latency_stats);
 851   element_latencies = g_hash_table_new_full (g_str_hash, g_str_equal, g_free,
 852       free_latency_stats);
 853   element_reported_latencies = g_queue_new ();
 854
 855   return TRUE;
 856 }
 857
 858 static void
 859 done (void)
 860 {
 861   if (pads)
 862     g_ptr_array_free (pads, TRUE);
 863   if (elements)
 864     g_ptr_array_free (elements, TRUE);
 865   if (threads)
 866     g_hash_table_destroy (threads);
 867
 868   if (latencies) {
 869     g_hash_table_remove_all (latencies);
 870     g_hash_table_destroy (latencies);
 871     latencies = NULL;
 872   }
 873   if (element_latencies) {
 874     g_hash_table_remove_all (element_latencies);
 875     g_hash_table_destroy (element_latencies);
 876     element_latencies = NULL;
 877   }
 878   if (element_reported_latencies) {
 879     g_queue_free_full (element_reported_latencies, free_reported_latency);
 880     element_reported_latencies = NULL;
 881   }
 882
 883   if (raw_log)
 884     g_regex_unref (raw_log);
 885   if (ansi_log)
 886     g_regex_unref (ansi_log);
 887 }
 888
 889 static void
 890 print_stats (void)
 891 {
 892   guint num_threads = g_hash_table_size (threads);
 893
 894   /* print overall stats */
 895   puts ("\nOverall Statistics:");
 896   printf ("Number of Threads: %u\n", num_threads);
 897   printf ("Number of Elements: %u\n", num_elements - num_bins);
 898   printf ("Number of Bins: %u\n", num_bins);
 899   printf ("Number of Pads: %u\n", num_pads - num_ghostpads);
 900   printf ("Number of GhostPads: %u\n", num_ghostpads);
 901   printf ("Number of Buffers passed: %" G_GUINT64_FORMAT "\n", num_buffers);
 902   printf ("Number of Events sent: %" G_GUINT64_FORMAT "\n", num_events);
 903   printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n", num_messages);
 904   printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", num_queries);
 905   printf ("Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (last_ts));
 906   if (have_cpuload) {
 907     printf ("Avg CPU load: %4.1f %%\n", (gfloat) total_cpuload / 10.0);
 908   }
 909   puts ("");
 910
 911   /* thread stats */
 912   if (num_threads) {
 913     GSList *list = NULL;
 914
 915     g_ptr_array_foreach (pads, sort_pad_stats, &list);
 916     g_hash_table_foreach (threads, print_thread_stats, list);
 917     puts ("");
 918     g_slist_free (list);
 919   }
 920
 921   /* element stats */
 922   if (num_elements) {
 923     GSList *list = NULL;
 924
 925     puts ("Element Statistics:");
 926     /* sort by first_activity */
 927     g_ptr_array_foreach (elements, sort_element_stats, &list);
 928     /* attribute element stats to bins */
 929     g_slist_foreach (list, accum_element_stats, NULL);
 930     g_slist_foreach (list, print_element_stats, NULL);
 931     puts ("");
 932     g_slist_free (list);
 933   }
 934
 935   /* bin stats */
 936   if (num_bins) {
 937     GSList *list = NULL;
 938     guint i;
 939     GHashTable *accum_bins = g_hash_table_new_full (NULL, NULL, NULL, NULL);
 940
 941     puts ("Bin Statistics:");
 942     /* attribute bin stats to parent-bins */
 943     for (i = 0; i < num_elements; i++) {
 944       GstElementStats *stats = g_ptr_array_index (elements, i);
 945       if (stats->is_bin) {
 946         g_hash_table_insert (accum_bins, GUINT_TO_POINTER (i), stats);
 947       }
 948     }
 949     while (g_hash_table_size (accum_bins)) {
 950       g_hash_table_foreach_remove (accum_bins, process_leaf_bins, accum_bins);
 951     }
 952     g_hash_table_destroy (accum_bins);
 953     /* sort by first_activity */
 954     g_ptr_array_foreach (elements, sort_bin_stats, &list);
 955     g_slist_foreach (list, print_element_stats, NULL);
 956     puts ("");
 957     g_slist_free (list);
 958   }
 959
 960   /* latency stats */
 961   if (have_latency) {
 962     puts ("Latency Statistics:");
 963     g_hash_table_foreach (latencies, (GHFunc) latencies_foreach_print_stats,
 964         NULL);
 965     puts ("");
 966   }
 967
 968   /* element latency stats */
 969   if (have_element_latency) {
 970     puts ("Element Latency Statistics:");
 971     g_hash_table_foreach (element_latencies,
 972         (GHFunc) latencies_foreach_print_stats, NULL);
 973     puts ("");
 974   }
 975
 976   /* element reported latency stats */
 977   if (have_element_reported_latency) {
 978     puts ("Element Reported Latency:");
 979     g_queue_foreach (element_reported_latencies,
 980         (GFunc) reported_latencies_foreach_print_stats, NULL);
 981     puts ("");
 982   }
 983 }
 984
 985 static void
 986 collect_stats (const gchar * filename)
 987 {
 988   FILE *log;
 989
 990   if ((log = fopen (filename, "rt"))) {
 991     gchar line[5001];
 992
 993     /* probe format */
 994     if (fgets (line, 5000, log)) {
 995       GMatchInfo *match_info;
 996       GRegex *parser;
 997       GstStructure *s;
 998       guint lnr = 0;
 999       gchar *level, *data;
1000
1001       if (strchr (line, 27)) {
1002         parser = ansi_log;
1003         GST_INFO ("format is 'ansi'");
1004       } else {
1005         parser = raw_log;
1006         GST_INFO ("format is 'raw'");
1007       }
1008       rewind (log);
1009
1010       /* parse the log */
1011       while (!feof (log)) {
1012         if (fgets (line, 5000, log)) {
1013           if (g_regex_match (parser, line, 0, &match_info)) {
1014             /* filter by level */
1015             level = g_match_info_fetch (match_info, 4);
1016             if (!strcmp (level, "TRACE")) {
1017               data = g_match_info_fetch (match_info, 7);
1018               if ((s = gst_structure_from_string (data, NULL))) {
1019                 const gchar *name = gst_structure_get_name (s);
1020
1021                 if (!strcmp (name, "new-pad")) {
1022                   new_pad_stats (s);
1023                 } else if (!strcmp (name, "new-element")) {
1024                   new_element_stats (s);
1025                 } else if (!strcmp (name, "buffer")) {
1026                   do_buffer_stats (s);
1027                 } else if (!strcmp (name, "event")) {
1028                   do_event_stats (s);
1029                 } else if (!strcmp (name, "message")) {
1030                   do_message_stats (s);
1031                 } else if (!strcmp (name, "query")) {
1032                   do_query_stats (s);
1033                 } else if (!strcmp (name, "thread-rusage")) {
1034                   do_thread_rusage_stats (s);
1035                 } else if (!strcmp (name, "proc-rusage")) {
1036                   do_proc_rusage_stats (s);
1037                 } else if (!strcmp (name, "latency")) {
1038                   do_latency_stats (s);
1039                 } else if (!strcmp (name, "element-latency")) {
1040                   do_element_latency_stats (s);
1041                 } else if (!strcmp (name, "element-reported-latency")) {
1042                   do_element_reported_latency (s);
1043                 } else {
1044                   // TODO(ensonic): parse the xxx.class log lines
1045                   if (!g_str_has_suffix (data, ".class")) {
1046                     GST_WARNING ("unknown log entry: '%s'", data);
1047                   }
1048                 }
1049                 gst_structure_free (s);
1050               } else {
1051                 GST_WARNING ("unknown log entry: '%s'", data);
1052               }
1053             }
1054           } else {
1055             if (*line) {
1056               GST_WARNING ("foreign log entry: %s:%d:'%s'", filename, lnr,
1057                   g_strchomp (line));
1058             }
1059           }
1060           g_match_info_free (match_info);
1061           match_info = NULL;
1062           lnr++;
1063         } else {
1064           if (!feof (log)) {
1065             // TODO(ensonic): run wc -L on the log file
1066             fprintf (stderr, "line too long");
1067           }
1068         }
1069       }
1070     } else {
1071       GST_WARNING ("empty log");
1072     }
1073     fclose (log);
1074   }
1075 }
1076
1077 gint
1078 main (gint argc, gchar * argv[])
1079 {
1080   gchar **filenames = NULL;
1081   guint num;
1082   GError *err = NULL;
1083   GOptionContext *ctx;
1084   GOptionEntry options[] = {
1085     GST_TOOLS_GOPTION_VERSION,
1086     // TODO(ensonic): add a summary flag, if set read the whole thing, print
1087     // stats once, and exit
1088     {G_OPTION_REMAINING, 0, 0, G_OPTION_ARG_FILENAME_ARRAY, &filenames, NULL}
1089     ,
1090     {NULL}
1091   };
1092
1093 #ifdef ENABLE_NLS
1094   bindtextdomain (GETTEXT_PACKAGE, LOCALEDIR);
1095   bind_textdomain_codeset (GETTEXT_PACKAGE, "UTF-8");
1096   textdomain (GETTEXT_PACKAGE);
1097 #endif
1098
1099   g_set_prgname ("gst-stats-" GST_API_VERSION);
1100
1101   ctx = g_option_context_new ("FILE");
1102   g_option_context_add_main_entries (ctx, options, GETTEXT_PACKAGE);
1103   g_option_context_add_group (ctx, gst_init_get_option_group ());
1104   if (!g_option_context_parse (ctx, &argc, &argv, &err)) {
1105     g_print ("Error initializing: %s\n", GST_STR_NULL (err->message));
1106     exit (1);
1107   }
1108   g_option_context_free (ctx);
1109
1110   gst_tools_print_version ();
1111
1112   if (filenames == NULL || *filenames == NULL) {
1113     g_print ("Please give one filename to %s\n\n", g_get_prgname ());
1114     return 1;
1115   }
1116   num = g_strv_length (filenames);
1117   if (num == 0 || num > 1) {
1118     g_print ("Please give exactly one filename to %s (%d given).\n\n",
1119         g_get_prgname (), num);
1120     return 1;
1121   }
1122
1123   if (init ()) {
1124     collect_stats (filenames[0]);
1125     print_stats ();
1126   }
1127   done ();
1128
1129   g_strfreev (filenames);
1130   return 0;
1131 }