Add per-frame time and latency measurements

Timing is measured with a glQueryCounter(GL_TIMESTAMP) on every frame.

Latency is measured by comparing glGetIntger(GL_TIMESTAMP) which gets
the timestamp synchronously to a glQueryCounter(GL_TIMESTAMP) which
gets the timestamp asynchronously by inserting a command into the
OpenGL queue.

diff --git a/context.c b/context.c
index 3c58a60e6b2fbd76ca7a13dfaa3248f67fd43828..b18017da9b55b5d8d345e9399c5af5728a948df3 100644 (file)
--- a/context.c
+++ b/context.c
@@ -119,9 +119,15 @@ context_get_current_op (void)
 }
 
 void
-context_end_frame (void)
+context_end_frame_pre_swap (void)
 {
-       return metrics_end_frame (current_context->metrics);
+       return metrics_end_frame_pre_swap (current_context->metrics);
+}
+
+void
+context_end_frame_post_swap (void)
+{
+       return metrics_end_frame_post_swap (current_context->metrics);
 }
 
 /* Is the given extension available? */

diff --git a/context.h b/context.h
index cbfd6b48f0dbc315f824a28255f8ddf7960c48c3..70e24981024367b6ec54392ba3abdb4629f8bca3 100644 (file)
--- a/context.h
+++ b/context.h
@@ -77,13 +77,21 @@ context_set_current_op (metrics_op_t op);
 metrics_op_t
 context_get_current_op (void);
 
-/* Should be called at the end of every function wrapper for a
- * function that ends a frame, (glXSwapBuffers and similar).
+/* This pair of functions can be used to indicate a frame end.
  *
- * This function performs whatever bookkeeping is necessary to
- * generate a timing report, then emits that report.
+ * Both functions should be by every function wrapper for a function
+ * that ends a frame, (glXSwapBuffers and similar). The pre_swap
+ * before the call to the underlying swap function, and post_swap
+ * after.
+ *
+ * These functions trigger whatever bookkeeping is necessary to
+ * generate a timing report, (such as collecting any outstanding timer
+ * query values), and will also emit those reports when necessary.
  */
 void
-context_end_frame (void);
+context_end_frame_pre_swap (void);
+
+void
+context_end_frame_post_swap (void);
 
 #endif

diff --git a/eglwrap.c b/eglwrap.c
index ef927f72dec9fc8474b31e9167454acf7e6a3e70..4c51c89d3fdbcf8186014f2030a5af7118d006eb 100644 (file)
--- a/eglwrap.c
+++ b/eglwrap.c
@@ -78,9 +78,11 @@ eglSwapBuffers (EGLDisplay dpy, EGLSurface surface)
 {
        EGLBoolean ret;
 
+       context_end_frame_pre_swap ();
+
        EGLWRAP_DEFER_WITH_RETURN (ret, eglSwapBuffers, dpy, surface);
 
-       context_end_frame ();
+       context_end_frame_post_swap ();
 
        return ret;
 }

diff --git a/glxwrap.c b/glxwrap.c
index 4523c90588f2dd709926061e677460e43696ecfa..7b90ceb4008d2d98976ce3645a352d901c3eeb8d 100644 (file)
--- a/glxwrap.c
+++ b/glxwrap.c
@@ -35,9 +35,11 @@
 void
 glXSwapBuffers (Display *dpy, GLXDrawable drawable)
 {
+       context_end_frame_pre_swap ();
+
        GLWRAP_DEFER (glXSwapBuffers, dpy, drawable);
 
-       context_end_frame ();
+       context_end_frame_post_swap ();
 }
 
 /* glXGetProcAddressARB is a function which accepts a string and

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;
 

diff --git a/metrics.h b/metrics.h
index 69afafb9b69b5cf6f164dba37d4042dbda4e4092..6cfc1494175cebfe13aec05606961f9facb3d3a7 100644 (file)
--- a/metrics.h
+++ b/metrics.h
@@ -108,14 +108,22 @@ metrics_set_current_op (metrics_t *metrics, metrics_op_t op);
 metrics_op_t
 metrics_get_current_op (metrics_t *metrics);
 
-/* Should be called at the end of every function wrapper for a
- * function that ends a frame, (glXSwapBuffers and similar).
+/* This pair of functions can be used to indicate a frame end.
  *
- * This function performs whatever bookkeeping is necessary to
- * generate a timing report, then emits that report.
+ * Both functions should be by every function wrapper for a function
+ * that ends a frame, (glXSwapBuffers and similar). The pre_swap
+ * before the call to the underlying swap function, and post_swap
+ * after.
+ *
+ * These functions trigger whatever bookkeeping is necessary to
+ * generate a timing report, (such as collecting any outstanding timer
+ * query values), and will also emit those reports when necessary.
  */
 void
-metrics_end_frame (metrics_t *metrics);
+metrics_end_frame_pre_swap (metrics_t *metrics);
+
+void
+metrics_end_frame_post_swap (metrics_t *metrics);
 
 /* Process outstanding metrics requests, accumulating results.
  *