From 0289d15f5ac659f32b5c201aefdad92a184eed6b Mon Sep 17 00:00:00 2001 From: Carl Worth Date: Sat, 9 Nov 2013 12:23:53 -0800 Subject: [PATCH] Capture and print CPU load on a per-frame basis. We use clock_gettime to measure the amount of CPU time accrued by the active process. Then, by subtracting the value between succesive frame times and dividing by the total wall-clock time for the frame, we determine a measure of the per-frame CPU load from 0.0 to 1.0. We now print the frame number, frame time, frame latency, and CPU load in a single-line format for simpler parsing, (with a header comment describing the names and units for each field). --- metrics.c | 41 +++++++++++++++++++++++++++++++++-------- 1 file changed, 33 insertions(+), 8 deletions(-) diff --git a/metrics.c b/metrics.c index 2fe2dc7..0c61e0e 100644 --- a/metrics.c +++ b/metrics.c @@ -26,7 +26,10 @@ #include #include #include +#include #include +#include +#include #include "fips-dispatch-gl.h" @@ -105,6 +108,9 @@ struct metrics 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; }; metrics_t * @@ -787,10 +793,15 @@ 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) + 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 @@ -816,24 +827,29 @@ metrics_end_frame_pre_swap (metrics_t *metrics) glGetQueryObjectui64v (metrics->swap_end_timestamp_id, GL_QUERY_RESULT, &swap_end_timestamp); - if (frames > 0) { - /* Subtract previous frame's timestamp to get frame time. */ + if (frames == 0) { + /* Print header */ + printf ("# frame: Frame_Number Frame_Time_milliseconds Frame_latency_milliseconds CPU_load\n"); + } else { + /* Subtract previous frame's times to get frame times. */ frame_time_ns = swap_end_timestamp - metrics->previous_swap_end_timestamp; latency_ns = swap_end_timestamp - metrics->swap_begin_timestamp; + cpu_time = TIMESPEC_DIFF (metrics->previous_cpu_time_ts, metrics->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-time: %d %" PRId64 "\n", - frames - 1, frame_time_ns); - - printf ("frame-latency: %d %" PRId64 "\n", - frames - 1, latency_ns); - + printf ("frame: %d %g %g %g\n", + frames - 1, + (double) frame_time_ns / 1e6, + (double) latency_ns / 1e6, + cpu_time / (frame_time_ns / 1e9)); } 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 @@ -847,6 +863,7 @@ 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 @@ -856,6 +873,14 @@ metrics_end_frame_post_swap (metrics_t *metrics) 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); if (getenv ("FIPS_VERBOSE")) -- 2.43.0