Don't print a frame-time report for the first frame after glXMakeCurrent

[fips] / metrics.c

diff --git a/metrics.c b/metrics.c
index 0c61e0ebab1620e715b4dad64c825c86452dade5..8f961331707569e0759bb635e3826af94bb1697a 100644 (file)
--- a/metrics.c
+++ b/metrics.c
@@ -74,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;
@@ -113,6 +116,28 @@ struct metrics
        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)
 {
@@ -122,6 +147,8 @@ metrics_create (metrics_info_t *info)
 
        metrics->info = info;
 
+       metrics->first_frame = true;
+
        metrics->op = 0;
 
        metrics->timer_begun_id = 0;
@@ -144,6 +171,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;
 }
 
@@ -409,6 +439,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);                                   \
@@ -793,9 +824,9 @@ 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)
+/* 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_pre_swap (metrics_t *metrics)
@@ -826,26 +857,32 @@ metrics_end_frame_pre_swap (metrics_t *metrics)
 
        glGetQueryObjectui64v (metrics->swap_end_timestamp_id,
                               GL_QUERY_RESULT, &swap_end_timestamp);
-
-       if (frames == 0) {
+ 
+       if (metrics->first_frame) {
                /* Print header */
-               printf ("# frame: Frame_Number Frame_Time_milliseconds Frame_latency_milliseconds CPU_load\n");
+               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 = swap_end_timestamp - metrics->previous_swap_end_timestamp;
+               frame_time_ns = subtract_timestamp (swap_end_timestamp,
+                                                   metrics->previous_swap_end_timestamp);
 
-               latency_ns = swap_end_timestamp - metrics->swap_begin_timestamp;
+               latency_ns = subtract_timestamp (swap_end_timestamp,
+                                                metrics->swap_begin_timestamp);
 
-               cpu_time = TIMESPEC_DIFF (metrics->previous_cpu_time_ts, metrics->cpu_time_ts);
+               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\n",
+               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));
+                       cpu_time / (frame_time_ns / 1e9),
+                       0.0);
        }
 
        metrics->previous_swap_end_timestamp = swap_end_timestamp;