From 79de3ddc1564d414a49e5d179fb3bf5577955e8e Mon Sep 17 00:00:00 2001 From: Chris Wilson Date: Thu, 19 May 2016 11:46:00 +0100 Subject: igt/kms_flip: Print more information to debug for flip timing checks We have a cantiga that doesn't pass igt@kms_flip@basic-flip-vs-wf_vblank, and so knowing why is off the upmost priority! Before the assertions print the values we are about to test in greater detail. References: https://bugs.freedesktop.org/show_bug.cgi?id=98352 Signed-off-by: Chris Wilson --- tests/kms_flip.c | 46 ++++++++++++++++++++++++---------------------- 1 file changed, 24 insertions(+), 22 deletions(-) (limited to 'tests/kms_flip.c') diff --git a/tests/kms_flip.c b/tests/kms_flip.c index 7646aafb..b30e07c9 100644 --- a/tests/kms_flip.c +++ b/tests/kms_flip.c @@ -686,24 +686,23 @@ static void check_state(const struct test_output *o, const struct event_state *e } if ((o->flags & TEST_CHECK_TS) && (!analog_tv_connector(o))) { - double usec_interflip, usec_diff; + double elapsed, expected; timersub(&es->current_ts, &es->last_ts, &diff); - usec_diff = diff.tv_sec * USEC_PER_SEC + diff.tv_usec; + elapsed = 1e6*diff.tv_sec + diff.tv_usec; + expected = (es->current_seq - es->last_seq) * frame_time(o); - usec_interflip = (es->current_seq - es->last_seq) * frame_time(o); - igt_assert_f(fabs((usec_diff - usec_interflip) / - usec_interflip) <= 0.005, - "inconsistent %s ts/seq: last %ld.%06ld/%u, current %ld.%06ld/%u\n", - es->name, es->last_ts.tv_sec, es->last_ts.tv_usec, es->last_seq, - es->current_ts.tv_sec, es->current_ts.tv_usec, es->current_seq); + igt_debug("%s ts/seq: last %ld.%06ld/%u, current %ld.%06ld/%u: elapsed=%.1fus expected=%.1fus +- %.1fus, error %.1f%%\n", + es->name, es->last_ts.tv_sec, es->last_ts.tv_usec, es->last_seq, + es->current_ts.tv_sec, es->current_ts.tv_usec, es->current_seq, + elapsed, expected, expected * 0.005, + fabs((elapsed - expected) / expected) * 100); - usec_interflip = o->seq_step * frame_time(o); - igt_assert_f(fabs((usec_diff - usec_interflip) / - usec_interflip) <= 0.005, - "inter-%s ts jitter: %ld.%06ld, expected %.6f\n", - es->name, diff.tv_sec, diff.tv_usec, - usec_interflip / USEC_PER_SEC); + igt_assert_f(fabs((elapsed - expected) / expected) <= 0.005, + "inconsistent %s ts/seq: last %ld.%06ld/%u, current %ld.%06ld/%u: elapsed=%.1fus expected=%.1fus\n", + es->name, es->last_ts.tv_sec, es->last_ts.tv_usec, es->last_seq, + es->current_ts.tv_sec, es->current_ts.tv_usec, es->current_seq, + elapsed, expected); igt_assert_f(es->current_seq == es->last_seq + o->seq_step, "unexpected %s seq %u, expected %u\n", @@ -1192,14 +1191,17 @@ static void check_final_state(const struct test_output *o, /* Verify we drop no frames, but only if it's not a TV encoder, since * those use some funny fake timings behind userspace's back. */ if (o->flags & TEST_CHECK_TS && !analog_tv_connector(o)) { - double expected; - int count = es->count; - - count *= o->seq_step; - expected = (double)elapsed / frame_time(o); - igt_assert_f(fabs((double)count - expected)/expected <= 0.01, - "dropped frames, expected %f, counted %d, encoder type %d\n", - expected, count, o->kencoder[0]->encoder_type); + int count = es->count * o->seq_step; + unsigned int min = frame_time(o) * (count - 1); + unsigned int max = frame_time(o) * (count + 1); + + igt_debug("expected %d, counted %d, encoder type %d\n", + (int)(elapsed / frame_time(o)), count, + o->kencoder[0]->encoder_type); + igt_assert_f(elapsed >= min && elapsed <= max, + "dropped frames, expected %d, counted %d, encoder type %d\n", + (int)(elapsed / frame_time(o)), count, + o->kencoder[0]->encoder_type); } } -- cgit v1.2.3