Fix CPU load reported on initial frame.

[fips] / metrics.c

diff --git a/metrics.c b/metrics.c
index 2fe2dc7c9ba875b08eb239c432799f21997f190f..36ef90bf1c86b661204745b83aced491e675ed84 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 *
@@ -138,6 +144,9 @@ metrics_create (metrics_info_t *info)
        /* Get the first frame timestamp started immediately. */
        glQueryCounter (metrics->swap_end_timestamp_id, GL_TIMESTAMP);
 
+       /* As well as the initial CPU time. */
+       clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &metrics->cpu_time_ts);
+
        return metrics;
 }
 
@@ -403,6 +412,7 @@ accumulate_program_metrics (metrics_t *metrics, metrics_op_t op,
        {                                                               \
                fprintf (stderr, "Unexpected end-of-buffer while "      \
                         "parsing results\n");                          \
+               value = 0.0;                                            \
                break;                                                  \
        }                                                               \
        (var) = *((typeof(var) *) p);                                   \
@@ -787,10 +797,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 +831,30 @@ 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 GPU_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 %g\n",
+                       frames - 1,
+                       (double) frame_time_ns / 1e6,
+                       (double) latency_ns / 1e6,
+                       cpu_time / (frame_time_ns / 1e9),
+                       0.0);
        }
 
        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 +868,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 +878,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"))