Bug 106682 - [CI] [ELK only] igt@* - dmesg-fail - Failed assertion: drmWaitVBlank(drm_fd, &wait_vbl) == 0
Summary: [CI] [ELK only] igt@* - dmesg-fail - Failed assertion: drmWaitVBlank(drm_fd, ...
Status: CLOSED WORKSFORME
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: XOrg git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2018-05-28 10:16 UTC by Martin Peres
Modified: 2018-11-01 16:02 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features: display/Other


Attachments

Description Martin Peres 2018-05-28 10:16:45 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_38/fi-elk-e7500/igt@kms_cursor_crc@cursor-256x256-sliding.html
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_41/fi-elk-e7500/igt@kms_chv_cursor_fail@pipe-a-128x128-top-edge.html

(kms_cursor_crc:1257) igt_kms-CRITICAL: Test assertion failure function igt_wait_for_vblank_count, file ../lib/igt_kms.c:3742:
(kms_cursor_crc:1257) igt_kms-CRITICAL: Failed assertion: drmWaitVBlank(drm_fd, &wait_vbl) == 0
(kms_cursor_crc:1257) igt_kms-CRITICAL: Last errno: 16, Device or resource busy
Subtest cursor-256x256-sliding failed.

[   74.720232] [drm:drm_atomic_helper_wait_for_flip_done] *ERROR* [CRTC:39:pipe A] flip_done timed out
[   84.960133] [drm:drm_atomic_helper_wait_for_dependencies] *ERROR* [CRTC:39:pipe A] flip_done timed out
[   95.200136] [drm:drm_atomic_helper_wait_for_dependencies] *ERROR* [CONNECTOR:55:HDMI-A-1] flip_done timed out
[  105.440127] [drm:drm_atomic_helper_wait_for_dependencies] *ERROR* [PLANE:28:primary A] flip_done timed out
[  115.680136] [drm:drm_atomic_helper_wait_for_flip_done] *ERROR* [CRTC:39:pipe A] flip_done timed out


https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_48/fi-elk-e7500/igt@kms_chv_cursor_fail@pipe-b-64x64-left-edge.html

(kms_chv_cursor_fail:1561) igt_kms-CRITICAL: Test assertion failure function igt_wait_for_vblank_count, file ../lib/igt_kms.c:3742:
(kms_chv_cursor_fail:1561) igt_kms-CRITICAL: Failed assertion: drmWaitVBlank(drm_fd, &wait_vbl) == 0
(kms_chv_cursor_fail:1561) igt_kms-CRITICAL: Last errno: 16, Device or resource busy
Subtest pipe-B-64x64-left-edge failed.

[  130.664141] ------------[ cut here ]------------
[  130.664146] vblank wait timed out on crtc 1
[  130.664179] WARNING: CPU: 1 PID: 1561 at drivers/gpu/drm/drm_vblank.c:1084 drm_wait_one_vblank+0x172/0x180
[  130.664182] Modules linked in: i915 coretemp snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel lpc_ich snd_hda_codec snd_hwdep snd_hda_core snd_pcm e1000e mei_me prime_numbers mei
[  130.664236] CPU: 1 PID: 1561 Comm: kms_chv_cursor_ Tainted: G     U            4.17.0-rc6-ge783c3164090-drmtip_48+ #1
[  130.664239] Hardware name: Hewlett-Packard HP Compaq 8000 Elite CMT PC/3647h, BIOS 786G7 v01.02 10/22/2009
[  130.664244] RIP: 0010:drm_wait_one_vblank+0x172/0x180
[  130.664247] RSP: 0018:ffffb2440019fa00 EFLAGS: 00010286
[  130.664254] RAX: 0000000000000000 RBX: ffff885e8e380000 RCX: 0000000000000001
[  130.664257] RDX: 0000000080000001 RSI: ffffffff830fb831 RDI: 00000000ffffffff
[  130.664261] RBP: 0000000000000001 R08: 000000000a1974e7 R09: 0000000000000000
[  130.664264] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[  130.664268] R13: 0000000000000409 R14: ffff885e592e5f48 R15: ffff885e85114258
[  130.664272] FS:  00007fbf4bdd6980(0000) GS:ffff885e9bc80000(0000) knlGS:0000000000000000
[  130.664276] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  130.664280] CR2: 00007fbf4bd3b000 CR3: 0000000110f24000 CR4: 00000000000406e0
[  130.664283] Call Trace:
[  130.664293]  ? wait_woken+0xa0/0xa0
[  130.664387]  intel_pre_plane_update+0x161/0x200 [i915]
[  130.664474]  intel_atomic_commit_tail+0xce/0xcf0 [i915]
[  130.664574]  intel_atomic_commit+0x240/0x320 [i915]
[  130.664587]  restore_fbdev_mode_atomic+0x1ad/0x220
[  130.664622]  drm_fb_helper_restore_fbdev_mode_unlocked+0x42/0x90
[  130.664630]  drm_fb_helper_set_par+0x24/0x50
[  130.664708]  intel_fbdev_set_par+0x11/0x40 [i915]
[  130.664717]  fbcon_init+0x4db/0x680
[  130.664735]  visual_init+0xd0/0x130
[  130.664744]  do_bind_con_driver+0x1ef/0x3f0
[  130.664763]  do_unbind_con_driver+0x1a8/0x230
[  130.664785]  store_bind+0xad/0x1a0
[  130.664798]  kernfs_fop_write+0x104/0x190
[  130.664811]  __vfs_write+0x31/0x160
[  130.664821]  ? rcu_read_lock_sched_held+0x6f/0x80
[  130.664826]  ? rcu_sync_lockdep_assert+0x29/0x50
[  130.664832]  ? __sb_start_write+0x152/0x1f0
[  130.664836]  ? __sb_start_write+0x168/0x1f0
[  130.664847]  vfs_write+0xbd/0x1a0
[  130.664858]  ksys_write+0x50/0xc0
[  130.664872]  do_syscall_64+0x55/0x190
[  130.664880]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  130.664884] RIP: 0033:0x7fbf4b55d281
[  130.664888] RSP: 002b:00007fff5d9e4598 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[  130.664894] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007fbf4b55d281
[  130.664898] RDX: 0000000000000002 RSI: 00007fbf4b9d16d4 RDI: 0000000000000008
[  130.664901] RBP: 00007fff5d9e55e0 R08: 0000563b26ffc9d3 R09: 0000000000000006
[  130.664905] R10: 0000000000000000 R11: 0000000000000246 R12: 00007fbf4b546718
[  130.664908] R13: 0000000000000003 R14: 00007fbf4b54b628 R15: 00007fbf4b547d80
[  130.664937] Code: 32 ff ff ff e8 00 5d a7 ff 48 89 e6 4c 89 f7 e8 95 70 ac ff 45 85 e4 0f 85 0f ff ff ff 89 ee 48 c7 c7 28 15 0d 83 e8 fe 59 a7 ff <0f> 0b e9 fa fe ff ff 0f 1f 80 00 00 00 00 8b b7 f8 00 00 00 48 
[  130.665074] irq event stamp: 128514
[  130.665074] hardirqs last  enabled at (128513): [<ffffffff820fc7c7>] vprintk_emit+0x4b7/0x4d0
[  130.665074] hardirqs last disabled at (128514): [<ffffffff82a0111c>] error_entry+0x7c/0x100
[  130.665074] softirqs last  enabled at (128284): [<ffffffff82c0032b>] __do_softirq+0x32b/0x4e1
[  130.665074] softirqs last disabled at (128261): [<ffffffff8208f724>] irq_exit+0xa4/0xb0
[  130.665074] WARNING: CPU: 1 PID: 1561 at drivers/gpu/drm/drm_vblank.c:1084 drm_wait_one_vblank+0x172/0x180
[  130.665074] ---[ end trace 1bb49f2f650dea0e ]---

This may or may not be related to https://bugs.freedesktop.org/show_bug.cgi?id=105702 (which seems like a super bug...).
Comment 1 Ville Syrjala 2018-09-03 15:22:35 UTC
This was presumably fixed by

commit 132c27c97cb958f637dc05adc35a61b47779bcd8
Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
Date:   Mon Jun 11 23:02:55 2018 +0300

    drm/i915: Fix PIPESTAT irq ack on i965/g4x
Comment 2 Martin Peres 2018-09-07 16:35:41 UTC
(In reply to Ville Syrjala from comment #1)
> This was presumably fixed by
> 
> commit 132c27c97cb958f637dc05adc35a61b47779bcd8
> Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
> Date:   Mon Jun 11 23:02:55 2018 +0300
> 
>     drm/i915: Fix PIPESTAT irq ack on i965/g4x

This happened again after this patch:

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4298_12/fi-elk-e7500/igt@kms_pipe_crc_basic@nonblocking-crc-pipe-b.html

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4298_12/fi-elk-e7500/igt@kms_pipe_crc_basic@nonblocking-crc-pipe-b.html

(kms_pipe_crc_basic:3583) igt_kms-CRITICAL: Test assertion failure function igt_wait_for_vblank_count, file ../lib/igt_kms.c:3842:
(kms_pipe_crc_basic:3583) igt_kms-CRITICAL: Failed assertion: drmWaitVBlank(drm_fd, &wait_vbl) == 0
(kms_pipe_crc_basic:3583) igt_kms-CRITICAL: Last errno: 16, Device or resource busy

In any case, this patch reduced massively the frequency of this issue!
Comment 3 Martin Peres 2018-11-01 16:02:07 UTC
(In reply to Martin Peres from comment #2)
> (In reply to Ville Syrjala from comment #1)
> > This was presumably fixed by
> > 
> > commit 132c27c97cb958f637dc05adc35a61b47779bcd8
> > Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
> > Date:   Mon Jun 11 23:02:55 2018 +0300
> > 
> >     drm/i915: Fix PIPESTAT irq ack on i965/g4x
> 
> This happened again after this patch:
> 
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4298_12/fi-elk-e7500/
> igt@kms_pipe_crc_basic@nonblocking-crc-pipe-b.html
> 
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4298_12/fi-elk-e7500/
> igt@kms_pipe_crc_basic@nonblocking-crc-pipe-b.html
> 
> (kms_pipe_crc_basic:3583) igt_kms-CRITICAL: Test assertion failure function
> igt_wait_for_vblank_count, file ../lib/igt_kms.c:3842:
> (kms_pipe_crc_basic:3583) igt_kms-CRITICAL: Failed assertion:
> drmWaitVBlank(drm_fd, &wait_vbl) == 0
> (kms_pipe_crc_basic:3583) igt_kms-CRITICAL: Last errno: 16, Device or
> resource busy
> 
> In any case, this patch reduced massively the frequency of this issue!

Not seen ever again after that... closing!


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.