From 4e1492ba1729d8e56f12db706f4bc08acbbf31e8 Mon Sep 17 00:00:00 2001 From: Ville Syrjälä Date: Thu, 17 May 2018 22:44:42 +0300 Subject: tests/kms_flip: Print timevals as float MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Time intervals as produced by timersub() are normalized to have the tv_usec in the range 0-999999. That leads to very confusing looking debug output for negative interval. Eg. an interval of -0.1 seconds would be represented as tv_sec=-1, tv_usec=900000. Let's just convert the thing to a float seconds value and print that so that we'll get less confusing debug output. Signed-off-by: Ville Syrjälä Reviewed-by: Chris Wilson --- tests/kms_flip.c | 43 +++++++++++++++++++++++-------------------- 1 file changed, 23 insertions(+), 20 deletions(-) diff --git a/tests/kms_flip.c b/tests/kms_flip.c index 3d6fe948..393d690a 100644 --- a/tests/kms_flip.c +++ b/tests/kms_flip.c @@ -125,23 +125,28 @@ struct event_state { int seq_step; }; +static float timeval_float(const struct timeval *tv) +{ + return tv->tv_sec + tv->tv_usec / 1000000.0f; +} + static void dump_event_state(const struct event_state *es) { igt_debug("name = %s\n" - "last_ts = %ld.%06ld\n" - "last_received_ts = %ld.%06ld\n" + "last_ts = %.06f\n" + "last_received_ts = %.06f\n" "last_seq = %u\n" - "current_ts = %ld.%06ld\n" - "current_received_ts = %ld.%06ld\n" + "current_ts = %.06f\n" + "current_received_ts = %.06f\n" "current_seq = %u\n" "count = %u\n" "seq_step = %d\n", es->name, - es->last_ts.tv_sec, es->last_ts.tv_usec, - es->last_received_ts.tv_sec, es->last_received_ts.tv_usec, + timeval_float(&es->last_ts), + timeval_float(&es->last_received_ts), es->last_seq, - es->current_ts.tv_sec, es->current_ts.tv_usec, - es->current_received_ts.tv_sec, es->current_received_ts.tv_usec, + timeval_float(&es->current_ts), + timeval_float(&es->current_received_ts), es->current_seq, es->count, es->seq_step); @@ -472,9 +477,8 @@ static void check_state(const struct test_output *o, const struct event_state *e timersub(&es->current_ts, &es->current_received_ts, &diff); if (!analog_tv_connector(o)) { igt_assert_f(diff.tv_sec < 0 || (diff.tv_sec == 0 && diff.tv_usec <= 2000), - "%s ts delayed for too long: %ld.%06ld\n", - es->name, diff.tv_sec, diff.tv_usec); - + "%s ts delayed for too long: %.06f\n", + es->name, timeval_float(&diff)); } if (es->count == 0) @@ -483,9 +487,8 @@ static void check_state(const struct test_output *o, const struct event_state *e timersub(&es->current_ts, &es->last_received_ts, &diff); igt_assert_f(timercmp(&es->last_received_ts, &es->current_ts, <), "%s ts before the %s was issued!\n" - "timerdiff %ld.%06ld\n", - es->name, es->name, - diff.tv_sec, diff.tv_usec); + "timerdiff %.06f\n", + es->name, es->name, timeval_float(&diff)); /* check only valid if no modeset happens in between, that increments by * (1 << 23) on each step. This bounding matches the one in @@ -517,16 +520,16 @@ static void check_state(const struct test_output *o, const struct event_state *e elapsed = 1e6*diff.tv_sec + diff.tv_usec; expected = (es->current_seq - es->last_seq) * actual_frame_time(o); - 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, + igt_debug("%s ts/seq: last %.06f/%u, current %.06f/%u: elapsed=%.1fus expected=%.1fus +- %.1fus, error %.1f%%\n", + es->name, timeval_float(&es->last_ts), es->last_seq, + timeval_float(&es->current_ts), es->current_seq, elapsed, expected, expected * 0.005, fabs((elapsed - expected) / expected) * 100); 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, + "inconsistent %s ts/seq: last %.06f/%u, current %.06f/%u: elapsed=%.1fus expected=%.1fus\n", + es->name, timeval_float(&es->last_ts), es->last_seq, + timeval_float(&es->current_ts), es->current_seq, elapsed, expected); igt_assert_f(es->current_seq == es->last_seq + o->seq_step, -- cgit v1.2.3