Add per-frame time and latency measurements

[fips] / metrics.c

diff --git a/metrics.c b/metrics.c
index d751ce20f6fd146dd050085abe3234e0e296a6fa..72f5400fa3c1668f468e286af707cdcd89de5497 100644 (file)
--- a/metrics.c
+++ b/metrics.c
@@ -21,6 +21,8 @@
 
 #define _GNU_SOURCE
 
+#include <inttypes.h>
+
 #include <stdio.h>
 #include <stdlib.h>
 #include <assert.h>
@@ -98,6 +100,11 @@ struct metrics
 
        unsigned num_op_metrics;
        op_metrics_t *op_metrics;
+
+       /* Per-frame time and latency measurement. */
+       GLint64 swap_begin_timestamp;
+       unsigned swap_end_timestamp_id;
+       GLint64 previous_swap_end_timestamp;
 };
 
 metrics_t *
@@ -126,6 +133,11 @@ metrics_create (metrics_info_t *info)
        metrics->num_op_metrics = 0;
        metrics->op_metrics = NULL;
 
+       glGenQueries (1, &metrics->swap_end_timestamp_id);
+
+       /* Get the first frame timestamp started immediately. */
+       glQueryCounter (metrics->swap_end_timestamp_id, GL_TIMESTAMP);
+
        return metrics;
 }
 
@@ -775,15 +787,70 @@ metrics_collect_available (metrics_t *metrics)
        }
 }
 
+void
+metrics_end_frame_pre_swap (metrics_t *metrics)
+{
+       GLint64 swap_end_timestamp, frame_time_ns, latency_ns;
+
+       /* Don't leave any counters running over the end_frame work we
+        * do here. The counters will be started again at the end of
+        * metrics_end_frame_post_swap.  */
+
+       metrics_counter_stop (metrics);
+
+       /* Now that an entire frame's worth of content has gone by, we
+        * can be sure that the timer quiery for the previous frame's
+        * swap is available.
+        *
+        * Note: The only case in which this query isn't immediately
+        * available would be if there was effectively nothing in this
+        * frame. In that case, triggering a block on this query
+        * result is not a concern (since an empty frame is not
+        * interesting, and all of our counters are stopped anyway).
+        *
+        * Accepting this one block is much better than adding a
+        * linked list for these results that would reaslisticly never
+        * have more than one entry anyway.
+        */
+
+       glGetQueryObjecti64v (metrics->swap_end_timestamp_id,
+                             GL_QUERY_RESULT, &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 = swap_end_timestamp - metrics->swap_begin_timestamp;
+
+               /* 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);
+       }
+
+       metrics->previous_swap_end_timestamp = swap_end_timestamp;
+
+       /* Before the actual swap call, we get the current timestamp
+        * value. This is a synchronous get so we can use this as the
+        * baseline for a frame latency measurment. */
+
+       glGetInteger64v (GL_TIMESTAMP, &metrics->swap_begin_timestamp);
+}
 
 void
-metrics_end_frame (metrics_t *metrics)
+metrics_end_frame_post_swap (metrics_t *metrics)
 {
        static int initialized = 0;
        static struct timeval tv_start, tv_now;
 
-       /* Don't leave any counters running over work we do here. */
-       metrics_counter_stop (metrics);
+       /* Now that the swap command has been queued, we issue an
+        * asynchronous query of the timestamp value. Comparing this
+        * to the synchronous get we just sent in
+        * metrics_end_frame_pre_swap allows us to measure the
+        * per-frame swap latency. */
+
+       glQueryCounter (metrics->swap_end_timestamp_id, GL_TIMESTAMP);
 
        if (! initialized) {
                gettimeofday (&tv_start, NULL);
@@ -792,10 +859,10 @@ metrics_end_frame (metrics_t *metrics)
                initialized = 1;
        }
 
-       frames++;
-
        metrics_collect_available (metrics);
 
+       frames++;
+
        if (frames % 15 == 0) {
                double fps;