Capture and print CPU load on a per-frame basis.

We use clock_gettime to measure the amount of CPU time accrued by the
active process. Then, by subtracting the value between succesive frame
times and dividing by the total wall-clock time for the frame, we
determine a measure of the per-frame CPU load from 0.0 to 1.0.

We now print the frame number, frame time, frame latency, and CPU load
in a single-line format for simpler parsing, (with a header comment
describing the names and units for each field).

diff --git a/metrics.c b/metrics.c
index 2fe2dc7c9ba875b08eb239c432799f21997f190f..0c61e0ebab1620e715b4dad64c825c86452dade5 100644 (file)
--- a/metrics.c
+++ b/metrics.c
@@ -26,7 +26,10 @@
 #include <stdio.h>
 #include <stdlib.h>
 #include <assert.h>
+#include <time.h>
 #include <sys/time.h>
+#include <string.h>
+#include <errno.h>
 
 #include "fips-dispatch-gl.h"
 
@@ -105,6 +108,9 @@ struct metrics
        GLint64 swap_begin_timestamp;
        unsigned swap_end_timestamp_id;
        GLint64 previous_swap_end_timestamp;
+
+       struct timespec previous_cpu_time_ts;
+       struct timespec cpu_time_ts;
 };
 
 metrics_t *
@@ -787,10 +793,15 @@ metrics_collect_available (metrics_t *metrics)
        }
 }
 
+/* Return the difference from ts0 to ts1 as floating-point seconds. */
+#define TIMESPEC_DIFF(ts0, ts1) (double) (ts1.tv_sec - ts0.tv_sec + \
+                                         (ts1.tv_nsec - ts0.tv_nsec) / 1e9)
+
 void
 metrics_end_frame_pre_swap (metrics_t *metrics)
 {
        GLuint64 swap_end_timestamp, frame_time_ns, latency_ns;
+       double cpu_time;
 
        /* Don't leave any counters running over the end_frame work we
         * do here. The counters will be started again at the end of
@@ -816,24 +827,29 @@ metrics_end_frame_pre_swap (metrics_t *metrics)
        glGetQueryObjectui64v (metrics->swap_end_timestamp_id,
                               GL_QUERY_RESULT, &swap_end_timestamp);
 
-       if (frames > 0) {
-               /* Subtract previous frame's timestamp to get frame time. */
+       if (frames == 0) {
+               /* Print header */
+               printf ("# frame: Frame_Number Frame_Time_milliseconds Frame_latency_milliseconds CPU_load\n");
+       } else {
+               /* Subtract previous frame's times to get frame times. */
                frame_time_ns = swap_end_timestamp - metrics->previous_swap_end_timestamp;
 
                latency_ns = swap_end_timestamp - metrics->swap_begin_timestamp;
 
+               cpu_time = TIMESPEC_DIFF (metrics->previous_cpu_time_ts, metrics->cpu_time_ts);
+
                /* We've waited one frame to ensure we have a timestamp
                 * result. So the time we've actually measured here is
                 * for the previous frame. */
-               printf ("frame-time: %d %" PRId64 "\n",
-                       frames - 1, frame_time_ns);
-
-               printf ("frame-latency: %d %" PRId64 "\n",
-                       frames - 1, latency_ns);
-
+               printf ("frame: %d %g %g %g\n",
+                       frames - 1,
+                       (double) frame_time_ns / 1e6,
+                       (double) latency_ns / 1e6,
+                       cpu_time / (frame_time_ns / 1e9));
        }
 
        metrics->previous_swap_end_timestamp = swap_end_timestamp;
+       metrics->previous_cpu_time_ts = metrics->cpu_time_ts;
 
        /* Before the actual swap call, we get the current timestamp
         * value. This is a synchronous get so we can use this as the
@@ -847,6 +863,7 @@ metrics_end_frame_post_swap (metrics_t *metrics)
 {
        static int initialized = 0;
        static struct timeval tv_start, tv_now;
+       int err;
 
        /* Now that the swap command has been queued, we issue an
         * asynchronous query of the timestamp value. Comparing this
@@ -856,6 +873,14 @@ metrics_end_frame_post_swap (metrics_t *metrics)
 
        glQueryCounter (metrics->swap_end_timestamp_id, GL_TIMESTAMP);
 
+       /* Query the total amount of CPU time spent by this process. */
+       err = clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &metrics->cpu_time_ts);
+       if (err == -1 ) {
+               fprintf (stderr, "Failed to query CPU time with clock_gettime: %s\n",
+                        strerror (errno));
+               exit (1);
+       }
+
        if (! initialized) {
                gettimeofday (&tv_start, NULL);
                if (getenv ("FIPS_VERBOSE"))