]> git.cworth.org Git - fips/blobdiff - metrics.c
stash
[fips] / metrics.c
index 47df1e0cf4a7071f5186b24c04cf95898da92311..ad7ea3a330cc27b6354e13a8070209b0b406bd13 100644 (file)
--- a/metrics.c
+++ b/metrics.c
 
 #define _GNU_SOURCE
 
+#include <inttypes.h>
+
 #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"
 
@@ -59,7 +64,7 @@ typedef struct monitor
 typedef struct op_metrics
 {
        /* This happens to also be the index into the
-        * ctx->op_metrics array currently
+        * metrics->op_metrics array currently
         */
        metrics_op_t op;
        double time_ns;
@@ -69,6 +74,9 @@ typedef struct op_metrics
 
 struct metrics
 {
+       /* Flag to indicate first frame is being processed. */
+       bool first_frame;
+
        /* Description of all available peformance counters, counter
         * groups, their names and IDs, etc. */
        metrics_info_t *info;
@@ -98,8 +106,38 @@ 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;
+
+       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)
 {
@@ -109,6 +147,8 @@ metrics_create (metrics_info_t *info)
 
        metrics->info = info;
 
+       metrics->first_frame = true;
+
        metrics->op = 0;
 
        metrics->timer_begun_id = 0;
@@ -126,6 +166,14 @@ 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);
+
+       /* As well as the initial CPU time. */
+       clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &metrics->cpu_time_ts);
+
        return metrics;
 }
 
@@ -137,7 +185,6 @@ metrics_fini (metrics_t *metrics)
 
        /* Discard and cleanup any outstanding queries. */
        if (metrics->timer_begun_id) {
-               glEndQuery (GL_TIME_ELAPSED);
                glDeleteQueries (1, &metrics->timer_begun_id);
                metrics->timer_begun_id = 0;
        }
@@ -153,22 +200,25 @@ metrics_fini (metrics_t *metrics)
        metrics->timer_head = NULL;
        metrics->timer_tail = NULL;
 
-       if (metrics->monitor_begun_id) {
-               glEndPerfMonitorAMD (metrics->monitor_begun_id);
-               glDeletePerfMonitorsAMD (1, &metrics->monitor_begun_id);
-               metrics->monitor_begun_id = 0;
-       }
+       if (metrics->info->have_perfmon) {
+
+               if (metrics->monitor_begun_id) {
+                       glDeletePerfMonitorsAMD (1, &metrics->monitor_begun_id);
+                       metrics->monitor_begun_id = 0;
+               }
+
+               for (monitor = metrics->monitor_head;
+                    monitor;
+                    monitor = monitor_next)
+               {
+                       glDeletePerfMonitorsAMD (1, &monitor->id);
+                       monitor_next = monitor->next;
+                       free (monitor);
+               }
+               metrics->monitor_head = NULL;
+               metrics->monitor_tail = NULL;
 
-       for (monitor = metrics->monitor_head;
-            monitor;
-            monitor = monitor_next)
-       {
-               glDeletePerfMonitorsAMD (1, &monitor->id);
-               monitor_next = monitor->next;
-               free (monitor);
        }
-       metrics->monitor_head = NULL;
-       metrics->monitor_tail = NULL;
 
        metrics->monitors_in_flight = 0;
 }
@@ -227,15 +277,22 @@ metrics_op_string (metrics_op_t op)
 }
 
 void
-metrics_counter_start (void)
+metrics_counter_start (metrics_t *metrics)
 {
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
        unsigned i;
 
-       /* Initialize the timer_query and monitor objects */
+       /* Initialize the timer_query object. */
        glGenQueries (1, &metrics->timer_begun_id);
 
+       /* Most everything else in this function is
+        * performance-monitor related. If we don't have that
+        * extension, just start the timer query and be done. */
+       if (! metrics->info->have_perfmon) {
+               glBeginQuery (GL_TIME_ELAPSED, metrics->timer_begun_id);
+               return;
+       }
+
+       /* Initialize the performance-monitor object */
        glGenPerfMonitorsAMD (1, &metrics->monitor_begun_id);
 
        for (i = 0; i < metrics->info->num_groups; i++)
@@ -268,16 +325,16 @@ metrics_counter_start (void)
 }
 
 void
-metrics_counter_stop (void)
+metrics_counter_stop (metrics_t *metrics)
 {
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
        timer_query_t *timer;
        monitor_t *monitor;
 
        /* Stop the current timer and monitor. */
        glEndQuery (GL_TIME_ELAPSED);
-       glEndPerfMonitorAMD (metrics->monitor_begun_id);
+
+       if (metrics->info->have_perfmon)
+               glEndPerfMonitorAMD (metrics->monitor_begun_id);
 
        /* Add these IDs to our lists of outstanding queries and
         * monitors so the results can be collected later. */
@@ -295,19 +352,21 @@ metrics_counter_stop (void)
                metrics->timer_head = timer;
        }
 
-       /* Create a new performance-monitor query */
-       monitor = xmalloc (sizeof (monitor_t));
+       if (metrics->info->have_perfmon) {
+               /* Create a new performance-monitor query */
+               monitor = xmalloc (sizeof (monitor_t));
 
-       monitor->op = metrics->op;
-       monitor->id = metrics->monitor_begun_id;
-       monitor->next = NULL;
+               monitor->op = metrics->op;
+               monitor->id = metrics->monitor_begun_id;
+               monitor->next = NULL;
 
-       if (metrics->monitor_tail) {
-               metrics->monitor_tail->next = monitor;
-               metrics->monitor_tail = monitor;
-       } else {
-               metrics->monitor_tail = monitor;
-               metrics->monitor_head = monitor;
+               if (metrics->monitor_tail) {
+                       metrics->monitor_tail->next = monitor;
+                       metrics->monitor_tail = monitor;
+               } else {
+                       metrics->monitor_tail = monitor;
+                       metrics->monitor_head = monitor;
+               }
        }
 
        metrics->monitors_in_flight++;
@@ -318,31 +377,24 @@ metrics_counter_stop (void)
         * available by now.)
         */
        if (metrics->monitors_in_flight > MAX_MONITORS_IN_FLIGHT)
-               metrics_collect_available ();
+               metrics_collect_available (metrics);
 }
 
 void
-metrics_set_current_op (metrics_op_t op)
+metrics_set_current_op (metrics_t *metrics, metrics_op_t op)
 {
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
-
        metrics->op = op;
 }
 
 metrics_op_t
-metrics_get_current_op (void)
+metrics_get_current_op (metrics_t *metrics)
 {
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
-
        return metrics->op;
 }
 
 static void
-op_metrics_init (context_t *ctx, op_metrics_t *metrics, metrics_op_t op)
+op_metrics_init (metrics_info_t *info, op_metrics_t *metrics, metrics_op_t op)
 {
-       metrics_info_t *info = ctx->metrics->info;
        unsigned i, j;
 
        metrics->op = op;
@@ -359,9 +411,8 @@ op_metrics_init (context_t *ctx, op_metrics_t *metrics, metrics_op_t op)
 }
 
 static op_metrics_t *
-ctx_get_op_metrics (context_t *ctx, metrics_op_t op)
+_get_op_metrics (metrics_t *metrics, metrics_op_t op)
 {
-       metrics_t *metrics = ctx->metrics;
        unsigned i;
 
        if (op >= metrics->num_op_metrics)
@@ -369,7 +420,7 @@ ctx_get_op_metrics (context_t *ctx, metrics_op_t op)
                metrics->op_metrics = realloc (metrics->op_metrics,
                                               (op + 1) * sizeof (op_metrics_t));
                for (i = metrics->num_op_metrics; i < op + 1; i++)
-                       op_metrics_init (ctx, &metrics->op_metrics[i], i);
+                       op_metrics_init (metrics->info, &metrics->op_metrics[i], i);
 
                metrics->num_op_metrics = op + 1;
        }
@@ -378,21 +429,22 @@ ctx_get_op_metrics (context_t *ctx, metrics_op_t op)
 }
 
 static void
-accumulate_program_metrics (metrics_op_t op, GLuint *result, GLuint size)
+accumulate_program_metrics (metrics_t *metrics, metrics_op_t op,
+                           GLuint *result, GLuint size)
 {
 #define CONSUME(var)                                                   \
        if (p + sizeof(var) > ((unsigned char *) result) + size)        \
        {                                                               \
                fprintf (stderr, "Unexpected end-of-buffer while "      \
                         "parsing results\n");                          \
+               value = 0.0;                                            \
                break;                                                  \
        }                                                               \
        (var) = *((typeof(var) *) p);                                   \
        p += sizeof(var);
 
-       context_t *ctx = context_get_current ();
-       metrics_info_t *info = ctx->metrics->info;
-       op_metrics_t *metrics = ctx_get_op_metrics (ctx, op);
+       metrics_info_t *info = metrics->info;
+       op_metrics_t *op_metrics = _get_op_metrics (metrics, op);
        unsigned char *p = (unsigned char *) result;
 
        while (p < ((unsigned char *) result) + size)
@@ -446,19 +498,18 @@ accumulate_program_metrics (metrics_op_t op, GLuint *result, GLuint size)
                        break;
                }
 
-               metrics->counters[group_index][counter_index] += value;
+               op_metrics->counters[group_index][counter_index] += value;
        }
 }
 
 static void
-accumulate_program_time (metrics_op_t op, unsigned time_ns)
+accumulate_program_time (metrics_t *metrics, metrics_op_t op, unsigned time_ns)
 {
-       context_t *ctx = context_get_current ();
-       op_metrics_t *metrics;
+       op_metrics_t *op_metrics;
 
-       metrics = ctx_get_op_metrics (ctx, op);
+       op_metrics = _get_op_metrics (metrics, op);
 
-       metrics->time_ns += time_ns;
+       op_metrics->time_ns += time_ns;
 }
 
 typedef struct per_stage_metrics
@@ -497,30 +548,47 @@ _is_shader_stage_counter (metrics_info_t *info,
 }
 
 static void
-print_per_stage_metrics (context_t *ctx,
+print_per_stage_metrics (metrics_t *metrics,
                         per_stage_metrics_t *per_stage,
                         double total)
 {
-       metrics_info_t *info = ctx->metrics->info;
-       op_metrics_t *metric = per_stage->metrics;
+       metrics_info_t *info = metrics->info;
+       op_metrics_t *op_metrics = per_stage->metrics;
        metrics_group_info_t *group;
        const char *op_string;
        unsigned group_index, counter;
        double value;
+       int program_name_length = 0;
 
        /* Don't print anything for stages with no alloted time. */
        if (per_stage->time_ns == 0.0)
                return;
 
-       op_string = metrics_op_string (metric->op);
+       op_string = metrics_op_string (op_metrics->op);
 
-       printf ("%21s", op_string);
+       if (op_metrics->op >= METRICS_OP_SHADER) {
+               int program = op_metrics->op - METRICS_OP_SHADER;
+               glGetObjectLabel (GL_PROGRAM, program, 0,
+                                 &program_name_length, NULL);
+               if (program_name_length) {
+                       char *program_name;
 
-       if (metric->op >= METRICS_OP_SHADER) {
-               printf (" %3d", metric->op - METRICS_OP_SHADER);
-       } else {
-               printf ("    ");
+                       program_name = malloc(program_name_length + 1);
+                       if (program_name == 0) {
+                               fprintf (stderr, "Out of memory.\n");
+                               exit (1);
+                       }
+                       glGetObjectLabel (GL_PROGRAM, program,
+                                         program_name_length + 1,
+                                         NULL, program_name);
 
+                       printf ("%21s    ", program_name);
+               } else {
+                       printf ("%21s %3d", op_string, program);
+               }
+       }
+       else {
+               printf ("%21s    ", op_string);
        }
 
        if (per_stage->stage)
@@ -554,7 +622,7 @@ print_per_stage_metrics (context_t *ctx,
                        if (_is_shader_stage_counter (info, group_index, counter))
                                continue;
 
-                       value = metric->counters[group_index][counter];
+                       value = op_metrics->counters[group_index][counter];
                        if (value == 0.0)
                                continue;
                        printf ("%s: %.2f ", group->counter_names[counter],
@@ -579,10 +647,8 @@ time_compare(const void *in_a, const void *in_b, void *arg unused)
 }
 
 static void
-print_program_metrics (void)
+print_program_metrics (metrics_t *metrics)
 {
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
        metrics_info_t *info = metrics->info;
        unsigned num_shader_stages = info->num_shader_stages;
        per_stage_metrics_t *sorted, *per_stage;
@@ -591,10 +657,24 @@ print_program_metrics (void)
        unsigned group_index, counter_index;
        unsigned i, j, num_sorted;
 
+       if (! info->have_perfmon &&
+           ! info->printed_missing_perfmon_warning)
+       {
+               fprintf (stderr,
+                        "Warning: The GL_AMD_performance_monitor extensions is not available.\n"
+                        "         Some fips features, (such as per-shader-stage timings),\n"
+                        "         will not be available.\n");
+
+               info->printed_missing_perfmon_warning = true;
+       }
+
        /* Make a sorted list of the per-stage operations by time
         * used, and figure out the total so we can print percentages.
         */
-       num_sorted = metrics->num_op_metrics * num_shader_stages;
+       if (num_shader_stages)
+               num_sorted = metrics->num_op_metrics * num_shader_stages;
+       else
+               num_sorted = metrics->num_op_metrics;
 
        sorted = xmalloc (sizeof (*sorted) * num_sorted);
 
@@ -610,6 +690,14 @@ print_program_metrics (void)
                /* Also, find total cycles in all stages of this op. */
                op_cycles = 0.0;
 
+               if (num_shader_stages == 0) {
+                       per_stage = &sorted[i];
+                       per_stage->metrics = op;
+                       per_stage->stage = NULL;
+                       per_stage->time_ns = op->time_ns;
+                       per_stage->active = 0.0;
+               }
+
                for (j = 0; j < num_shader_stages; j++) {
                        /* Active cycles */
                        group_index = info->stages[j].active_group_index;
@@ -670,76 +758,14 @@ print_program_metrics (void)
                 time_compare, metrics->op_metrics);
 
        for (i = 0; i < num_sorted; i++)
-               print_per_stage_metrics (ctx, &sorted[i], total_time);
+               print_per_stage_metrics (metrics, &sorted[i], total_time);
 
        free (sorted);
 }
 
-/* Called at program exit.
- *
- * This is similar to metrics_info_fini, but only frees any used
- * memory. Notably, it does not call any OpenGL functions, (since the
- * OpenGL context no longer exists at program exit).
- */
-static void
-metrics_exit (void)
-{
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
-       metrics_info_t *info = metrics->info;
-       unsigned i, j;
-       timer_query_t *timer, *timer_next;
-       monitor_t *monitor, *monitor_next;
-
-       if (verbose)
-               printf ("fips: terminating\n");
-
-       if (! info->initialized)
-               return;
-
-       for (timer = metrics->timer_head;
-            timer;
-            timer = timer_next)
-       {
-               timer_next = timer->next;
-               free (timer);
-       }
-
-       for (monitor = metrics->monitor_head;
-            monitor;
-            monitor = monitor_next)
-       {
-               monitor_next = monitor->next;
-               free (monitor);
-       }
-
-       for (i = 0; i < info->num_groups; i++) {
-               metrics_group_info_t *group = &info->groups[i];
-
-               for (j = 0; j < group->num_counters; i++)
-                       free (group->counter_names[j]);
-
-               free (group->counter_types);
-               free (group->counter_names);
-               free (group->counter_ids);
-
-               free (group->name);
-       }
-
-       free (info->groups);
-
-       for (i = 0; i < info->num_shader_stages; i++)
-               free (info->stages[i].name);
-
-       free (info->stages);
-}
-
 void
-metrics_collect_available (void)
+metrics_collect_available (metrics_t *metrics)
 {
-       context_t *ctx = context_get_current ();
-       metrics_t *metrics = ctx->metrics;
-
        /* Consume all timer queries that are ready. */
        timer_query_t *timer = metrics->timer_head;
 
@@ -754,7 +780,7 @@ metrics_collect_available (void)
                glGetQueryObjectuiv (timer->id,
                                     GL_QUERY_RESULT, &elapsed);
 
-               accumulate_program_time (timer->op, elapsed);
+               accumulate_program_time (metrics, timer->op, elapsed);
 
                metrics->timer_head = timer->next;
                if (metrics->timer_head == NULL)
@@ -766,6 +792,9 @@ metrics_collect_available (void)
                timer = metrics->timer_head;
        }
 
+       if (! metrics->info->have_perfmon)
+               return;
+
        /* And similarly for all performance monitors that are ready. */
        monitor_t *monitor = metrics->monitor_head;
 
@@ -792,7 +821,7 @@ metrics_collect_available (void)
                                                result_size, result,
                                                &bytes_written);
 
-               accumulate_program_metrics (monitor->op, result, result_size);
+               accumulate_program_metrics (metrics, monitor->op, result, result_size);
 
                free (result);
 
@@ -810,26 +839,112 @@ metrics_collect_available (void)
        }
 }
 
+/* Subtract timespec values: Return (a - b) in seconds as a double. */
+#define SUBTRACT_TIMESPEC(a, b) (double) (a.tv_sec - b.tv_sec + \
+                                         (a.tv_nsec - b.tv_nsec) / 1e9)
 
 void
-metrics_end_frame (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
+        * 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.
+        */
+
+       glGetQueryObjectui64v (metrics->swap_end_timestamp_id,
+                              GL_QUERY_RESULT, &swap_end_timestamp);
+       if (metrics->first_frame) {
+               /* Print header */
+               printf ("# frame: Frame_Number Frame_Time_milliseconds Frame_latency_milliseconds CPU_load GPU_load\n");
+
+               metrics->first_frame = false;
+       } else {
+               /* Subtract previous frame's times to get frame times. */
+               frame_time_ns = subtract_timestamp (swap_end_timestamp,
+                                                   metrics->previous_swap_end_timestamp);
+
+               latency_ns = subtract_timestamp (swap_end_timestamp,
+                                                metrics->swap_begin_timestamp);
+
+               cpu_time = SUBTRACT_TIMESPEC (metrics->cpu_time_ts,
+                                             metrics->previous_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 %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
+        * baseline for a frame latency measurment. */
+
+       glGetInteger64v (GL_TIMESTAMP, &metrics->swap_begin_timestamp);
+}
+
+void
+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
+        * 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);
+
+       /* 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);
-               atexit (metrics_exit);
                if (getenv ("FIPS_VERBOSE"))
                        verbose = 1;
                initialized = 1;
        }
 
-       frames++;
+       metrics_collect_available (metrics);
 
-       metrics_collect_available ();
+       frames++;
 
-       if (frames % 15 == 0) {
+       if (frames) {
                double fps;
 
                gettimeofday (&tv_now, NULL);
@@ -839,6 +954,9 @@ metrics_end_frame (void)
 
                printf("FPS: %.3f\n", fps);
 
-               print_program_metrics ();
+               print_program_metrics (metrics);
        }
+
+       /* Start the counter up again now that we're done. */
+       metrics_counter_start (metrics);
 }