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

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

[Chris Wilson]

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, <),
-		     "%s ts before the %s was issued!\n"
-		     "timerdiff %ld.%06ld\n",
-		     es->name, es->name,
-		     diff.tv_sec, diff.tv_usec);
-
 	/* check only valid if no modeset happens in between, that increments by
 	 * (1 << 23) on each step. This bounding matches the one in
 	 * DRM_IOCTL_WAIT_VBLANK. */
-- 
2.17.0

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] ✓ Fi.CI.BAT: success for igt/kms_flip: Allow reported vblank times to be in the future

[Patchwork]

== Series Details ==

Series: igt/kms_flip: Allow reported vblank times to be in the future
URL   : https://patchwork.freedesktop.org/series/43019/
State : success

== Summary ==

= CI Bug Log - changes from CI_DRM_4163 -> IGTPW_1342 =

== Summary - SUCCESS ==

  No regressions found.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/43019/revisions/1/mbox/

== Known issues ==

  Here are the changes found in IGTPW_1342 that come from known issues:

  === IGT changes ===

    ==== Issues hit ====

    igt@kms_frontbuffer_tracking@basic:
      fi-hsw-4200u:       PASS -> DMESG-FAIL (fdo#102614, fdo#106103)

    
    ==== Possible fixes ====

    igt@drv_module_reload@basic-reload-inject:
      fi-glk-j4005:       DMESG-WARN (fdo#106248) -> PASS

    igt@kms_flip@basic-flip-vs-wf_vblank:
      fi-hsw-4770r:       FAIL (fdo#100368) -> PASS

    
  fdo#100368 https://bugs.freedesktop.org/show_bug.cgi?id=100368
  fdo#102614 https://bugs.freedesktop.org/show_bug.cgi?id=102614
  fdo#106103 https://bugs.freedesktop.org/show_bug.cgi?id=106103
  fdo#106248 https://bugs.freedesktop.org/show_bug.cgi?id=106248


== Participating hosts (41 -> 37) ==

  Missing    (4): fi-ctg-p8600 fi-ilk-m540 fi-byt-squawks fi-skl-6700hq 


== Build changes ==

    * IGT: IGT_4468 -> IGTPW_1342
    * Piglit: piglit_4468 -> piglit_4474

  CI_DRM_4163: 8e1dab6e913be7d014eb9bc355ec65b6b56dcd56 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_1342: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1342/
  IGT_4468: 548a894dc904c4628522dbbc77cb179a4c965ebc @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  piglit_4468: 1e60f1499e5b71b6d5a747189d7c28f57359a87f @ git://anongit.freedesktop.org/piglit
  piglit_4474: 318e0b8c5cdf7aac628f85d0c4a00db8f2d6ab0d @ git://anongit.freedesktop.org/piglit

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1342/issues.html
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] ✓ Fi.CI.IGT: success for igt/kms_flip: Allow reported vblank times to be in the future

[Patchwork]

== Series Details ==

Series: igt/kms_flip: Allow reported vblank times to be in the future
URL   : https://patchwork.freedesktop.org/series/43019/
State : success

== Summary ==

= CI Bug Log - changes from IGT_4468_full -> IGTPW_1342_full =

== Summary - WARNING ==

  Minor unknown changes coming with IGTPW_1342_full need to be verified
  manually.
  
  If you think the reported changes have nothing to do with the changes
  introduced in IGTPW_1342_full, please notify your bug team to allow them
  to document this new failure mode, which will reduce false positives in CI.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/43019/revisions/1/mbox/

== Possible new issues ==

  Here are the unknown changes that may have been introduced in IGTPW_1342_full:

  === IGT changes ===

    ==== Warnings ====

    igt@drv_selftest@live_execlists:
      shard-glk:          SKIP -> PASS +1
      shard-apl:          SKIP -> PASS +1

    igt@drv_selftest@live_guc:
      shard-kbl:          SKIP -> PASS +1

    
== Known issues ==

  Here are the changes found in IGTPW_1342_full that come from known issues:

  === IGT changes ===

    ==== Issues hit ====

    igt@gem_workarounds@suspend-resume-context:
      shard-kbl:          PASS -> INCOMPLETE (fdo#103665)

    igt@kms_flip@2x-plain-flip-ts-check-interruptible:
      shard-hsw:          PASS -> FAIL (fdo#100368)

    igt@kms_flip@plain-flip-ts-check-interruptible:
      shard-glk:          PASS -> FAIL (fdo#100368)

    igt@kms_rotation_crc@sprite-rotation-180:
      shard-snb:          PASS -> FAIL (fdo#103925, fdo#104724) +1

    igt@kms_setmode@basic:
      shard-glk:          PASS -> FAIL (fdo#99912)

    igt@perf_pmu@rc6-runtime-pm-long:
      shard-kbl:          PASS -> FAIL (fdo#105010)

    
    ==== Possible fixes ====

    igt@drv_selftest@live_hangcheck:
      shard-kbl:          DMESG-FAIL (fdo#106453) -> PASS
      shard-apl:          DMESG-FAIL (fdo#106453) -> PASS
      shard-glk:          DMESG-FAIL (fdo#106453) -> PASS

    igt@drv_selftest@mock_breadcrumbs:
      shard-hsw:          DMESG-WARN (fdo#106453) -> PASS +7

    igt@drv_selftest@mock_dmabuf:
      shard-glk:          DMESG-WARN (fdo#106453) -> PASS +7

    igt@drv_selftest@mock_evict:
      shard-snb:          DMESG-WARN (fdo#106453) -> PASS +7

    igt@drv_selftest@mock_requests:
      shard-kbl:          DMESG-WARN (fdo#106453) -> PASS +7

    igt@drv_selftest@mock_vma:
      shard-apl:          DMESG-WARN (fdo#106453) -> PASS +7

    igt@drv_suspend@debugfs-reader:
      shard-glk:          INCOMPLETE (fdo#103359, k.org#198133) -> PASS

    igt@kms_flip@flip-vs-expired-vblank-interruptible:
      shard-glk:          FAIL (fdo#102887) -> PASS

    igt@kms_flip@flip-vs-wf_vblank-interruptible:
      shard-glk:          FAIL (fdo#100368) -> PASS

    igt@kms_flip@plain-flip-fb-recreate-interruptible:
      shard-hsw:          FAIL (fdo#100368) -> PASS

    
  fdo#100368 https://bugs.freedesktop.org/show_bug.cgi?id=100368
  fdo#102887 https://bugs.freedesktop.org/show_bug.cgi?id=102887
  fdo#103359 https://bugs.freedesktop.org/show_bug.cgi?id=103359
  fdo#103665 https://bugs.freedesktop.org/show_bug.cgi?id=103665
  fdo#103925 https://bugs.freedesktop.org/show_bug.cgi?id=103925
  fdo#104724 https://bugs.freedesktop.org/show_bug.cgi?id=104724
  fdo#105010 https://bugs.freedesktop.org/show_bug.cgi?id=105010
  fdo#106453 https://bugs.freedesktop.org/show_bug.cgi?id=106453
  fdo#99912 https://bugs.freedesktop.org/show_bug.cgi?id=99912
  k.org#198133 https://bugzilla.kernel.org/show_bug.cgi?id=198133


== Participating hosts (9 -> 5) ==

  Missing    (4): pig-snb-2600 pig-glk-j5005 pig-skl-6600 pig-hsw-4770r 


== Build changes ==

    * IGT: IGT_4468 -> IGTPW_1342
    * Linux: CI_DRM_4160 -> CI_DRM_4163
    * Piglit: piglit_4468 -> piglit_4474

  CI_DRM_4160: 6d9a2ccf9fca7c006f24b7ff6193ee356b6d3503 @ git://anongit.freedesktop.org/gfx-ci/linux
  CI_DRM_4163: 8e1dab6e913be7d014eb9bc355ec65b6b56dcd56 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_1342: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1342/
  IGT_4468: 548a894dc904c4628522dbbc77cb179a4c965ebc @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  piglit_4468: 1e60f1499e5b71b6d5a747189d7c28f57359a87f @ git://anongit.freedesktop.org/piglit
  piglit_4474: 318e0b8c5cdf7aac628f85d0c4a00db8f2d6ab0d @ git://anongit.freedesktop.org/piglit

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1342/shards.html
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

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

[Ville Syrjälä]

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? 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?

> -		     "%s ts before the %s was issued!\n"
> -		     "timerdiff %ld.%06ld\n",
> -		     es->name, es->name,
> -		     diff.tv_sec, diff.tv_usec);
> -
>  	/* check only valid if no modeset happens in between, that increments by
>  	 * (1 << 23) on each step. This bounding matches the one in
>  	 * DRM_IOCTL_WAIT_VBLANK. */
> -- 
> 2.17.0
> 
> _______________________________________________
> igt-dev mailing list
> igt-dev@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/igt-dev

-- 
Ville Syrjälä
Intel
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

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

[Chris Wilson]

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?
-Chris
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

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

[Ville Syrjälä]

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.

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?

-- 
Ville Syrjälä
Intel
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

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

[Chris Wilson]

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