]> git.cworth.org Git - fips/blob - metrics.c
Add explicit link to libpthread, to work around debugging issues
[fips] / metrics.c
1 /* Copyright © 2013, Intel Corporation
2  *
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:
9  *
10  * The above copyright notice and this permission notice shall be included in
11  * all copies or substantial portions of the Software.
12  *
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
19  * THE SOFTWARE.
20  */
21
22 #define _GNU_SOURCE
23
24 #include <stdio.h>
25 #include <stdlib.h>
26 #include <assert.h>
27 #include <sys/time.h>
28
29 #include "fips-dispatch-gl.h"
30
31 #include "metrics.h"
32 #include "context.h"
33 #include "metrics-info.h"
34 #include "xmalloc.h"
35
36 int frames;
37 int verbose;
38
39 #define MAX_MONITORS_IN_FLIGHT 1000
40
41 /* Timer query */
42 typedef struct timer_query
43 {
44         unsigned id;
45
46         metrics_op_t op;
47         struct timer_query *next;
48 } timer_query_t;
49
50 /* Performance-monitor query */
51 typedef struct monitor
52 {
53         unsigned id;
54
55         metrics_op_t op;
56         struct monitor *next;
57 } monitor_t;
58
59 typedef struct op_metrics
60 {
61         /* This happens to also be the index into the
62          * metrics->op_metrics array currently
63          */
64         metrics_op_t op;
65         double time_ns;
66
67         double **counters;
68 } op_metrics_t;
69
70 struct metrics
71 {
72         /* Description of all available peformance counters, counter
73          * groups, their names and IDs, etc. */
74         metrics_info_t *info;
75
76         /* The current operation being measured. */
77         metrics_op_t op;
78
79         /* GL_TIME_ELAPSED query for which glEndQuery has not yet
80          * been called. */
81         unsigned timer_begun_id;
82
83         /* GL_TIME_ELAPSED queries for which glEndQuery has been
84          * called, (but results have not yet been queried). */
85         timer_query_t *timer_head;
86         timer_query_t *timer_tail;
87
88         /* Performance monitor for which glEndPerfMonitorAMD has not
89          * yet been called. */
90         unsigned monitor_begun_id;
91
92         /* Performance monitors for which glEndPerfMonitorAMD has
93          * been called, (but results have not yet been queried). */
94         monitor_t *monitor_head;
95         monitor_t *monitor_tail;
96
97         int monitors_in_flight;
98
99         unsigned num_op_metrics;
100         op_metrics_t *op_metrics;
101 };
102
103 metrics_t *
104 metrics_create (metrics_info_t *info)
105 {
106         metrics_t *metrics;
107
108         metrics = xmalloc (sizeof (metrics_t));
109
110         metrics->info = info;
111
112         metrics->op = 0;
113
114         metrics->timer_begun_id = 0;
115
116         metrics->timer_head = NULL;
117         metrics->timer_tail = NULL;
118
119         metrics->monitor_begun_id = 0;
120
121         metrics->monitor_head = NULL;
122         metrics->monitor_tail = NULL;
123
124         metrics->monitors_in_flight = 0;
125
126         metrics->num_op_metrics = 0;
127         metrics->op_metrics = NULL;
128
129         return metrics;
130 }
131
132 void
133 metrics_fini (metrics_t *metrics)
134 {
135         timer_query_t *timer, *timer_next;
136         monitor_t *monitor, *monitor_next;
137
138         /* Discard and cleanup any outstanding queries. */
139         if (metrics->timer_begun_id) {
140                 glEndQuery (GL_TIME_ELAPSED);
141                 glDeleteQueries (1, &metrics->timer_begun_id);
142                 metrics->timer_begun_id = 0;
143         }
144
145         for (timer = metrics->timer_head;
146              timer;
147              timer = timer_next)
148         {
149                 glDeleteQueries (1, &timer->id);
150                 timer_next = timer->next;
151                 free (timer);
152         }
153         metrics->timer_head = NULL;
154         metrics->timer_tail = NULL;
155
156         if (metrics->info->have_perfmon) {
157
158                 if (metrics->monitor_begun_id) {
159                         glEndPerfMonitorAMD (metrics->monitor_begun_id);
160                         glDeletePerfMonitorsAMD (1, &metrics->monitor_begun_id);
161                         metrics->monitor_begun_id = 0;
162                 }
163
164                 for (monitor = metrics->monitor_head;
165                      monitor;
166                      monitor = monitor_next)
167                 {
168                         glDeletePerfMonitorsAMD (1, &monitor->id);
169                         monitor_next = monitor->next;
170                         free (monitor);
171                 }
172                 metrics->monitor_head = NULL;
173                 metrics->monitor_tail = NULL;
174
175         }
176
177         metrics->monitors_in_flight = 0;
178 }
179
180 void
181 metrics_destroy (metrics_t *metrics)
182 {
183         metrics_fini (metrics);
184
185         free (metrics);
186 }
187
188 static const char *
189 metrics_op_string (metrics_op_t op)
190 {
191         if (op >= METRICS_OP_SHADER)
192                 return "Shader program";
193
194         switch (op)
195         {
196         case METRICS_OP_ACCUM:
197                 return "glAccum*(+)";
198         case METRICS_OP_BUFFER_DATA:
199                 return "glBufferData(+)";
200         case METRICS_OP_BUFFER_SUB_DATA:
201                 return "glCopyBufferSubData*";
202         case METRICS_OP_BITMAP:
203                 return "glBitmap*";
204         case METRICS_OP_BLIT_FRAMEBUFFER:
205                 return "glBlitFramebuffer*";
206         case METRICS_OP_CLEAR:
207                 return "glClear(+)";
208         case METRICS_OP_CLEAR_BUFFER_DATA:
209                 return "glCearBufferData(+)";
210         case METRICS_OP_CLEAR_TEX_IMAGE:
211                 return "glClearTexImage(+)";
212         case METRICS_OP_COPY_PIXELS:
213                 return "glCopyPixels";
214         case METRICS_OP_COPY_TEX_IMAGE:
215                 return "glCopyTexImage(+)";
216         case METRICS_OP_DRAW_PIXELS:
217                 return "glDrawPixels";
218         case METRICS_OP_GET_TEX_IMAGE:
219                 return "glGetTexImage(+)";
220         case METRICS_OP_READ_PIXELS:
221                 return "glReadPixels*";
222         case METRICS_OP_TEX_IMAGE:
223                 return "glTexImage*(+)";
224         default:
225                 fprintf (stderr, "fips: Internal error: "
226                          "Unknown metrics op value: %d\n", op);
227                 exit (1);
228         }
229
230         return "";
231 }
232
233 void
234 metrics_counter_start (metrics_t *metrics)
235 {
236         unsigned i;
237
238         /* Initialize the timer_query object. */
239         glGenQueries (1, &metrics->timer_begun_id);
240
241         /* Most everything else in this function is
242          * performance-monitor related. If we don't have that
243          * extension, just start the timer query and be done. */
244         if (! metrics->info->have_perfmon) {
245                 glBeginQuery (GL_TIME_ELAPSED, metrics->timer_begun_id);
246                 return;
247         }
248
249         /* Initialize the performance-monitor object */
250         glGenPerfMonitorsAMD (1, &metrics->monitor_begun_id);
251
252         for (i = 0; i < metrics->info->num_groups; i++)
253         {
254                 metrics_group_info_t *group;
255                 int num_counters;
256
257                 group = &metrics->info->groups[i];
258
259                 num_counters = group->num_counters;
260                 if (group->max_active_counters < group->num_counters)
261                 {
262                         fprintf (stderr, "Warning: Only monitoring %d/%d counters from group %d\n",
263                                  group->max_active_counters,
264                                  group->num_counters, i);
265                         num_counters = group->max_active_counters;
266
267                 }
268
269                 glSelectPerfMonitorCountersAMD(metrics->monitor_begun_id,
270                                                GL_TRUE, group->id,
271                                                num_counters,
272                                                group->counter_ids);
273         }
274
275         /* Start the queries */
276         glBeginQuery (GL_TIME_ELAPSED, metrics->timer_begun_id);
277
278         glBeginPerfMonitorAMD (metrics->monitor_begun_id);
279 }
280
281 void
282 metrics_counter_stop (metrics_t *metrics)
283 {
284         timer_query_t *timer;
285         monitor_t *monitor;
286
287         /* Stop the current timer and monitor. */
288         glEndQuery (GL_TIME_ELAPSED);
289
290         if (metrics->info->have_perfmon)
291                 glEndPerfMonitorAMD (metrics->monitor_begun_id);
292
293         /* Add these IDs to our lists of outstanding queries and
294          * monitors so the results can be collected later. */
295         timer = xmalloc (sizeof (timer_query_t));
296
297         timer->op = metrics->op;
298         timer->id = metrics->timer_begun_id;
299         timer->next = NULL;
300
301         if (metrics->timer_tail) {
302                 metrics->timer_tail->next = timer;
303                 metrics->timer_tail = timer;
304         } else {
305                 metrics->timer_tail = timer;
306                 metrics->timer_head = timer;
307         }
308
309         if (metrics->info->have_perfmon) {
310                 /* Create a new performance-monitor query */
311                 monitor = xmalloc (sizeof (monitor_t));
312
313                 monitor->op = metrics->op;
314                 monitor->id = metrics->monitor_begun_id;
315                 monitor->next = NULL;
316
317                 if (metrics->monitor_tail) {
318                         metrics->monitor_tail->next = monitor;
319                         metrics->monitor_tail = monitor;
320                 } else {
321                         metrics->monitor_tail = monitor;
322                         metrics->monitor_head = monitor;
323                 }
324         }
325
326         metrics->monitors_in_flight++;
327
328         /* Avoid being a resource hog and collect outstanding results
329          * once we have sent off a large number of
330          * queries. (Presumably, many of the outstanding queries are
331          * available by now.)
332          */
333         if (metrics->monitors_in_flight > MAX_MONITORS_IN_FLIGHT)
334                 metrics_collect_available (metrics);
335 }
336
337 void
338 metrics_set_current_op (metrics_t *metrics, metrics_op_t op)
339 {
340         metrics->op = op;
341 }
342
343 metrics_op_t
344 metrics_get_current_op (metrics_t *metrics)
345 {
346         return metrics->op;
347 }
348
349 static void
350 op_metrics_init (metrics_info_t *info, op_metrics_t *metrics, metrics_op_t op)
351 {
352         unsigned i, j;
353
354         metrics->op = op;
355         metrics->time_ns = 0.0;
356
357         metrics->counters = xmalloc (sizeof(double *) * info->num_groups);
358
359         for (i = 0; i < info->num_groups; i++) {
360                 metrics->counters[i] = xmalloc (sizeof (double) *
361                                                 info->groups[i].num_counters);
362                 for (j = 0; j < info->groups[i].num_counters; j++)
363                         metrics->counters[i][j] = 0.0;
364         }
365 }
366
367 static op_metrics_t *
368 _get_op_metrics (metrics_t *metrics, metrics_op_t op)
369 {
370         unsigned i;
371
372         if (op >= metrics->num_op_metrics)
373         {
374                 metrics->op_metrics = realloc (metrics->op_metrics,
375                                                (op + 1) * sizeof (op_metrics_t));
376                 for (i = metrics->num_op_metrics; i < op + 1; i++)
377                         op_metrics_init (metrics->info, &metrics->op_metrics[i], i);
378
379                 metrics->num_op_metrics = op + 1;
380         }
381
382         return &metrics->op_metrics[op];
383 }
384
385 static void
386 accumulate_program_metrics (metrics_t *metrics, metrics_op_t op,
387                             GLuint *result, GLuint size)
388 {
389 #define CONSUME(var)                                                    \
390         if (p + sizeof(var) > ((unsigned char *) result) + size)        \
391         {                                                               \
392                 fprintf (stderr, "Unexpected end-of-buffer while "      \
393                          "parsing results\n");                          \
394                 break;                                                  \
395         }                                                               \
396         (var) = *((typeof(var) *) p);                                   \
397         p += sizeof(var);
398
399         metrics_info_t *info = metrics->info;
400         op_metrics_t *op_metrics = _get_op_metrics (metrics, op);
401         unsigned char *p = (unsigned char *) result;
402
403         while (p < ((unsigned char *) result) + size)
404         {
405                 GLuint group_id, group_index;
406                 GLuint counter_id, counter_index;
407                 metrics_group_info_t *group;
408                 double value = 0.0;
409                 unsigned i;
410
411                 CONSUME (group_id);
412                 CONSUME (counter_id);
413
414                 for (i = 0; i < info->num_groups; i++) {
415                         if (info->groups[i].id == group_id)
416                                 break;
417                 }
418                 group_index = i;
419                 assert (group_index < info->num_groups);
420                 group = &info->groups[group_index];
421
422                 for (i = 0; i < group->num_counters; i++) {
423                         if (group->counter_ids[i] == counter_id)
424                                 break;
425                 }
426                 counter_index = i;
427                 assert (counter_index < group->num_counters);
428
429                 switch (group->counter_types[counter_index])
430                 {
431                         uint uint_value;
432                         uint64_t uint64_value;
433                         float float_value;
434                 case GL_UNSIGNED_INT:
435                         CONSUME (uint_value);
436                         value = uint_value;
437                         break;
438                 case GL_UNSIGNED_INT64_AMD:
439                         CONSUME (uint64_value);
440                         value = uint64_value;
441                         break;
442                 case GL_PERCENTAGE_AMD:
443                 case GL_FLOAT:
444                         CONSUME (float_value);
445                         value = float_value;
446                         break;
447                 default:
448                         fprintf (stderr, "fips: Warning: Unknown counter value type (%d)\n",
449                                  group->counter_types[counter_index]);
450                         value = 0.0;
451                         break;
452                 }
453
454                 op_metrics->counters[group_index][counter_index] += value;
455         }
456 }
457
458 static void
459 accumulate_program_time (metrics_t *metrics, metrics_op_t op, unsigned time_ns)
460 {
461         op_metrics_t *op_metrics;
462
463         op_metrics = _get_op_metrics (metrics, op);
464
465         op_metrics->time_ns += time_ns;
466 }
467
468 typedef struct per_stage_metrics
469 {
470         op_metrics_t *metrics;
471         shader_stage_info_t *stage;
472         double time_ns;
473         double active;
474 } per_stage_metrics_t;
475
476 static int
477 _is_shader_stage_counter (metrics_info_t *info,
478                           unsigned group_index,
479                           unsigned counter_index)
480 {
481         shader_stage_info_t *stage;
482         unsigned i;
483
484         for (i = 0; i < info->num_shader_stages; i++) {
485                 stage = &info->stages[i];
486
487                 if (stage->active_group_index == group_index &&
488                     stage->active_counter_index == counter_index)
489                 {
490                         return 1;
491                 }
492
493                 if (stage->stall_group_index == group_index &&
494                     stage->stall_counter_index == counter_index)
495                 {
496                         return 1;
497                 }
498         }
499
500         return 0;
501 }
502
503 static void
504 print_per_stage_metrics (metrics_t *metrics,
505                          per_stage_metrics_t *per_stage,
506                          double total)
507 {
508         metrics_info_t *info = metrics->info;
509         op_metrics_t *op_metrics = per_stage->metrics;
510         metrics_group_info_t *group;
511         const char *op_string;
512         unsigned group_index, counter;
513         double value;
514
515         /* Don't print anything for stages with no alloted time. */
516         if (per_stage->time_ns == 0.0)
517                 return;
518
519         op_string = metrics_op_string (op_metrics->op);
520
521         printf ("%21s", op_string);
522
523         if (op_metrics->op >= METRICS_OP_SHADER) {
524                 printf (" %3d", op_metrics->op - METRICS_OP_SHADER);
525         } else {
526                 printf ("    ");
527
528         }
529
530         if (per_stage->stage)
531                 printf (" %cS:", per_stage->stage->name[0]);
532         else
533                 printf ("   :");
534
535         printf ("\t%7.2f ms (%4.1f%%)",
536                 per_stage->time_ns / 1e6,
537                 per_stage->time_ns / total * 100);
538
539         if (per_stage->active)
540                 printf (", %4.1f%% active", per_stage->active * 100);
541
542         printf ("\n");
543
544         /* I'm not seeing a lot of value printing the rest of these
545          * performance counters by default yet. Use --verbose to get
546          * them for now. */
547         if (! verbose)
548                 return;
549
550         printf ("[");
551         for (group_index = 0; group_index < info->num_groups; group_index++) {
552                 group = &info->groups[group_index];
553                 for (counter = 0; counter < group->num_counters; counter++) {
554
555                         /* Don't print this counter value if it's a
556                          * per-stage cycle counter, (which we have
557                          * already accounted for). */
558                         if (_is_shader_stage_counter (info, group_index, counter))
559                                 continue;
560
561                         value = op_metrics->counters[group_index][counter];
562                         if (value == 0.0)
563                                 continue;
564                         printf ("%s: %.2f ", group->counter_names[counter],
565                                 value / 1e6);
566                 }
567         }
568         printf ("]\n");
569 }
570
571 static int
572 time_compare(const void *in_a, const void *in_b, void *arg unused)
573 {
574         const per_stage_metrics_t *a = in_a;
575         const per_stage_metrics_t *b = in_b;
576
577
578         if (a->time_ns < b->time_ns)
579                 return -1;
580         if (a->time_ns > b->time_ns)
581                 return 1;
582         return 0;
583 }
584
585 static void
586 print_program_metrics (metrics_t *metrics)
587 {
588         metrics_info_t *info = metrics->info;
589         unsigned num_shader_stages = info->num_shader_stages;
590         per_stage_metrics_t *sorted, *per_stage;
591         double total_time, op_cycles;
592         op_metrics_t *op;
593         unsigned group_index, counter_index;
594         unsigned i, j, num_sorted;
595
596         /* Make a sorted list of the per-stage operations by time
597          * used, and figure out the total so we can print percentages.
598          */
599         if (num_shader_stages)
600                 num_sorted = metrics->num_op_metrics * num_shader_stages;
601         else
602                 num_sorted = metrics->num_op_metrics;
603
604         sorted = xmalloc (sizeof (*sorted) * num_sorted);
605
606         total_time = 0.0;
607
608         for (i = 0; i < metrics->num_op_metrics; i++) {
609
610                 op = &metrics->op_metrics[i];
611
612                 /* Accumulate total time across all ops. */
613                 total_time += op->time_ns;
614
615                 /* Also, find total cycles in all stages of this op. */
616                 op_cycles = 0.0;
617
618                 if (num_shader_stages == 0) {
619                         per_stage = &sorted[i];
620                         per_stage->metrics = op;
621                         per_stage->stage = NULL;
622                         per_stage->time_ns = op->time_ns;
623                         per_stage->active = 0.0;
624                 }
625
626                 for (j = 0; j < num_shader_stages; j++) {
627                         /* Active cycles */
628                         group_index = info->stages[j].active_group_index;
629                         counter_index = info->stages[j].active_counter_index;
630                         op_cycles += op->counters[group_index][counter_index];
631
632                         /* Stall cycles */
633                         group_index = info->stages[j].stall_group_index;
634                         counter_index = info->stages[j].stall_counter_index;
635                         op_cycles += op->counters[group_index][counter_index];
636                 }
637
638                 for (j = 0; j < num_shader_stages; j++) {
639                         double active_cycles, stall_cycles, stage_cycles;
640
641                         /* Active cycles */
642                         group_index = info->stages[j].active_group_index;
643                         counter_index = info->stages[j].active_counter_index;
644                         active_cycles = op->counters[group_index][counter_index];
645
646                         /* Stall cycles */
647                         group_index = info->stages[j].stall_group_index;
648                         counter_index = info->stages[j].stall_counter_index;
649                         stall_cycles = op->counters[group_index][counter_index];
650
651                         stage_cycles = active_cycles + stall_cycles;
652
653                         per_stage = &sorted[i * num_shader_stages + j];
654                         per_stage->metrics = op;
655
656                         if (op_cycles) {
657                                 per_stage->stage = &info->stages[j];
658                                 per_stage->time_ns = op->time_ns * (stage_cycles / op_cycles);
659                         } else {
660                                 /* If we don't have any per-stage cycle counts
661                                  * for this operation, then use the first
662                                  * stage as a placeholder for all the time,
663                                  * but NULL-ify the stage info so that the
664                                  * report doesn't lie about this time being
665                                  * from any particular stage. */
666                                 per_stage->stage = NULL;
667                                 if (j == 0) {
668                                         per_stage->time_ns = op->time_ns;
669                                 } else {
670                                         per_stage->time_ns = 0.0;
671                                 }
672                         }
673
674                         if (stage_cycles) {
675                                 per_stage->active = active_cycles / stage_cycles;
676                         } else {
677                                 per_stage->active = 0.0;
678                         }
679                 }
680         }
681
682         qsort_r (sorted, num_sorted, sizeof (*sorted),
683                  time_compare, metrics->op_metrics);
684
685         for (i = 0; i < num_sorted; i++)
686                 print_per_stage_metrics (metrics, &sorted[i], total_time);
687
688         free (sorted);
689 }
690
691 void
692 metrics_collect_available (metrics_t *metrics)
693 {
694         /* Consume all timer queries that are ready. */
695         timer_query_t *timer = metrics->timer_head;
696
697         while (timer) {
698                 GLuint available, elapsed;
699
700                 glGetQueryObjectuiv (timer->id,
701                                      GL_QUERY_RESULT_AVAILABLE, &available);
702                 if (! available)
703                         break;
704
705                 glGetQueryObjectuiv (timer->id,
706                                      GL_QUERY_RESULT, &elapsed);
707
708                 accumulate_program_time (metrics, timer->op, elapsed);
709
710                 metrics->timer_head = timer->next;
711                 if (metrics->timer_head == NULL)
712                         metrics->timer_tail = NULL;
713
714                 glDeleteQueries (1, &timer->id);
715
716                 free (timer);
717                 timer = metrics->timer_head;
718         }
719
720         if (! metrics->info->have_perfmon)
721                 return;
722
723         /* And similarly for all performance monitors that are ready. */
724         monitor_t *monitor = metrics->monitor_head;
725
726         while (monitor) {
727                 GLuint available, result_size, *result;
728                 GLint bytes_written;
729
730                 glGetPerfMonitorCounterDataAMD (monitor->id,
731                                                 GL_PERFMON_RESULT_AVAILABLE_AMD,
732                                                 sizeof (available), &available,
733                                                 NULL);
734                 if (! available)
735                         break;
736
737                 glGetPerfMonitorCounterDataAMD (monitor->id,
738                                                 GL_PERFMON_RESULT_SIZE_AMD,
739                                                 sizeof (result_size),
740                                                 &result_size, NULL);
741
742                 result = xmalloc (result_size);
743
744                 glGetPerfMonitorCounterDataAMD (monitor->id,
745                                                 GL_PERFMON_RESULT_AMD,
746                                                 result_size, result,
747                                                 &bytes_written);
748
749                 accumulate_program_metrics (metrics, monitor->op, result, result_size);
750
751                 free (result);
752
753                 metrics->monitor_head = monitor->next;
754                 if (metrics->monitor_head == NULL)
755                         metrics->monitor_tail = NULL;
756
757                 glDeletePerfMonitorsAMD (1, &monitor->id);
758
759                 free (monitor);
760
761                 metrics->monitors_in_flight--;
762
763                 monitor = metrics->monitor_head;
764         }
765 }
766
767 static void
768 metrics_exit (void)
769 {
770         if (verbose)
771                 printf ("fips: terminating\n");
772 }
773
774 void
775 metrics_end_frame (metrics_t *metrics)
776 {
777         static int initialized = 0;
778         static struct timeval tv_start, tv_now;
779
780         if (! initialized) {
781                 gettimeofday (&tv_start, NULL);
782                 atexit (metrics_exit);
783                 if (getenv ("FIPS_VERBOSE"))
784                         verbose = 1;
785                 initialized = 1;
786         }
787
788         frames++;
789
790         metrics_collect_available (metrics);
791
792         if (frames % 15 == 0) {
793                 double fps;
794
795                 gettimeofday (&tv_now, NULL);
796
797                 fps = (double) frames / (tv_now.tv_sec - tv_start.tv_sec +
798                                          (tv_now.tv_usec - tv_start.tv_usec) / 1.0e6);
799
800                 printf("FPS: %.3f\n", fps);
801
802                 print_program_metrics (metrics);
803         }
804 }