| Summary: | [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) | ||
|---|---|---|---|
| Product: | DRI | Reporter: | Marta Löfstedt <marta.lofstedt> |
| Component: | DRM/Intel | Assignee: | Intel GFX Bugs mailing list <intel-gfx-bugs> |
| Status: | CLOSED FIXED | QA Contact: | Intel GFX Bugs mailing list <intel-gfx-bugs> |
| Severity: | normal | ||
| Priority: | medium | CC: | intel-gfx-bugs |
| Version: | DRI git | ||
| Hardware: | Other | ||
| OS: | All | ||
| Whiteboard: | ReadyForDev | ||
| i915 platform: | BXT, CNL, GLK, HSW, ICL, SKL, SNB | i915 features: | display/Other |
|
Description
Marta Löfstedt
2017-10-02 09:39:52 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 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. 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 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 *** Bug 102919 has been marked as a duplicate of this bug. *** 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. 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. 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. 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. 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. 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 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 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. 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. 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. 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. 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. 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. (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. 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. 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. 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) ... Where these fail are Chamelium systems. 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? patch merged: igt/kms_flip: Use actual vblank_interval instead of expected. author Stanislav Lisovskiy <stanislav.lisovskiy@intel.com> committer Maarten Lankhorst <maarten.lankhorst@linux.intel.com> commit 073caf4acb7cac63abe7a5e1409ea27a764db5fd Last seen on drmtip 362(2 months 1 week ago) with a reproduction rate of 100%, archiving this as it is not seen in the last 40 runs. 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. |
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.