Re: [igt-dev] [PATCH i-g-t] igt/kms_flip: Allow reported vblank times to be in the future

[Chris Wilson <chris@chris-wilson.co.uk>]

Quoting Ville Syrjälä (2018-05-11 15:36:46)
> On Fri, May 11, 2018 at 02:50:18PM +0100, Chris Wilson wrote:
> > Quoting Ville Syrjälä (2018-05-11 14:37:31)
> > > On Thu, May 10, 2018 at 05:04:34PM +0100, Chris Wilson wrote:
> > > > The vblank timestamp is given for the end of the vblank, but the
> > > > hardware may report the vblank before that point (so the kernel computes
> > > > a timestamp in the future), and userspace may then see the vblank event
> > > > that says the actual start-of-scanout has yet to happen. All this is
> > > > perfectly legal and can be observed in practice.
> > > > 
> > > > Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=106087
> > > > Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> > > > ---
> > > >  tests/kms_flip.c | 7 -------
> > > >  1 file changed, 7 deletions(-)
> > > > 
> > > > diff --git a/tests/kms_flip.c b/tests/kms_flip.c
> > > > index 3d6fe948d..5b0d07cc2 100644
> > > > --- a/tests/kms_flip.c
> > > > +++ b/tests/kms_flip.c
> > > > @@ -480,13 +480,6 @@ static void check_state(const struct test_output *o, const struct event_state *e
> > > >       if (es->count == 0)
> > > >               return;
> > > >  
> > > > -     timersub(&es->current_ts, &es->last_received_ts, &diff);
> > > > -     igt_assert_f(timercmp(&es->last_received_ts, &es->current_ts, <),
> > > 
> > > last_received_ts is the time we received the previous event isn't it?
> > 
> > Hmm, I thought it was the timestamp of the last received, which would
> > be the most recent event...
> > 
> > > So somehow our current event's kernel reported timestamp is older than the
> > > the time we received the previous event. So the kernel failed to send
> > > events when it was supposed to, or we failed to process them in a timely
> > > fashion perhaps?
> > 
> > (kms_flip:1495) DEBUG: name = vblank
> > last_ts = 326.737520
> > last_received_ts = 326.737347
> > last_seq = 15665
> > current_ts = 326.904242
> > current_received_ts = 328.153186
> > current_seq = 15675
> > count = 66
> > seq_step = 10
> > (kms_flip:1495) DEBUG: name = vblank
> > last_ts = 326.904242
> > last_received_ts = 328.153186
> > last_seq = 15675
> > current_ts = 328.137985
> > current_received_ts = 328.153386
> > current_seq = 15749
> > count = 67
> > seq_step = 10
> > 
> > Ok, should we have rejected the earlier vblank for having a received_ts
> > more than a frame into the future?
> 
> I guess it would make the failure easier to diagnose at least. But I'm
> not sure if there aren't any cases where the test actually wants to wait
> a while before reading the event.

If the test is intentionally causing a wait, the timercmp assert is
noise.

In the case above, we were delayed by 2s between the interrupt and the
read+gettime. That does seem quite something. Probably systemd.

> We should also do something about printing the results of
> timersub(). Currently what we print for negative time intervals
> is pretty confusing. Maybe just convert to float when printing?

Heh, as demonstrated I find the whole debug quite confusing.
-Chris
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev