The open source OpenXR runtime
comp: Add basic frame timing information to trace log
+40
-3
+40
-3
src/xrt/compositor/main/comp_compositor.c
+40
-3
src/xrt/compositor/main/comp_compositor.c
···
63
63
64
64
#define WINDOW_TITLE "Monado"
65
65
66
+
static double
67
+
ns_to_ms(int64_t ns)
68
+
{
69
+
double ms = ((double)ns) * 1. / 1000. * 1. / 1000.;
70
+
return ms;
71
+
}
72
+
73
+
static double
74
+
ts_ms()
75
+
{
76
+
int64_t monotonic = os_monotonic_get_ns();
77
+
return ns_to_ms(monotonic);
78
+
}
79
+
66
80
/*!
67
81
*/
68
82
static void
···
196
210
uint64_t *predicted_display_period)
197
211
{
198
212
struct comp_compositor *c = comp_compositor(xc);
199
-
COMP_SPEW(c, "WAIT_FRAME");
200
213
201
214
// A little bit easier to read.
202
215
int64_t interval_ns = (int64_t)c->settings.nominal_frame_interval_ns;
203
216
204
217
int64_t now_ns = os_monotonic_get_ns();
218
+
219
+
COMP_SPEW(c, "WAIT_FRAME at %8.3fms", ns_to_ms(now_ns));
220
+
205
221
if (c->last_next_display_time == 0) {
206
222
// First frame, we'll just assume we will display immediately
207
223
···
210
226
*predicted_display_time = c->last_next_display_time;
211
227
*out_frame_id = c->last_next_display_time;
212
228
229
+
COMP_SPEW(c,
230
+
"WAIT_FRAME Finished at %8.3fms, predicted display "
231
+
"time %8.3fms, period %8.3fms",
232
+
ns_to_ms(now_ns), ns_to_ms(*predicted_display_time),
233
+
ns_to_ms(*predicted_display_period));
234
+
213
235
return XRT_SUCCESS;
214
236
}
215
237
···
243
265
244
266
c->last_next_display_time = next_display_time;
245
267
268
+
COMP_SPEW(c,
269
+
"WAIT_FRAME Finished at %8.3fms, predicted "
270
+
"display time %8.3fms, period %8.3fms",
271
+
ns_to_ms(now_ns),
272
+
ns_to_ms(*predicted_display_time),
273
+
ns_to_ms(*predicted_display_period));
274
+
246
275
return XRT_SUCCESS;
247
276
}
248
277
}
···
261
290
compositor_discard_frame(struct xrt_compositor *xc, int64_t frame_id)
262
291
{
263
292
struct comp_compositor *c = comp_compositor(xc);
264
-
COMP_SPEW(c, "DISCARD_FRAME");
293
+
COMP_SPEW(c, "DISCARD_FRAME at %8.3fms", ts_ms());
265
294
return XRT_SUCCESS;
266
295
}
267
296
···
429
458
{
430
459
struct comp_compositor *c = comp_compositor(xc);
431
460
432
-
COMP_SPEW(c, "LAYER_COMMIT");
461
+
COMP_SPEW(c, "LAYER_COMMIT at %8.3fms", ts_ms());
433
462
434
463
// Always zero for now.
435
464
uint32_t slot_id = 0;
···
441
470
for (uint32_t i = 0; i < num_layers; i++) {
442
471
struct comp_layer *layer = &c->slots[slot_id].layers[i];
443
472
struct xrt_layer_data *data = &layer->data;
473
+
474
+
COMP_SPEW(c,
475
+
"LAYER_COMMIT (%d) predicted display time: %8.3fms",
476
+
i, ns_to_ms(data->timestamp));
477
+
444
478
switch (data->type) {
445
479
case XRT_LAYER_QUAD: {
446
480
struct xrt_layer_quad_data *quad = &layer->data.quad;
···
507
541
//! @todo do a time-weighted average or something.
508
542
c->expected_app_duration_ns =
509
543
c->app_profiling.last_end - c->app_profiling.last_begin;
544
+
545
+
COMP_SPEW(c, "LAYER_COMMIT finished drawing at %8.3fms",
546
+
ns_to_ms(c->last_frame_time_ns));
510
547
511
548
// Now is a good point to garbage collect.
512
549
comp_compositor_garbage_collect(c);