From a61ba86b00f083f5e4afbd472937b856f1e618e7 Mon Sep 17 00:00:00 2001 From: Carl Worth Date: Tue, 5 Nov 2013 09:56:07 -0800 Subject: [PATCH] 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. --- context.c | 10 ++++++-- context.h | 18 +++++++++---- eglwrap.c | 4 ++- glxwrap.c | 4 ++- metrics.c | 77 +++++++++++++++++++++++++++++++++++++++++++++++++++---- metrics.h | 18 +++++++++---- 6 files changed, 112 insertions(+), 19 deletions(-) diff --git a/context.c b/context.c index 3c58a60..b18017d 100644 --- 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 cbfd6b4..70e2498 100644 --- 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 ef927f7..4c51c89 100644 --- 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 4523c90..7b90ceb 100644 --- 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 d751ce2..72f5400 100644 --- a/metrics.c +++ b/metrics.c @@ -21,6 +21,8 @@ #define _GNU_SOURCE +#include + #include #include #include @@ -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 69afafb..6cfc149 100644 --- 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. * -- 2.43.0