[Intel-gfx] [PATCH igt] igt/kms_flip: Print more information to debug for flip timing checks

[Daniel Vetter]

On Thu, Oct 20, 2016 at 03:35:04PM +0100, Chris Wilson wrote:
> We have a cantiga that doesn't pass
> igt at 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 <chris at chris-wilson.co.uk>

Random drive-by, but I wonder whether some helpers to print timings here
might be useful. Stuff like how many % of the vrefresh an error is, and
how that compares to the line-time (since on some boxes that's our limit
for timestamp accuracy). Either way more debug info is great (and this is
a bit a mess either way ...).
-Daniel

> ---
>  tests/kms_flip.c | 46 ++++++++++++++++++++++++----------------------
>  1 file changed, 24 insertions(+), 22 deletions(-)
> 
> diff --git a/tests/kms_flip.c b/tests/kms_flip.c
> index 7646aaf..b30e07c 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);
>  	}
>  }
>  
> -- 
> 2.9.3
> 
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch