stats: improve cpu load meassurements

Rename variables for clarity. Handle the initial disparity between debug time
and the time already spent in the proc and main thread.

diff --git a/plugins/tracers/gstrusage.c b/plugins/tracers/gstrusage.c
index 22f1eb3..f54f53a 100644 (file)
--- a/plugins/tracers/gstrusage.c
+++ b/plugins/tracers/gstrusage.c
@@ -44,11 +44,14 @@ GST_DEBUG_CATEGORY_STATIC (gst_rusage_debug);
 G_DEFINE_TYPE_WITH_CODE (GstRUsageTracer, gst_rusage_tracer, GST_TYPE_TRACER,
     _do_init);
 
+/* for ts calibration */
+static gpointer main_thread_id = NULL;
+static guint64 tproc_base = G_GINT64_CONSTANT (0);
+
 typedef struct
 {
   /* time spend in this thread */
-  GstClockTime treal;
-  guint max_cpuload;
+  GstClockTime tthread;
 } GstThreadStats;
 
 static void gst_rusage_tracer_invoke (GstTracer * self, GstTracerHookId id,
@@ -75,6 +78,9 @@ gst_rusage_tracer_init (GstRUsageTracer * self)
 {
   g_object_set (self, "mask", GST_TRACER_HOOK_ALL, NULL);
   self->threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
+
+  main_thread_id = g_thread_self ();
+  GST_DEBUG ("rusage: main thread=%p", main_thread_id);
 }
 
 static void
@@ -82,12 +88,12 @@ gst_rusage_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
     GstTracerMessageId mid, va_list var_args)
 {
   GstRUsageTracer *self = GST_RUSAGE_TRACER_CAST (obj);
-  guint64 treal = va_arg (var_args, guint64);
+  guint64 ts = va_arg (var_args, guint64);
   GstThreadStats *stats;
   gpointer thread_id = g_thread_self ();
   guint cpuload = 0;
   struct rusage ru;
-  GstClockTime tusersys = G_GUINT64_CONSTANT (0);
+  GstClockTime tproc = G_GUINT64_CONSTANT (0);
 
   // FIXME(ensonic): not threadsafe
   static GstClockTime last_ts = G_GUINT64_CONSTANT (0);
@@ -104,30 +110,49 @@ gst_rusage_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
     struct timespec now;
 
     if (!clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &now)) {
-      tusersys = GST_TIMESPEC_TO_TIME (now);
+      tproc = GST_TIMESPEC_TO_TIME (now);
     } else {
       GST_WARNING ("clock_gettime (CLOCK_PROCESS_CPUTIME_ID,...) failed.");
-      tusersys =
+      tproc =
           GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
     }
 
     /* cpu time per thread */
     if (!clock_gettime (CLOCK_THREAD_CPUTIME_ID, &now)) {
-      stats->treal = GST_TIMESPEC_TO_TIME (now);
+      stats->tthread = GST_TIMESPEC_TO_TIME (now);
     } else {
       GST_WARNING ("clock_gettime (CLOCK_THREAD_CPUTIME_ID,...) failed.");
-      stats->treal += GST_CLOCK_DIFF (last_ts, treal);
+      stats->tthread += GST_CLOCK_DIFF (last_ts, ts);
     }
   }
 #else
-  tusersys =
-      GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
+  tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
   /* crude way to meassure time spend in which thread */
-  stats->treal += GST_CLOCK_DIFF (last_ts, treal);
+  stats->tthread += GST_CLOCK_DIFF (last_ts, ts);
 #endif
 
-  /* remember last timestamp for percentage calculations */
-  last_ts = treal;
+  /* remember last timestamp for fallback calculations */
+  last_ts = ts;
+
+  /* Calibrate ts for the process and main thread. For tthread[main] and tproc
+   * the time is larger than ts, as our base-ts is taken after the process has
+   * started.
+   */
+  if (G_UNLIKELY (thread_id == main_thread_id)) {
+    main_thread_id = NULL;
+    /* when the registry gets updated, the tproc is less than the debug time ? */
+    /* TODO(ensonic): we still see cases where tproc overtakes ts, especially
+     * when with sync=false, can this be due to multiple cores in use? */
+    if (tproc > ts) {
+      tproc_base = tproc - ts;
+      GST_DEBUG ("rusage: calibrating by %" G_GUINT64_FORMAT ", thread: %"
+          G_GUINT64_FORMAT ", proc: %" G_GUINT64_FORMAT,
+          tproc_base, stats->tthread, tproc);
+      stats->tthread -= tproc_base;
+    }
+  }
+  /* we always need to corect proc time */
+  tproc -= tproc_base;
 
   /* FIXME: how can we take cpu-frequency scaling into account?
    * - looking at /sys/devices/system/cpu/cpu0/cpufreq/
@@ -136,9 +161,9 @@ gst_rusage_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
    *   cpufreq-selector -g performance
    *   cpufreq-selector -g ondemand
    */
-  cpuload =
-      (guint) gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT (100), treal);
-  gst_tracer_log_trace (gst_structure_new ("rusage", "ts", G_TYPE_UINT64, treal, "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (thread_id), "cpuload", G_TYPE_UINT, cpuload, "treal", G_TYPE_UINT64, stats->treal, /* time in thread */
-          "tsum", G_TYPE_UINT64, tusersys,      /* time in process */
+  cpuload = (guint) gst_util_uint64_scale (tproc, G_GINT64_CONSTANT (100), ts);
+  gst_tracer_log_trace (gst_structure_new ("rusage", "ts", G_TYPE_UINT64, ts, "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (thread_id), "cpuload", G_TYPE_UINT, cpuload,  /* cpu usage per thread - FIXME: not used in gst-stats */
+          "thread-time", G_TYPE_UINT64, stats->tthread, /* time spent in thread */
+          "proc-time", G_TYPE_UINT64, tproc,    /* time spent in process */
           NULL));
 }

diff --git a/tools/gst-stats.c b/tools/gst-stats.c
index 2ab514c..b2a6f32 100644 (file)
--- a/tools/gst-stats.c
+++ b/tools/gst-stats.c
@@ -41,8 +41,7 @@ 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 GstClockTime tusersys = G_GUINT64_CONSTANT (0);
-static guint64 total_cpuload = 0;
+static GstClockTime tproc = G_GUINT64_CONSTANT (0);
 
 typedef struct
 {
@@ -78,7 +77,7 @@ typedef struct
   /* first activity on the element */
   GstClockTime first_ts, last_ts;
   /* time spend in this element */
-  GstClockTime treal;
+  GstClockTime tthread;
   /* hierarchy */
   guint parent_ix;
 } GstElementStats;
@@ -86,7 +85,7 @@ typedef struct
 typedef struct
 {
   /* time spend in this thread */
-  GstClockTime treal;
+  GstClockTime tthread;
 } GstThreadStats;
 
 /* stats helper */
@@ -294,7 +293,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 = ts;
+  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;
@@ -329,7 +328,7 @@ 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 = ts;
+  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;
@@ -352,7 +351,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 = ts;
+  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;
@@ -370,7 +369,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 = ts;
+  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;
@@ -381,17 +380,17 @@ do_query_stats (GstStructure * s)
 static void
 do_rusage_stats (GstStructure * s)
 {
-  guint64 ts, treal;
-  guint thread_id, cpuload;
+  guint64 ts, tthread;
+  guint thread_id;
   GstThreadStats *thread_stats;
 
   gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
       "thread-id", G_TYPE_UINT, &thread_id,
-      "cpuload", G_TYPE_UINT, &cpuload,
-      "treal", G_TYPE_UINT64, &treal, "tsum", G_TYPE_UINT64, &tusersys, NULL);
+      "thread-time", G_TYPE_UINT64, &tthread,
+      "proc-time", G_TYPE_UINT64, &tproc, NULL);
   thread_stats = get_thread_stats (thread_id);
-  thread_stats->treal = treal;
-  last_ts = ts;
+  thread_stats->tthread = tthread;
+  last_ts = MAX (last_ts, ts);
 }
 
 /* reporting */
@@ -452,25 +451,18 @@ print_thread_stats (gpointer key, gpointer value, gpointer user_data)
   GSList *list = user_data;
   GSList *node = g_slist_find_custom (list, key, find_pad_stats_for_thread);
   GstThreadStats *stats = (GstThreadStats *) value;
-  guint cpuload = 0;
-  guint time_percent;
+  guint cpuload;
 
   /* skip stats if there are no pads for that thread (e.g. a pipeline) */
   if (!node)
     return;
 
-  time_percent =
-      (guint) gst_util_uint64_scale (stats->treal, G_GINT64_CONSTANT (100),
+  cpuload =
+      (guint) gst_util_uint64_scale (stats->tthread, G_GINT64_CONSTANT (100),
       last_ts);
 
-  if (total_cpuload) {
-    cpuload =
-        (guint) gst_util_uint64_scale (total_cpuload, stats->treal, last_ts);
-  }
-
   printf ("Thread %p Statistics:\n", key);
-  printf ("  Time: %" GST_TIME_FORMAT ", %u %%\n", GST_TIME_ARGS (stats->treal),
-      (guint) time_percent);
+  printf ("  Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (stats->tthread));
   printf ("  Avg CPU load: %u %%\n", cpuload);
 
   puts ("  Pad Statistics:");
@@ -687,6 +679,7 @@ static void
 print_stats (void)
 {
   guint num_threads = g_hash_table_size (threads);
+  guint64 total_cpuload = 0;
 
   /* print overall stats */
   puts ("\nOverall Statistics:");
@@ -700,8 +693,8 @@ print_stats (void)
   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 (tusersys) {
-    total_cpuload = gst_util_uint64_scale (tusersys,
+  if (tproc) {
+    total_cpuload = gst_util_uint64_scale (tproc,
         G_GINT64_CONSTANT (100), last_ts);
     printf ("Avg CPU load: %u %%\n", (guint) total_cpuload);
   }