stats: fix cpu stats printing
[platform/upstream/gstreamer.git] / tools / gst-stats.c
index c7c550e..95bba8c 100644 (file)
@@ -40,6 +40,9 @@ static GPtrArray *pads = NULL;
 static guint64 num_buffers = 0, num_events = 0, num_messages = 0, num_queries =
     0;
 static guint num_elements = 0, num_bins = 0, num_pads = 0, num_ghostpads = 0;
+static GstClockTime last_ts = G_GUINT64_CONSTANT (0);
+static guint total_cpuload = 0;
+static gboolean have_cpuload = FALSE;
 
 typedef struct
 {
@@ -74,8 +77,6 @@ typedef struct
   guint num_events, num_messages, num_queries;
   /* first activity on the element */
   GstClockTime first_ts, last_ts;
-  /* time spend in this element */
-  GstClockTime treal;
   /* hierarchy */
   guint parent_ix;
 } GstElementStats;
@@ -83,8 +84,8 @@ typedef struct
 typedef struct
 {
   /* time spend in this thread */
-  GstClockTime treal;
-  guint max_cpuload;
+  GstClockTime tthread;
+  guint cpuload;
 } GstThreadStats;
 
 /* stats helper */
@@ -113,11 +114,24 @@ free_pad_stats (gpointer data)
   g_slice_free (GstPadStats, data);
 }
 
+static inline GstThreadStats *
+get_thread_stats (guint id)
+{
+  GstThreadStats *stats = g_hash_table_lookup (threads, GUINT_TO_POINTER (id));
+
+  if (G_UNLIKELY (!stats)) {
+    stats = g_slice_new0 (GstThreadStats);
+    stats->tthread = GST_CLOCK_TIME_NONE;
+    g_hash_table_insert (threads, GUINT_TO_POINTER (id), stats);
+  }
+  return stats;
+}
+
 static void
 new_pad_stats (GstStructure * s)
 {
   GstPadStats *stats;
-  guint ix;
+  guint ix, parent_ix;
   gchar *type, *name;
   gboolean is_ghost_pad;
   GstPadDirection dir;
@@ -125,6 +139,7 @@ new_pad_stats (GstStructure * s)
 
   gst_structure_get (s,
       "ix", G_TYPE_UINT, &ix,
+      "parent-ix", G_TYPE_UINT, &parent_ix,
       "name", G_TYPE_STRING, &name,
       "type", G_TYPE_STRING, &type,
       "is-ghostpad", G_TYPE_BOOLEAN, &is_ghost_pad,
@@ -143,31 +158,24 @@ new_pad_stats (GstStructure * s)
   stats->min_size = G_MAXUINT;
   stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE;
   stats->thread_id = thread_id;
+  stats->parent_ix = parent_ix;
 
   if (pads->len <= ix)
     g_ptr_array_set_size (pads, ix + 1);
   g_ptr_array_index (pads, ix) = stats;
-
-  if (thread_id) {
-    GstThreadStats *thread_stats;
-    if (!(thread_stats = g_hash_table_lookup (threads,
-                GUINT_TO_POINTER (thread_id)))) {
-      thread_stats = g_slice_new0 (GstThreadStats);
-      g_hash_table_insert (threads, GUINT_TO_POINTER (thread_id), thread_stats);
-    }
-  }
 }
 
 static void
 new_element_stats (GstStructure * s)
 {
   GstElementStats *stats;
-  guint ix;
+  guint ix, parent_ix;
   gchar *type, *name;
   gboolean is_bin;
 
   gst_structure_get (s,
       "ix", G_TYPE_UINT, &ix,
+      "parent-ix", G_TYPE_UINT, &parent_ix,
       "name", G_TYPE_STRING, &name,
       "type", G_TYPE_STRING, &type, "is-bin", G_TYPE_BOOLEAN, &is_bin, NULL);
 
@@ -180,7 +188,7 @@ new_element_stats (GstStructure * s)
   stats->type_name = type;
   stats->is_bin = is_bin;
   stats->first_ts = GST_CLOCK_TIME_NONE;
-  stats->parent_ix = G_MAXUINT;
+  stats->parent_ix = parent_ix;
 
   if (elements->len <= ix)
     g_ptr_array_set_size (elements, ix + 1);
@@ -204,6 +212,10 @@ do_pad_stats (GstPadStats * stats, guint elem_ix, guint size, guint64 ts,
     stats->parent_ix = elem_ix;
   }
 
+  if (stats->thread_id) {
+    get_thread_stats (stats->thread_id);
+  }
+
   /* size stats */
   avg_size = (((gulong) stats->avg_size * (gulong) stats->num_buffers) + size);
   stats->num_buffers++;
@@ -282,6 +294,7 @@ do_buffer_stats (GstStructure * s)
       "buffer-ts", G_TYPE_UINT64, &buffer_ts,
       "buffer-duration", G_TYPE_UINT64, &buffer_dur,
       "buffer-flags", GST_TYPE_BUFFER_FLAGS, &buffer_flags, NULL);
+  last_ts = MAX (last_ts, ts);
   if (!(pad_stats = get_pad_stats (pad_ix))) {
     GST_WARNING ("no pad stats found for ix=%u", pad_ix);
     return;
@@ -316,12 +329,14 @@ do_event_stats (GstStructure * s)
   num_events++;
   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
       "pad-ix", G_TYPE_UINT, &pad_ix, "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+  last_ts = MAX (last_ts, ts);
   if (!(pad_stats = get_pad_stats (pad_ix))) {
     GST_WARNING ("no pad stats found for ix=%u", pad_ix);
     return;
   }
   if (!(elem_stats = get_element_stats (elem_ix))) {
-    GST_WARNING ("no element stats found for ix=%u", elem_ix);
+    // e.g. reconfigure events are send over unparented pads
+    GST_INFO ("no element stats found for ix=%u", elem_ix);
     return;
   }
   elem_stats->num_events++;
@@ -337,6 +352,7 @@ do_message_stats (GstStructure * s)
   num_messages++;
   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
       "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+  last_ts = MAX (last_ts, ts);
   if (!(elem_stats = get_element_stats (elem_ix))) {
     GST_WARNING ("no element stats found for ix=%u", elem_ix);
     return;
@@ -354,6 +370,7 @@ do_query_stats (GstStructure * s)
   num_queries++;
   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
       "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+  last_ts = MAX (last_ts, ts);
   if (!(elem_stats = get_element_stats (elem_ix))) {
     GST_WARNING ("no element stats found for ix=%u", elem_ix);
     return;
@@ -361,8 +378,48 @@ do_query_stats (GstStructure * s)
   elem_stats->num_queries++;
 }
 
+static void
+do_thread_rusage_stats (GstStructure * s)
+{
+  guint64 ts, tthread;
+  guint thread_id, cpuload;
+  GstThreadStats *thread_stats;
+
+  gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+      "thread-id", G_TYPE_UINT, &thread_id,
+      "average-cpuload", G_TYPE_UINT, &cpuload, "time", G_TYPE_UINT64, &tthread,
+      NULL);
+  thread_stats = get_thread_stats (thread_id);
+  thread_stats->cpuload = cpuload;
+  thread_stats->tthread = tthread;
+  last_ts = MAX (last_ts, ts);
+}
+
+static void
+do_proc_rusage_stats (GstStructure * s)
+{
+  guint64 ts;
+
+  gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+      "average-cpuload", G_TYPE_UINT, &total_cpuload, NULL);
+  last_ts = MAX (last_ts, ts);
+  have_cpuload = TRUE;
+}
+
 /* reporting */
 
+static gint
+find_pad_stats_for_thread (gconstpointer value, gconstpointer user_data)
+{
+  const GstPadStats *stats = (const GstPadStats *) value;
+
+  if ((stats->thread_id == GPOINTER_TO_UINT (user_data)) &&
+      (stats->num_buffers)) {
+    return 0;
+  }
+  return 1;
+}
+
 static void
 print_pad_stats (gpointer value, gpointer user_data)
 {
@@ -405,35 +462,21 @@ static void
 print_thread_stats (gpointer key, gpointer value, gpointer user_data)
 {
   GSList *list = user_data;
-#if 0
+  GSList *node = g_slist_find_custom (list, key, find_pad_stats_for_thread);
   GstThreadStats *stats = (GstThreadStats *) value;
-  guint cpuload = 0;
-  guint time_percent;
 
-  time_percent =
-      (guint) gst_util_uint64_scale (stats->treal, G_GINT64_CONSTANT (100),
-      last_ts);
-
-  if (tusersys) {
-    guint64 total;
-    /* cpuload for the process, scaled by the timeslice of this thread */
-    //cpuload = (guint) gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT(100) * stats->treal, last_ts * last_ts);
+  /* skip stats if there are no pads for that thread (e.g. a pipeline) */
+  if (!node)
+    return;
 
-    total = gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT (100), last_ts);
-    cpuload = gst_util_uint64_scale (total, stats->treal, last_ts);
+  printf ("Thread %p Statistics:\n", key);
+  if (GST_CLOCK_TIME_IS_VALID (stats->tthread)) {
+    printf ("  Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (stats->tthread));
+    printf ("  Avg CPU load: %4.1f %%\n", (gfloat) stats->cpuload / 10.0);
   }
 
-  printf ("Thread %p Statistics:\n", key);
-  printf ("  Time: %" GST_TIME_FORMAT ", %u %%\n", GST_TIME_ARGS (stats->treal),
-      (guint) time_percent);
-  printf ("  Avg/Max CPU load: %u %%, %u %%\n", cpuload, stats->max_cpuload);
-#endif
-  /* FIXME: would be nice to skip, if there are no pads for that thread
-   * (e.g. a pipeline), we would need to pass as struct to
-   * g_hash_table_foreach::user_data
-   */
   puts ("  Pad Statistics:");
-  g_slist_foreach (list, print_pad_stats, key);
+  g_slist_foreach (node, print_pad_stats, key);
 }
 
 static void
@@ -443,7 +486,6 @@ print_element_stats (gpointer value, gpointer user_data)
 
   /* skip temporary elements */
   if (stats->first_ts != GST_CLOCK_TIME_NONE) {
-    //GstClockTimeDiff running = GST_CLOCK_DIFF (stats->first_ts, stats->last_ts);
     gchar fullname[45 + 1];
 
     g_snprintf (fullname, 45, "%s:%s", stats->type_name, stats->name);
@@ -465,10 +507,9 @@ print_element_stats (gpointer value, gpointer user_data)
       printf ("/%12" G_GUINT64_FORMAT, stats->sent_bytes);
     else
       printf ("/%12s", "-");
-    printf (" first activity %" GST_TIME_FORMAT ", " " ev/msg/qry sent %5u/%5u/%5u"     /*", "
-                                                                                           " cpu usage %u %%" */
-        "\n", GST_TIME_ARGS (stats->first_ts), stats->num_events, stats->num_messages, stats->num_queries       /*,
-                                                                                                                   (guint)(100*stats->treal/last_ts) */ );
+    printf (" first activity %" GST_TIME_FORMAT ", "
+        " ev/msg/qry sent %5u/%5u/%5u\n", GST_TIME_ARGS (stats->first_ts),
+        stats->num_events, stats->num_messages, stats->num_queries);
   }
 }
 
@@ -660,6 +701,10 @@ print_stats (void)
   printf ("Number of Events sent: %" G_GUINT64_FORMAT "\n", num_events);
   printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n", num_messages);
   printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", num_queries);
+  printf ("Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (last_ts));
+  if (have_cpuload) {
+    printf ("Avg CPU load: %4.1f %%\n", (gfloat) total_cpuload / 10.0);
+  }
   puts ("");
 
   /* thread stats */
@@ -748,8 +793,6 @@ collect_stats (const gchar * filename)
               if ((s = gst_structure_from_string (data, NULL))) {
                 const gchar *name = gst_structure_get_name (s);
 
-                // TODO(ensonic): add a function for each name-id quark
-                // these function will do the actual stats tracking
                 if (!strcmp (name, "new-pad")) {
                   new_pad_stats (s);
                 } else if (!strcmp (name, "new-element")) {
@@ -762,8 +805,15 @@ collect_stats (const gchar * filename)
                   do_message_stats (s);
                 } else if (!strcmp (name, "query")) {
                   do_query_stats (s);
+                } else if (!strcmp (name, "thread-rusage")) {
+                  do_thread_rusage_stats (s);
+                } else if (!strcmp (name, "proc-rusage")) {
+                  do_proc_rusage_stats (s);
                 } else {
-                  GST_WARNING ("unknown log entry: '%s'", data);
+                  // TODO(ensonic): parse the xxx.class log lines
+                  if (!g_str_has_suffix (data, ".class")) {
+                    GST_WARNING ("unknown log entry: '%s'", data);
+                  }
                 }
                 gst_structure_free (s);
               } else {
@@ -787,7 +837,6 @@ collect_stats (const gchar * filename)
         }
       }
       fclose (log);
-      // TODO(ensonic): print stats
     } else {
       GST_WARNING ("empty log");
     }