1 /* Copyright © 2013, Intel Corporation
3 * Permission is hereby granted, free of charge, to any person obtaining a copy
4 * of this software and associated documentation files (the "Software"), to deal
5 * in the Software without restriction, including without limitation the rights
6 * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
7 * copies of the Software, and to permit persons to whom the Software is
8 * furnished to do so, subject to the following conditions:
10 * The above copyright notice and this permission notice shall be included in
11 * all copies or substantial portions of the Software.
13 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
14 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
15 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
16 * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
17 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
18 * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
34 #include "fips-dispatch-gl.h"
38 #include "metrics-info.h"
44 #define MAX_MONITORS_IN_FLIGHT 1000
47 typedef struct timer_query
52 struct timer_query *next;
55 /* Performance-monitor query */
56 typedef struct monitor
64 typedef struct op_metrics
66 /* This happens to also be the index into the
67 * metrics->op_metrics array currently
77 /* Flag to indicate first frame is being processed. */
80 /* Description of all available peformance counters, counter
81 * groups, their names and IDs, etc. */
84 /* The current operation being measured. */
87 /* GL_TIME_ELAPSED query for which glEndQuery has not yet
89 unsigned timer_begun_id;
91 /* GL_TIME_ELAPSED queries for which glEndQuery has been
92 * called, (but results have not yet been queried). */
93 timer_query_t *timer_head;
94 timer_query_t *timer_tail;
96 /* Performance monitor for which glEndPerfMonitorAMD has not
98 unsigned monitor_begun_id;
100 /* Performance monitors for which glEndPerfMonitorAMD has
101 * been called, (but results have not yet been queried). */
102 monitor_t *monitor_head;
103 monitor_t *monitor_tail;
105 int monitors_in_flight;
107 unsigned num_op_metrics;
108 op_metrics_t *op_metrics;
110 /* Per-frame time and latency measurement. */
111 GLint64 swap_begin_timestamp;
112 unsigned swap_end_timestamp_id;
113 GLint64 previous_swap_end_timestamp;
115 struct timespec previous_cpu_time_ts;
116 struct timespec cpu_time_ts;
119 /* Return (a - b) while accounting for the fact that between a and b,
120 * the counter may have wrapped around (with a maximum number of bits
121 * in the counter of GL_QUERY_COUNTER_BITS). */
123 subtract_timestamp (uint64_t a, uint64_t b)
125 GLint timestamp_bits;
127 glGetQueryiv (GL_TIMESTAMP, GL_QUERY_COUNTER_BITS, ×tamp_bits);
129 /* Note: "<<" isn't defined for the number of bits in the
130 * type, and the compiler will punish you.
132 if (timestamp_bits == 64)
136 return (1ull << timestamp_bits) + a - b;
142 metrics_create (metrics_info_t *info)
146 metrics = xmalloc (sizeof (metrics_t));
148 metrics->info = info;
150 metrics->first_frame = true;
154 metrics->timer_begun_id = 0;
156 metrics->timer_head = NULL;
157 metrics->timer_tail = NULL;
159 metrics->monitor_begun_id = 0;
161 metrics->monitor_head = NULL;
162 metrics->monitor_tail = NULL;
164 metrics->monitors_in_flight = 0;
166 metrics->num_op_metrics = 0;
167 metrics->op_metrics = NULL;
169 glGenQueries (1, &metrics->swap_end_timestamp_id);
171 /* Get the first frame timestamp started immediately. */
172 glQueryCounter (metrics->swap_end_timestamp_id, GL_TIMESTAMP);
174 /* As well as the initial CPU time. */
175 clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &metrics->cpu_time_ts);
181 metrics_fini (metrics_t *metrics)
183 timer_query_t *timer, *timer_next;
184 monitor_t *monitor, *monitor_next;
186 /* Discard and cleanup any outstanding queries. */
187 if (metrics->timer_begun_id) {
188 glDeleteQueries (1, &metrics->timer_begun_id);
189 metrics->timer_begun_id = 0;
192 for (timer = metrics->timer_head;
196 glDeleteQueries (1, &timer->id);
197 timer_next = timer->next;
200 metrics->timer_head = NULL;
201 metrics->timer_tail = NULL;
203 if (metrics->info->have_perfmon) {
205 if (metrics->monitor_begun_id) {
206 glDeletePerfMonitorsAMD (1, &metrics->monitor_begun_id);
207 metrics->monitor_begun_id = 0;
210 for (monitor = metrics->monitor_head;
212 monitor = monitor_next)
214 glDeletePerfMonitorsAMD (1, &monitor->id);
215 monitor_next = monitor->next;
218 metrics->monitor_head = NULL;
219 metrics->monitor_tail = NULL;
223 metrics->monitors_in_flight = 0;
227 metrics_destroy (metrics_t *metrics)
229 metrics_fini (metrics);
235 metrics_op_string (metrics_op_t op)
237 if (op >= METRICS_OP_SHADER)
238 return "Shader program";
242 case METRICS_OP_ACCUM:
243 return "glAccum*(+)";
244 case METRICS_OP_BUFFER_DATA:
245 return "glBufferData(+)";
246 case METRICS_OP_BUFFER_SUB_DATA:
247 return "glCopyBufferSubData*";
248 case METRICS_OP_BITMAP:
250 case METRICS_OP_BLIT_FRAMEBUFFER:
251 return "glBlitFramebuffer*";
252 case METRICS_OP_CLEAR:
254 case METRICS_OP_CLEAR_BUFFER_DATA:
255 return "glCearBufferData(+)";
256 case METRICS_OP_CLEAR_TEX_IMAGE:
257 return "glClearTexImage(+)";
258 case METRICS_OP_COPY_PIXELS:
259 return "glCopyPixels";
260 case METRICS_OP_COPY_TEX_IMAGE:
261 return "glCopyTexImage(+)";
262 case METRICS_OP_DRAW_PIXELS:
263 return "glDrawPixels";
264 case METRICS_OP_GET_TEX_IMAGE:
265 return "glGetTexImage(+)";
266 case METRICS_OP_READ_PIXELS:
267 return "glReadPixels*";
268 case METRICS_OP_TEX_IMAGE:
269 return "glTexImage*(+)";
271 fprintf (stderr, "fips: Internal error: "
272 "Unknown metrics op value: %d\n", op);
280 metrics_counter_start (metrics_t *metrics)
284 /* Initialize the timer_query object. */
285 glGenQueries (1, &metrics->timer_begun_id);
287 /* Most everything else in this function is
288 * performance-monitor related. If we don't have that
289 * extension, just start the timer query and be done. */
290 if (! metrics->info->have_perfmon) {
291 glBeginQuery (GL_TIME_ELAPSED, metrics->timer_begun_id);
295 /* Initialize the performance-monitor object */
296 glGenPerfMonitorsAMD (1, &metrics->monitor_begun_id);
298 for (i = 0; i < metrics->info->num_groups; i++)
300 metrics_group_info_t *group;
303 group = &metrics->info->groups[i];
305 num_counters = group->num_counters;
306 if (group->max_active_counters < group->num_counters)
308 fprintf (stderr, "Warning: Only monitoring %d/%d counters from group %d\n",
309 group->max_active_counters,
310 group->num_counters, i);
311 num_counters = group->max_active_counters;
315 glSelectPerfMonitorCountersAMD(metrics->monitor_begun_id,
321 /* Start the queries */
322 glBeginQuery (GL_TIME_ELAPSED, metrics->timer_begun_id);
324 glBeginPerfMonitorAMD (metrics->monitor_begun_id);
328 metrics_counter_stop (metrics_t *metrics)
330 timer_query_t *timer;
333 /* Stop the current timer and monitor. */
334 glEndQuery (GL_TIME_ELAPSED);
336 if (metrics->info->have_perfmon)
337 glEndPerfMonitorAMD (metrics->monitor_begun_id);
339 /* Add these IDs to our lists of outstanding queries and
340 * monitors so the results can be collected later. */
341 timer = xmalloc (sizeof (timer_query_t));
343 timer->op = metrics->op;
344 timer->id = metrics->timer_begun_id;
347 if (metrics->timer_tail) {
348 metrics->timer_tail->next = timer;
349 metrics->timer_tail = timer;
351 metrics->timer_tail = timer;
352 metrics->timer_head = timer;
355 if (metrics->info->have_perfmon) {
356 /* Create a new performance-monitor query */
357 monitor = xmalloc (sizeof (monitor_t));
359 monitor->op = metrics->op;
360 monitor->id = metrics->monitor_begun_id;
361 monitor->next = NULL;
363 if (metrics->monitor_tail) {
364 metrics->monitor_tail->next = monitor;
365 metrics->monitor_tail = monitor;
367 metrics->monitor_tail = monitor;
368 metrics->monitor_head = monitor;
372 metrics->monitors_in_flight++;
374 /* Avoid being a resource hog and collect outstanding results
375 * once we have sent off a large number of
376 * queries. (Presumably, many of the outstanding queries are
379 if (metrics->monitors_in_flight > MAX_MONITORS_IN_FLIGHT)
380 metrics_collect_available (metrics);
384 metrics_set_current_op (metrics_t *metrics, metrics_op_t op)
390 metrics_get_current_op (metrics_t *metrics)
396 op_metrics_init (metrics_info_t *info, op_metrics_t *metrics, metrics_op_t op)
401 metrics->time_ns = 0.0;
403 metrics->counters = xmalloc (sizeof(double *) * info->num_groups);
405 for (i = 0; i < info->num_groups; i++) {
406 metrics->counters[i] = xmalloc (sizeof (double) *
407 info->groups[i].num_counters);
408 for (j = 0; j < info->groups[i].num_counters; j++)
409 metrics->counters[i][j] = 0.0;
413 static op_metrics_t *
414 _get_op_metrics (metrics_t *metrics, metrics_op_t op)
418 if (op >= metrics->num_op_metrics)
420 metrics->op_metrics = realloc (metrics->op_metrics,
421 (op + 1) * sizeof (op_metrics_t));
422 for (i = metrics->num_op_metrics; i < op + 1; i++)
423 op_metrics_init (metrics->info, &metrics->op_metrics[i], i);
425 metrics->num_op_metrics = op + 1;
428 return &metrics->op_metrics[op];
432 accumulate_program_metrics (metrics_t *metrics, metrics_op_t op,
433 GLuint *result, GLuint size)
435 #define CONSUME(var) \
436 if (p + sizeof(var) > ((unsigned char *) result) + size) \
438 fprintf (stderr, "Unexpected end-of-buffer while " \
439 "parsing results\n"); \
443 (var) = *((typeof(var) *) p); \
446 metrics_info_t *info = metrics->info;
447 op_metrics_t *op_metrics = _get_op_metrics (metrics, op);
448 unsigned char *p = (unsigned char *) result;
450 while (p < ((unsigned char *) result) + size)
452 GLuint group_id, group_index;
453 GLuint counter_id, counter_index;
454 metrics_group_info_t *group;
459 CONSUME (counter_id);
461 for (i = 0; i < info->num_groups; i++) {
462 if (info->groups[i].id == group_id)
466 assert (group_index < info->num_groups);
467 group = &info->groups[group_index];
469 for (i = 0; i < group->num_counters; i++) {
470 if (group->counter_ids[i] == counter_id)
474 assert (counter_index < group->num_counters);
476 switch (group->counter_types[counter_index])
479 uint64_t uint64_value;
481 case GL_UNSIGNED_INT:
482 CONSUME (uint_value);
485 case GL_UNSIGNED_INT64_AMD:
486 CONSUME (uint64_value);
487 value = uint64_value;
489 case GL_PERCENTAGE_AMD:
491 CONSUME (float_value);
495 fprintf (stderr, "fips: Warning: Unknown counter value type (%d)\n",
496 group->counter_types[counter_index]);
501 op_metrics->counters[group_index][counter_index] += value;
506 accumulate_program_time (metrics_t *metrics, metrics_op_t op, unsigned time_ns)
508 op_metrics_t *op_metrics;
510 op_metrics = _get_op_metrics (metrics, op);
512 op_metrics->time_ns += time_ns;
515 typedef struct per_stage_metrics
517 op_metrics_t *metrics;
518 shader_stage_info_t *stage;
521 } per_stage_metrics_t;
524 _is_shader_stage_counter (metrics_info_t *info,
525 unsigned group_index,
526 unsigned counter_index)
528 shader_stage_info_t *stage;
531 for (i = 0; i < info->num_shader_stages; i++) {
532 stage = &info->stages[i];
534 if (stage->active_group_index == group_index &&
535 stage->active_counter_index == counter_index)
540 if (stage->stall_group_index == group_index &&
541 stage->stall_counter_index == counter_index)
551 print_per_stage_metrics (metrics_t *metrics,
552 per_stage_metrics_t *per_stage,
555 metrics_info_t *info = metrics->info;
556 op_metrics_t *op_metrics = per_stage->metrics;
557 metrics_group_info_t *group;
558 const char *op_string;
559 unsigned group_index, counter;
561 int program_name_length = 0;
563 /* Don't print anything for stages with no alloted time. */
564 if (per_stage->time_ns == 0.0)
567 op_string = metrics_op_string (op_metrics->op);
569 if (op_metrics->op >= METRICS_OP_SHADER) {
570 int program = op_metrics->op - METRICS_OP_SHADER;
571 glGetObjectLabel (GL_PROGRAM, program, 0,
572 &program_name_length, NULL);
573 if (program_name_length) {
576 program_name = malloc(program_name_length + 1);
577 if (program_name == 0) {
578 fprintf (stderr, "Out of memory.\n");
581 glGetObjectLabel (GL_PROGRAM, program,
582 program_name_length + 1,
585 printf ("%21s ", program_name);
587 printf ("%21s %3d", op_string, program);
591 printf ("%21s ", op_string);
594 if (per_stage->stage)
595 printf (" %cS:", per_stage->stage->name[0]);
599 printf ("\t%7.2f ms (%4.1f%%)",
600 per_stage->time_ns / 1e6,
601 per_stage->time_ns / total * 100);
603 if (per_stage->active)
604 printf (", %4.1f%% active", per_stage->active * 100);
608 /* I'm not seeing a lot of value printing the rest of these
609 * performance counters by default yet. Use --verbose to get
615 for (group_index = 0; group_index < info->num_groups; group_index++) {
616 group = &info->groups[group_index];
617 for (counter = 0; counter < group->num_counters; counter++) {
619 /* Don't print this counter value if it's a
620 * per-stage cycle counter, (which we have
621 * already accounted for). */
622 if (_is_shader_stage_counter (info, group_index, counter))
625 value = op_metrics->counters[group_index][counter];
628 printf ("%s: %.2f ", group->counter_names[counter],
636 time_compare(const void *in_a, const void *in_b, void *arg unused)
638 const per_stage_metrics_t *a = in_a;
639 const per_stage_metrics_t *b = in_b;
642 if (a->time_ns < b->time_ns)
644 if (a->time_ns > b->time_ns)
650 print_program_metrics (metrics_t *metrics)
652 metrics_info_t *info = metrics->info;
653 unsigned num_shader_stages = info->num_shader_stages;
654 per_stage_metrics_t *sorted, *per_stage;
655 double total_time, op_cycles;
657 unsigned group_index, counter_index;
658 unsigned i, j, num_sorted;
660 if (! info->have_perfmon &&
661 ! info->printed_missing_perfmon_warning)
664 "Warning: The GL_AMD_performance_monitor extensions is not available.\n"
665 " Some fips features, (such as per-shader-stage timings),\n"
666 " will not be available.\n");
668 info->printed_missing_perfmon_warning = true;
671 /* Make a sorted list of the per-stage operations by time
672 * used, and figure out the total so we can print percentages.
674 if (num_shader_stages)
675 num_sorted = metrics->num_op_metrics * num_shader_stages;
677 num_sorted = metrics->num_op_metrics;
679 sorted = xmalloc (sizeof (*sorted) * num_sorted);
683 for (i = 0; i < metrics->num_op_metrics; i++) {
685 op = &metrics->op_metrics[i];
687 /* Accumulate total time across all ops. */
688 total_time += op->time_ns;
690 /* Also, find total cycles in all stages of this op. */
693 if (num_shader_stages == 0) {
694 per_stage = &sorted[i];
695 per_stage->metrics = op;
696 per_stage->stage = NULL;
697 per_stage->time_ns = op->time_ns;
698 per_stage->active = 0.0;
701 for (j = 0; j < num_shader_stages; j++) {
703 group_index = info->stages[j].active_group_index;
704 counter_index = info->stages[j].active_counter_index;
705 op_cycles += op->counters[group_index][counter_index];
708 group_index = info->stages[j].stall_group_index;
709 counter_index = info->stages[j].stall_counter_index;
710 op_cycles += op->counters[group_index][counter_index];
713 for (j = 0; j < num_shader_stages; j++) {
714 double active_cycles, stall_cycles, stage_cycles;
717 group_index = info->stages[j].active_group_index;
718 counter_index = info->stages[j].active_counter_index;
719 active_cycles = op->counters[group_index][counter_index];
722 group_index = info->stages[j].stall_group_index;
723 counter_index = info->stages[j].stall_counter_index;
724 stall_cycles = op->counters[group_index][counter_index];
726 stage_cycles = active_cycles + stall_cycles;
728 per_stage = &sorted[i * num_shader_stages + j];
729 per_stage->metrics = op;
732 per_stage->stage = &info->stages[j];
733 per_stage->time_ns = op->time_ns * (stage_cycles / op_cycles);
735 /* If we don't have any per-stage cycle counts
736 * for this operation, then use the first
737 * stage as a placeholder for all the time,
738 * but NULL-ify the stage info so that the
739 * report doesn't lie about this time being
740 * from any particular stage. */
741 per_stage->stage = NULL;
743 per_stage->time_ns = op->time_ns;
745 per_stage->time_ns = 0.0;
750 per_stage->active = active_cycles / stage_cycles;
752 per_stage->active = 0.0;
757 qsort_r (sorted, num_sorted, sizeof (*sorted),
758 time_compare, metrics->op_metrics);
760 for (i = 0; i < num_sorted; i++)
761 print_per_stage_metrics (metrics, &sorted[i], total_time);
767 metrics_collect_available (metrics_t *metrics)
769 /* Consume all timer queries that are ready. */
770 timer_query_t *timer = metrics->timer_head;
773 GLuint available, elapsed;
775 glGetQueryObjectuiv (timer->id,
776 GL_QUERY_RESULT_AVAILABLE, &available);
780 glGetQueryObjectuiv (timer->id,
781 GL_QUERY_RESULT, &elapsed);
783 accumulate_program_time (metrics, timer->op, elapsed);
785 metrics->timer_head = timer->next;
786 if (metrics->timer_head == NULL)
787 metrics->timer_tail = NULL;
789 glDeleteQueries (1, &timer->id);
792 timer = metrics->timer_head;
795 if (! metrics->info->have_perfmon)
798 /* And similarly for all performance monitors that are ready. */
799 monitor_t *monitor = metrics->monitor_head;
802 GLuint available, result_size, *result;
805 glGetPerfMonitorCounterDataAMD (monitor->id,
806 GL_PERFMON_RESULT_AVAILABLE_AMD,
807 sizeof (available), &available,
812 glGetPerfMonitorCounterDataAMD (monitor->id,
813 GL_PERFMON_RESULT_SIZE_AMD,
814 sizeof (result_size),
817 result = xmalloc (result_size);
819 glGetPerfMonitorCounterDataAMD (monitor->id,
820 GL_PERFMON_RESULT_AMD,
824 accumulate_program_metrics (metrics, monitor->op, result, result_size);
828 metrics->monitor_head = monitor->next;
829 if (metrics->monitor_head == NULL)
830 metrics->monitor_tail = NULL;
832 glDeletePerfMonitorsAMD (1, &monitor->id);
836 metrics->monitors_in_flight--;
838 monitor = metrics->monitor_head;
842 /* Subtract timespec values: Return (a - b) in seconds as a double. */
843 #define SUBTRACT_TIMESPEC(a, b) (double) (a.tv_sec - b.tv_sec + \
844 (a.tv_nsec - b.tv_nsec) / 1e9)
847 metrics_end_frame_pre_swap (metrics_t *metrics)
849 GLuint64 swap_end_timestamp, frame_time_ns, latency_ns;
852 /* Don't leave any counters running over the end_frame work we
853 * do here. The counters will be started again at the end of
854 * metrics_end_frame_post_swap. */
856 metrics_counter_stop (metrics);
858 /* Now that an entire frame's worth of content has gone by, we
859 * can be sure that the timer quiery for the previous frame's
862 * Note: The only case in which this query isn't immediately
863 * available would be if there was effectively nothing in this
864 * frame. In that case, triggering a block on this query
865 * result is not a concern (since an empty frame is not
866 * interesting, and all of our counters are stopped anyway).
868 * Accepting this one block is much better than adding a
869 * linked list for these results that would reaslisticly never
870 * have more than one entry anyway.
873 glGetQueryObjectui64v (metrics->swap_end_timestamp_id,
874 GL_QUERY_RESULT, &swap_end_timestamp);
876 if (metrics->first_frame) {
878 printf ("# frame: Frame_Number Frame_Time_milliseconds Frame_latency_milliseconds CPU_load GPU_load\n");
880 metrics->first_frame = false;
882 /* Subtract previous frame's times to get frame times. */
883 frame_time_ns = subtract_timestamp (swap_end_timestamp,
884 metrics->previous_swap_end_timestamp);
886 latency_ns = subtract_timestamp (swap_end_timestamp,
887 metrics->swap_begin_timestamp);
889 cpu_time = SUBTRACT_TIMESPEC (metrics->cpu_time_ts,
890 metrics->previous_cpu_time_ts);
892 /* We've waited one frame to ensure we have a timestamp
893 * result. So the time we've actually measured here is
894 * for the previous frame. */
895 printf ("frame: %d %g %g %g %g\n",
897 (double) frame_time_ns / 1e6,
898 (double) latency_ns / 1e6,
899 cpu_time / (frame_time_ns / 1e9),
903 metrics->previous_swap_end_timestamp = swap_end_timestamp;
904 metrics->previous_cpu_time_ts = metrics->cpu_time_ts;
906 /* Before the actual swap call, we get the current timestamp
907 * value. This is a synchronous get so we can use this as the
908 * baseline for a frame latency measurment. */
910 glGetInteger64v (GL_TIMESTAMP, &metrics->swap_begin_timestamp);
914 metrics_end_frame_post_swap (metrics_t *metrics)
916 static int initialized = 0;
917 static struct timeval tv_start, tv_now;
920 /* Now that the swap command has been queued, we issue an
921 * asynchronous query of the timestamp value. Comparing this
922 * to the synchronous get we just sent in
923 * metrics_end_frame_pre_swap allows us to measure the
924 * per-frame swap latency. */
926 glQueryCounter (metrics->swap_end_timestamp_id, GL_TIMESTAMP);
928 /* Query the total amount of CPU time spent by this process. */
929 err = clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &metrics->cpu_time_ts);
931 fprintf (stderr, "Failed to query CPU time with clock_gettime: %s\n",
937 gettimeofday (&tv_start, NULL);
938 if (getenv ("FIPS_VERBOSE"))
943 metrics_collect_available (metrics);
950 gettimeofday (&tv_now, NULL);
952 fps = (double) frames / (tv_now.tv_sec - tv_start.tv_sec +
953 (tv_now.tv_usec - tv_start.tv_usec) / 1.0e6);
955 printf("FPS: %.3f\n", fps);
957 print_program_metrics (metrics);
960 /* Start the counter up again now that we're done. */
961 metrics_counter_start (metrics);