Do something sensible for timestamp wrapping.

[fips] / metrics.c

diff --git a/metrics.c b/metrics.c
index 72f5400fa3c1668f468e286af707cdcd89de5497..c52bf2ee6c3557dd6b8b41dda820ac24bced4e5b 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,8 +108,33 @@ 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;
 };
 
+/* Return (a - b) while accounting for the fact that between a and b,
+ * the counter may have wrapped around (with a maximum number of bits
+ * in the counter of GL_QUERY_COUNTER_BITS). */
+static uint64_t
+subtract_timestamp (uint64_t a, uint64_t b)
+{
+       GLint timestamp_bits;
+
+       glGetQueryiv (GL_TIMESTAMP, GL_QUERY_COUNTER_BITS, &timestamp_bits);
+
+       /* Note: "<<" isn't defined for the number of bits in the
+        * type, and the compiler will punish you.
+        */
+       if (timestamp_bits == 64)
+               return a - b;
+
+       if (b > a)
+               return (1ull << timestamp_bits) + a - b;
+       else
+               return a - b;
+}
+
 metrics_t *
 metrics_create (metrics_info_t *info)
 {
@@ -138,6 +166,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 +434,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 +819,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)
 {
-       GLint64 swap_end_timestamp, frame_time_ns, latency_ns;
+       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
@@ -813,23 +850,35 @@ metrics_end_frame_pre_swap (metrics_t *metrics)
         * have more than one entry anyway.
         */
 
-       glGetQueryObjecti64v (metrics->swap_end_timestamp_id,
-                             GL_QUERY_RESULT, &swap_end_timestamp);
+       glGetQueryObjectui64v (metrics->swap_end_timestamp_id,
+                              GL_QUERY_RESULT, &swap_end_timestamp);
+
+       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 = subtract_timestamp (swap_end_timestamp,
+                                                   metrics->previous_swap_end_timestamp);
 
-       if (frames > 0) {
-               /* Subtract previous frame's timestamp to get frame time. */
-               frame_time_ns = swap_end_timestamp - metrics->previous_swap_end_timestamp;
+               latency_ns = subtract_timestamp (swap_end_timestamp,
+                                                metrics->swap_begin_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 %d: %.2f ms (latency: %.2f ms)\n",
-                       frames - 1, frame_time_ns / 1e6, latency_ns / 1e6);
+               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
@@ -843,6 +892,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
@@ -852,6 +902,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"))