With commit 0d0fe91 we are getting a bunch of flip_done timed out messages on SNB. Don't have yesterday logs, but I'll attach today's with 4.15.0-rc2 commit-1a0d67e+. Note: I'm adding SNB in tittle since it seems to be the only platform affected. Sample messages: [ 4364.260454] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 4374.500423] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:47:pipe B] flip_done timed out [ 4384.740457] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:48:VGA-1] flip_done timed out [ 4394.980460] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:56:DP-1] flip_done timed out [ 4405.220458] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:28:primary A] flip_done timed out [ 4415.460450] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:38:primary B] flip_done timed out [ 4425.700456] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 4435.940451] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:47:pipe B] flip_done timed out Tests affected: igt@vgem_basic@create igt@vgem_basic@dmabuf-fence-before igt@prime_vgem@basic-sync-default igt@prime_self_import@basic-llseek-bad igt@vgem_basic@second-client igt@vgem_basic@debugfs igt@prime_self_import@basic-with_one_bo igt@prime_self_import@basic-llseek-size igt@pm_rps@basic-api igt@prime_self_import@basic-with_fd_dup igt@prime_vgem@basic-write igt@prime_vgem@basic-read igt@vgem_basic@sysfs igt@prime_vgem@basic-fence-mmap igt@vgem_basic@dmabuf-mmap igt@prime_self_import@basic-with_one_bo_two_files igt@prime_vgem@basic-fence-wait-default igt@vgem_basic@dmabuf-fence igt@drv_module_reload@basic-reload igt@prime_vgem@basic-fence-read igt@vgem_basic@mmap igt@vgem_basic@setversion igt@prime_vgem@basic-wait-default igt@prime_self_import@basic-with_two_bos igt@prime_vgem@basic-gtt igt@prime_vgem@basic-busy-default igt@vgem_basic@dmabuf-export
Created attachment 136008 [details] kern_log_SNB_flip_timeouts It seems that problem is evolving, now I also get vblank warns and failed tests. Test igt@prime_vgem@basic-fence-flip, output: IGT-Version: 1.20-g1db1246 (x86_64) (Linux: 4.15.0-rc2-drm-intel-qa-ww49-commit-1a0d67e+ x86_64) Stack trace: #0 [__igt_fail_assert+0x101] #1 [test_flip+0x425] #2 [__real_main757+0x17df] #3 [main+0x23] #4 [__libc_start_main+0xf1] #5 [_start+0x29] #6 [<unknown>+0x29] Subtest basic-fence-flip: FAIL (41.076s) Test requirement not met in function __real_main757, file prime_vgem.c:849: Test requirement: vgem_fence_has_flag(vgem, WIP_VGEM_FENCE_NOTIMEOUT) (prime_vgem:22664) CRITICAL: Test assertion failure function test_flip, file prime_vgem.c:738: (prime_vgem:22664) CRITICAL: Failed assertion: (drmModePageFlip(i915, crtc_id, fb_id[i], 0x01, &fb_id[i])) == 0 (prime_vgem:22664) CRITICAL: Last errno: 16, Device or resource busy Subtest basic-fence-flip failed. **** DEBUG **** (prime_vgem:22664) ioctl-wrappers-DEBUG: Test requirement passed: has_modifiers (prime_vgem:22664) ioctl-wrappers-DEBUG: Test requirement passed: has_modifiers (prime_vgem:22664) DEBUG: Test requirement passed: (crtc_id = set_fb_on_crtc(i915, 0, &bo[0], fb_id[0])) (prime_vgem:22664) CRITICAL: Test assertion failure function test_flip, file prime_vgem.c:738: (prime_vgem:22664) CRITICAL: Failed assertion: (drmModePageFlip(i915, crtc_id, fb_id[i], 0x01, &fb_id[i])) == 0 (prime_vgem:22664) CRITICAL: Last errno: 16, Device or resource busy (prime_vgem:22664) igt-core-INFO: Stack trace: (prime_vgem:22664) igt-core-INFO: #0 [__igt_fail_assert+0x101] (prime_vgem:22664) igt-core-INFO: #1 [test_flip+0x425] (prime_vgem:22664) igt-core-INFO: #2 [__real_main757+0x17df] (prime_vgem:22664) igt-core-INFO: #3 [main+0x23] (prime_vgem:22664) igt-core-INFO: #4 [__libc_start_main+0xf1] (prime_vgem:22664) igt-core-INFO: #5 [_start+0x29] (prime_vgem:22664) igt-core-INFO: #6 [<unknown>+0x29] **** END **** Dmesg: [ 2744.036434] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2754.276424] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:47:pipe B] flip_done timed out [ 2764.516433] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:48:VGA-1] flip_done timed out [ 2774.756428] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:56:DP-1] flip_done timed out [ 2784.996434] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:28:primary A] flip_done timed out [ 2795.236431] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:38:primary B] flip_done timed out [ 2805.476431] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2815.716425] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:47:pipe B] flip_done timed out [ 2825.956434] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2836.196428] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:48:VGA-1] flip_done timed out [ 2846.436431] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:28:primary A] flip_done timed out [ 2846.568413] ------------[ cut here ]------------ [ 2846.568415] vblank wait timed out on crtc 0 [ 2846.568465] WARNING: CPU: 2 PID: 22664 at drivers/gpu/drm/drm_vblank.c:1073 drm_wait_one_vblank+0x18d/0x1a0 [drm] [ 2846.568466] Modules linked in: vgem ip6table_filter ip6_tables iptable_filter snd_hda_codec_hdmi intel_rapl snd_hda_codec_realtek x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_generic coretemp kvm_intel kvm snd_hda_intel snd_hda_codec irqbypass snd_hda_core snd_hwdep crct10dif_pclmul crc32_pclmul snd_pcm ghash_clmulni_intel pcbc snd_seq_midi snd_seq_midi_event binfmt_misc snd_rawmidi aesni_intel aes_x86_64 crypto_simd nls_iso8859_1 glue_helper cryptd snd_seq dcdbas intel_cstate snd_seq_device intel_rapl_perf snd_timer serio_raw snd mei_me mei soundcore shpchp lpc_ich mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 i915 i2c_algo_bit prime_numbers drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm e1000e psmouse ahci libahci ptp pps_core video [ 2846.568489] CPU: 2 PID: 22664 Comm: prime_vgem Tainted: G U W 4.15.0-rc2-drm-intel-qa-ww49-commit-1a0d67e+ #1 [ 2846.568490] Hardware name: Dell Inc. OptiPlex 990/06D7TR, BIOS A19 08/26/2015 [ 2846.568491] task: 00000000c9bea46b task.stack: 0000000056e5785a [ 2846.568498] RIP: 0010:drm_wait_one_vblank+0x18d/0x1a0 [drm] [ 2846.568499] RSP: 0018:ffffa534e1de7a30 EFLAGS: 00010282 [ 2846.568500] RAX: 0000000000000000 RBX: ffff8fd190220000 RCX: 0000000000000006 [ 2846.568500] RDX: 0000000000000007 RSI: 0000000000000092 RDI: ffff8fd19d28dcd0 [ 2846.568501] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000018ce5 [ 2846.568501] R10: 0000000000000000 R11: 0000000000018ce5 R12: 0000000000000000 [ 2846.568502] R13: 0000000000000000 R14: 000000000001edc8 R15: ffff8fd19aa87c08 [ 2846.568503] FS: 00007fa7c4e62880(0000) GS:ffff8fd19d280000(0000) knlGS:0000000000000000 [ 2846.568504] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 2846.568504] CR2: 0000559639fd53a8 CR3: 0000000415a6a001 CR4: 00000000000606e0 [ 2846.568505] Call Trace: [ 2846.568511] ? wait_woken+0x80/0x80 [ 2846.568532] ironlake_crtc_enable+0x792/0xbf0 [i915] [ 2846.568552] intel_update_crtc+0x3d/0x90 [i915] [ 2846.568570] intel_update_crtcs+0x57/0x70 [i915] [ 2846.568587] intel_atomic_commit_tail+0x39d/0xdd0 [i915] [ 2846.568605] ? intel_atomic_commit_ready+0x44/0x4c [i915] [ 2846.568622] intel_atomic_commit+0x1fd/0x2a0 [i915] [ 2846.568627] drm_atomic_helper_set_config+0x5c/0x90 [drm_kms_helper] [ 2846.568630] ? mutex_lock+0xe/0x30 [ 2846.568637] __drm_mode_set_config_internal+0x61/0x110 [drm] [ 2846.568645] drm_mode_setcrtc+0x45b/0x5b0 [drm] [ 2846.568653] ? drm_mode_getencoder+0x11d/0x180 [drm] [ 2846.568659] ? drm_mode_getcrtc+0x170/0x170 [drm] [ 2846.568666] drm_ioctl_kernel+0x65/0xb0 [drm] [ 2846.568672] drm_ioctl+0x2e5/0x3e0 [drm] [ 2846.568678] ? drm_mode_getcrtc+0x170/0x170 [drm] [ 2846.568681] do_vfs_ioctl+0x9f/0x5f0 [ 2846.568684] ? handle_mm_fault+0xc4/0x1b0 [ 2846.568686] ? __do_page_fault+0x287/0x500 [ 2846.568687] SyS_ioctl+0x74/0x80 [ 2846.568688] entry_SYSCALL_64_fastpath+0x1e/0x81 [ 2846.568690] RIP: 0033:0x7fa7c33728b7 [ 2846.568690] RSP: 002b:00007fff92d552f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 2846.568691] RAX: ffffffffffffffda RBX: 00007fa7c3636b00 RCX: 00007fa7c33728b7 [ 2846.568692] RDX: 00007fff92d55430 RSI: 00000000c06864a2 RDI: 0000000000000004 [ 2846.568692] RBP: 0000000000044010 R08: 0000000000000300 R09: 0000000000000000 [ 2846.568693] R10: 00007fa7c4e1d010 R11: 0000000000000246 R12: 0000000000045000 [ 2846.568693] R13: 0000000000044010 R14: 0000000000001000 R15: 000000000000270c [ 2846.568694] Code: 0a ff ff ff e8 85 b9 dc cb 48 89 e6 4c 89 ff e8 2a e6 e0 cb 45 85 ed 0f 85 14 ff ff ff 89 ee 48 c7 c7 38 f5 2c c0 e8 c3 b6 dc cb <0f> ff e9 ff fe ff ff 66 90 66 2e 0f 1f 84 00 00 00 00 00 66 66 [ 2846.568711] ---[ end trace 85c462e7447a738a ]--- [ 2856.676430] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2866.916428] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2877.156393] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:28:primary A] flip_done timed out [ 2887.396429] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2897.636432] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2907.876430] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:47:pipe B] flip_done timed out [ 2918.116433] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:48:VGA-1] flip_done timed out [ 2928.356402] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CONNECTOR:56:DP-1] flip_done timed out [ 2938.596433] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:28:primary A] flip_done timed out [ 2948.836435] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:38:primary B] flip_done timed out [ 2948.964414] ------------[ cut here ]------------ [ 2948.964417] vblank wait timed out on crtc 0 [ 2948.964467] WARNING: CPU: 6 PID: 22664 at drivers/gpu/drm/drm_vblank.c:1073 drm_wait_one_vblank+0x18d/0x1a0 [drm] [ 2948.964467] Modules linked in: vgem ip6table_filter ip6_tables iptable_filter snd_hda_codec_hdmi intel_rapl snd_hda_codec_realtek x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_generic coretemp kvm_intel kvm snd_hda_intel snd_hda_codec irqbypass snd_hda_core snd_hwdep crct10dif_pclmul crc32_pclmul snd_pcm ghash_clmulni_intel pcbc snd_seq_midi snd_seq_midi_event binfmt_misc snd_rawmidi aesni_intel aes_x86_64 crypto_simd nls_iso8859_1 glue_helper cryptd snd_seq dcdbas intel_cstate snd_seq_device intel_rapl_perf snd_timer serio_raw snd mei_me mei soundcore shpchp lpc_ich mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 i915 i2c_algo_bit prime_numbers drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm e1000e psmouse ahci libahci ptp pps_core video [ 2948.964493] CPU: 6 PID: 22664 Comm: prime_vgem Tainted: G U W 4.15.0-rc2-drm-intel-qa-ww49-commit-1a0d67e+ #1 [ 2948.964493] Hardware name: Dell Inc. OptiPlex 990/06D7TR, BIOS A19 08/26/2015 [ 2948.964494] task: 00000000c9bea46b task.stack: 0000000056e5785a [ 2948.964501] RIP: 0010:drm_wait_one_vblank+0x18d/0x1a0 [drm] [ 2948.964501] RSP: 0018:ffffa534e1de7b80 EFLAGS: 00010282 [ 2948.964502] RAX: 0000000000000000 RBX: ffff8fd190220000 RCX: 0000000000000006 [ 2948.964503] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff8fd19d38dcd0 [ 2948.964504] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000018d92 [ 2948.964504] R10: 0000000000000000 R11: 0000000000018d92 R12: 0000000000000000 [ 2948.964505] R13: 0000000000000000 R14: 00000000000205b4 R15: ffff8fd19aa87c08 [ 2948.964506] FS: 00007fa7c4e62880(0000) GS:ffff8fd19d380000(0000) knlGS:0000000000000000 [ 2948.964506] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 2948.964507] CR2: 000055e8ce40bbb8 CR3: 0000000415a6a006 CR4: 00000000000606e0 [ 2948.964508] Call Trace: [ 2948.964514] ? wait_woken+0x80/0x80 [ 2948.964535] ironlake_crtc_enable+0x792/0xbf0 [i915] [ 2948.964556] intel_update_crtc+0x3d/0x90 [i915] [ 2948.964574] intel_update_crtcs+0x57/0x70 [i915] [ 2948.964591] intel_atomic_commit_tail+0x39d/0xdd0 [i915] [ 2948.964609] ? intel_atomic_commit_ready+0x44/0x4c [i915] [ 2948.964626] intel_atomic_commit+0x1fd/0x2a0 [i915] [ 2948.964630] restore_fbdev_mode_atomic+0x1ab/0x220 [drm_kms_helper] [ 2948.964634] drm_fb_helper_restore_fbdev_mode_unlocked+0x45/0x90 [drm_kms_helper] [ 2948.964653] intel_fbdev_restore_mode+0x30/0x80 [i915] [ 2948.964667] i915_driver_lastclose+0xa/0x10 [i915] [ 2948.964674] drm_lastclose+0x34/0xf0 [drm] [ 2948.964680] drm_release+0x2b6/0x370 [drm] [ 2948.964682] __fput+0xd5/0x210 [ 2948.964685] task_work_run+0x80/0xa0 [ 2948.964687] exit_to_usermode_loop+0xbb/0xc0 [ 2948.964688] syscall_return_slowpath+0x81/0xa0 [ 2948.964690] entry_SYSCALL_64_fastpath+0x7f/0x81 [ 2948.964691] RIP: 0033:0x7fa7c408b730 [ 2948.964692] RSP: 002b:00007fff92d55b28 EFLAGS: 00000246 ORIG_RAX: 0000000000000003 [ 2948.964693] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007fa7c408b730 [ 2948.964694] RDX: 0000000000000005 RSI: 00007fff92d55a20 RDI: 0000000000000005 [ 2948.964694] RBP: 0000000000624a00 R08: 00000000018dc460 R09: 0000000000000000 [ 2948.964695] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001 [ 2948.964695] R13: 00007fa7c3637c20 R14: 0000000000000000 R15: 0000000000000000 [ 2948.964696] Code: 0a ff ff ff e8 85 b9 dc cb 48 89 e6 4c 89 ff e8 2a e6 e0 cb 45 85 ed 0f 85 14 ff ff ff 89 ee 48 c7 c7 38 f5 2c c0 e8 c3 b6 dc cb <0f> ff e9 ff fe ff ff 66 90 66 2e 0f 1f 84 00 00 00 00 00 66 66 [ 2948.964713] ---[ end trace 85c462e7447a738b ]--- [ 2959.076434] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:37:pipe A] flip_done timed out [ 2969.316427] [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR* [CRTC:47:pipe B] flip_done timed out Other test failed with the vbland and/or flip timeout messages: igt@kms_pipe_crc_basic@suspend-read-crc-pipe-b igt@prime_busy@basic-wait-before-default igt@prime_busy@basic-before-default igt@prime_busy@basic-after-default
Created attachment 136009 [details] Test_failed_with_flip_timeouts_and_vblank_warns
This seems to be caused by our own configuration. Checking.
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.