Bug 103060 - [CI] igt@kms_flip@*-vs-vblank-race* - Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
Summary: [CI] igt@kms_flip@*-vs-vblank-race* - Failed assertion: end - start > 0.9 * m...
Status: NEW
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
: 102919 (view as bug list)
Depends on:
Blocks:
 
Reported: 2017-10-02 09:39 UTC by Marta Löfstedt
Modified: 2019-06-19 10:55 UTC (History)
1 user (show)

See Also:
i915 platform: BXT, CNL, GLK, HSW, ICL, SKL, SNB
i915 features: display/Other


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Marta Löfstedt 2017-10-02 09:39:52 UTC
CI_DRM_3159 snb-shards igt@kms_flip@dpms-vs-vblank-race fail:

(kms_flip:1595) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:780:
(kms_flip:1595) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1595) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:1595) CRITICAL: wait for two vblanks took 51717 usec (frame time 16665.600000 usec)
Subtest dpms-vs-vblank-race failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3159/shard-hsw5/igt@kms_flip@dpms-vs-vblank-race.html
Comment 1 Marta Löfstedt 2017-10-16 06:28:44 UTC
Also, CI_DRM_3237 APL-shards:

 (kms_flip:1343) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:780:
(kms_flip:1343) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1343) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1343) CRITICAL: wait for two vblanks took 38557 usec (frame time 16665.600000 usec)
Subtest dpms-vs-vblank-race-interruptible failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3237/shard-apl1/igt@kms_flip@dpms-vs-vblank-race-interruptible.html
Comment 2 Marta Löfstedt 2017-10-17 06:57:53 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3244/shard-apl3/igt@kms_flip@modeset-vs-vblank-race.html

(kms_flip:3752) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:780:
(kms_flip:3752) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:3752) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:3752) CRITICAL: wait for two vblanks took 64841 usec (frame time 16665.600000 usec)
Subtest modeset-vs-vblank-race failed.
Comment 3 Marta Löfstedt 2017-10-18 10:31:03 UTC
Also, CI_DRM_3252 GLK-shards 

(kms_flip:1606) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:780:
(kms_flip:1606) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1606) CRITICAL: wait for two vblanks took 49618 usec (frame time 16666.378441 usec)
Subtest dpms-vs-vblank-race failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3252/shard-glkb2/igt@kms_flip@dpms-vs-vblank-race.html
Comment 4 Marta Löfstedt 2017-10-18 10:39:34 UTC
Also, GLK-shards:

(kms_flip:2685) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:780:
(kms_flip:2685) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:2685) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2685) CRITICAL: wait for two vblanks took 49324 usec (frame time 16666.378441 usec)
Subtest modeset-vs-vblank-race-interruptible failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3253/shard-glkb2/igt@kms_flip@modeset-vs-vblank-race-interruptible.html
Comment 5 Marta Löfstedt 2017-11-03 07:32:57 UTC
*** Bug 102919 has been marked as a duplicate of this bug. ***
Comment 6 Marta Löfstedt 2017-12-18 13:26:23 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3539/shard-snb3/igt@kms_flip@modeset-vs-vblank-race.html

(kms_flip:1429) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:780:
(kms_flip:1429) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1429) CRITICAL: wait for two vblanks took 46119 usec (frame time 16665.600000 usec)
Subtest modeset-vs-vblank-race failed.
Comment 7 Marta Löfstedt 2018-01-30 07:28:13 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3688/shard-hsw6/igt@kms_flip@2x-modeset-vs-vblank-race.html

	
(kms_flip:6120) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:763:
(kms_flip:6120) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:6120) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:6120) CRITICAL: wait for two vblanks took 36105 usec (frame time 16665.600000 usec)
Subtest 2x-modeset-vs-vblank-race failed.
Comment 8 Marta Löfstedt 2018-02-06 07:49:32 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3723/shard-hsw5/igt@kms_flip@2x-dpms-vs-vblank-race-interruptible.html

(kms_flip:7296) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:763:
(kms_flip:7296) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:7296) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7296) CRITICAL: wait for two vblanks took 37261 usec (frame time 16665.600000 usec)
Subtest 2x-dpms-vs-vblank-race-interruptible failed.
Comment 9 Marta Löfstedt 2018-02-07 12:07:31 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4227/shard-hsw5/igt@kms_flip@2x-dpms-vs-vblank-race.html

(kms_flip:17014) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:763:
(kms_flip:17014) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:17014) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:17014) CRITICAL: wait for two vblanks took 41085 usec (frame time 16665.600000 usec)
Subtest 2x-dpms-vs-vblank-race failed.
Comment 10 Marta Löfstedt 2018-02-16 07:02:34 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4256/shard-hsw6/igt@kms_flip@2x-modeset-vs-vblank-race-interruptible.html

(kms_flip:31512) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:763:
(kms_flip:31512) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:31512) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:31512) CRITICAL: wait for two vblanks took 37954 usec (frame time 16665.600000 usec)
Subtest 2x-modeset-vs-vblank-race-interruptible failed.
Comment 11 Marta Löfstedt 2018-03-12 11:08:13 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-drrs/igt@kms_flip@modeset-vs-vblank-race-interruptible.html

(kms_flip:2975) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:763:
(kms_flip:2975) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:2975) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2975) CRITICAL: wait for two vblanks took 49658 usec (frame time 16666.378441 usec)

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@modeset-vs-vblank-race-interruptible.html

(kms_flip:2998) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:763:
(kms_flip:2998) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:2998) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2998) CRITICAL: wait for two vblanks took 40912 usec (frame time 16667.604313 usec)
Subtest modeset-vs-vblank-race-interruptible failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-drrs/igt@kms_flip@modeset-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@modeset-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-drrs/igt@kms_flip@dpms-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@dpms-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-drrs/igt@kms_flip@dpms-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@dpms-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@2x-modeset-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@2x-modeset-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@2x-dpms-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3903/fi-cnl-y3/igt@kms_flip@2x-dpms-vs-vblank-race.html
Comment 12 Marta Löfstedt 2018-03-16 07:26:26 UTC
From shardlist on BAT machines runs fi_skl_6600u hit:

(kms_flip:1763) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:763:
(kms_flip:1763) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1763) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1763) CRITICAL: wait for two vblanks took 40335 usec (frame time 16671.721366 usec)


https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-skl-6600u/igt@kms_flip@modeset-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-skl-6600u/igt@kms_flip@modeset-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-skl-6600u/igt@kms_flip@dpms-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-skl-6600u/igt@kms_flip@dpms-vs-vblank-race.html
Comment 13 Marta Löfstedt 2018-03-19 07:34:18 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-ilk-m540/igt@kms_flip@2x-modeset-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-ilk-m540/igt@kms_flip@2x-modeset-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-ilk-m540/igt@kms_flip@modeset-vs-vblank-race.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-ilk-m540/igt@kms_flip@modeset-vs-vblank-race-interruptible.html

(kms_flip:1442) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:763:
(kms_flip:1442) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1442) CRITICAL: wait for two vblanks took 49734 usec (frame time 16670.871985 usec)
Subtest 2x-modeset-vs-vblank-race failed.
Comment 14 Marta Löfstedt 2018-03-19 07:39:53 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_2/fi-bsw-n3050/igt@kms_flip@dpms-vs-vblank-race-interruptible.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1/fi-bsw-n3050/igt@kms_flip@dpms-vs-vblank-race.html

(kms_flip:1515) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:763:
(kms_flip:1515) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1515) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1515) CRITICAL: wait for two vblanks took 37918 usec (frame time 16680.519481 usec)
Subtest dpms-vs-vblank-race-interruptible failed.
Comment 15 Marta Löfstedt 2018-03-19 15:07:39 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_4/fi-skl-gvtdvm/igt@kms_flip@dpms-vs-vblank-race.html

(kms_flip:1248) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:763:
(kms_flip:1248) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1248) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:1248) CRITICAL: wait for two vblanks took 36273 usec (frame time 16672.736573 usec)
Subtest dpms-vs-vblank-race failed.
Comment 16 Marta Löfstedt 2018-03-21 09:48:19 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_5/fi-bdw-gvtdvm/igt@kms_flip@modeset-vs-vblank-race.html

(kms_flip:1301) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:763:
(kms_flip:1301) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1301) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:1301) CRITICAL: wait for two vblanks took 38360 usec (frame time 16672.736573 usec)
Subtest modeset-vs-vblank-race failed.
Comment 18 Marta Löfstedt 2018-04-12 08:07:07 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4046/shard-glk3/igt@kms_flip@dpms-vs-vblank-race.html


(kms_flip:1243) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:763:
(kms_flip:1243) CRITICAL: Failed assertion: end - start > 0.9 * mode_frame_time(o) && end - start < 2.1 * mode_frame_time(o)
(kms_flip:1243) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_flip:1243) CRITICAL: wait for two vblanks took 37473 usec (frame time 16666.666667 usec)
Subtest dpms-vs-vblank-race failed.
Comment 19 CI Bug Log 2019-04-04 11:42:16 UTC
The CI Bug Log issue associated to this bug has been archived.

New failures matching the above filters will not be associated to this bug anymore.
Comment 20 Martin Peres 2019-04-04 11:48:51 UTC
(In reply to CI Bug Log from comment #19)
> The CI Bug Log issue associated to this bug has been archived.
> 
> New failures matching the above filters will not be associated to this bug
> anymore.

There was 2 issues associated to this bug, one being a super-set of the other. I closed the smaller one since it was useless.
Comment 21 Daniel Vetter 2019-04-04 11:49:47 UTC
Need to figure out why we stall and the vblank wait takes longer (sometimes a lot longer) than we expect. Best way probably is grab the ftrace flight recorder log when this happens and dump it, since reproducibility is pretty low.

The delay is sometimes multiple frames, so not something we can just shrug off as statistical noise.
Comment 22 Martin Peres 2019-04-04 11:56:28 UTC
Customer impact could be increased stuttering when watching videos or playing games. More information needs to be collected in order to improve our understanding of the issue, but a medium priority seems appropriate.
Comment 23 Stanislav Lisovskiy 2019-06-18 11:40:31 UTC
I wonder still, if this wait_for_vblanks is really that long. 
As I understand from test case we wait for 2 vblanks and then expected time elapsed to be in ([ 1, 2] +- 0.1) * frame time.

Collected from ci buglog few last runs:

(kms_flip:1841) CRITICAL: wait for two vblanks took 35113 usec (frame time 16667.604313 usec)
(kms_flip:1836) CRITICAL: wait for two vblanks took 35024 usec (frame time 16667.604313 usec)
(kms_flip:1769) CRITICAL: wait for two vblanks took 35070 usec (frame time 16667.604313 usec)
(kms_flip:1782) CRITICAL: wait for two vblanks took 35063 usec (frame time 16667.604313 usec)
(kms_flip:1596) CRITICAL: wait for two vblanks took 35138 usec (frame time 16667.604313 usec)
(kms_flip:1777) CRITICAL: wait for two vblanks took 35060 usec (frame time 16667.604313 usec)

The frame time here is 16667.604313 which multiplied by 2.1 gives 35000.0000007(maximum value that we allow in assert)
which is only ~100 usec different from values which we currently see.

I also checked on my own ICL board - it doesn't fail as the values stay between 32000-33000 usec, however the deviation is still might be even up to 1000 usec if I modify this test case to run it 100 times:

...
wait for two vblanks took 32139 usec (frame time 16667.604313 usec)
wait for two vblanks took 33297 usec (frame time 16667.604313 usec)
wait for two vblanks took 33289 usec (frame time 16667.604313 usec)
wait for two vblanks took 33221 usec (frame time 16667.604313 usec)
wait for two vblanks took 33330 usec (frame time 16667.604313 usec)
wait for two vblanks took 33325 usec (frame time 16667.604313 usec)
wait for two vblanks took 33334 usec (frame time 16667.604313 usec)
wait for two vblanks took 33238 usec (frame time 16667.604313 usec)
wait for two vblanks took 33352 usec (frame time 16667.604313 usec)
...
Comment 24 Jani Saarinen 2019-06-18 11:51:12 UTC
Where these fail are Chamelium systems.
Comment 25 Stanislav Lisovskiy 2019-06-19 10:55:39 UTC
Looked into test case wf_blank-ts-check-interruptible results in the same run and found one interesting correlation: in case when we have those failures we also have that one: 

Using monotonic timestamps
Starting subtest: wf_vblank-ts-check-interruptible
Beginning wf_vblank-ts-check-interruptible on pipe A, connector eDP-1
  3840x2160 60 3840 3888 3920 4000 2160 2163 2168 2222 0xa 0x48 533250
Expected frametime: 16668us; measured 17955.9us +- 5.512us accuracy 0.09%
vblank interval differs from modeline! expected 16667.6us, measured 17956us +- 5.512us, difference 1288.3us (233.7 sigma)

wf_vblank-ts-check-interruptible on pipe A, connector eDP-1: PASSED

...

Beginning wf_vblank-ts-check-interruptible on pipe C, connector eDP-1
  3840x2160 60 3840 3888 3920 4000 2160 2163 2168 2222 0xa 0x48 533250
Expected frametime: 16668us; measured 17955.9us +- 5.702us accuracy 0.10%
vblank interval differs from modeline! expected 16667.6us, measured 17956us +- 5.702us, difference 1288.3us (225.9 sigma)

In normal case two vblanks take ~33297 which approximately twice as expected frame time, however there seems to be cases when the actual vblank interval gets different: 17956us will give us value rather close or exceeding boundary condition in assert. So basically this is not about some overhead in vblank_wait or other code path, but it is really the vblanking interval itself which is getting different from expected one.

I wonder why we don't consider this an error in wf_vblank-ts-check-interruptible as it clearly leads to this fail as a consequence. We should either then not consider this an issue here either then and compare to the actual frame time or wf_vblank-ts-check-interruptible should also fail. Any thoughts?


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.