Bug 77297

Summary: [i965 bisected]CallTrace: WARNING: CPU: 0 PID: 1335 at drivers/gpu/drm/i915/intel_display.c:768 intel_wait_for_vblank+0x159/0x17c [i915]() while running kms_flip_absolute-wf_vblank
Product: DRI Reporter: Guo Jinxian <jinxianx.guo>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: CLOSED FIXED QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: highest CC: intel-gfx-bugs, orion, yi.sun
Version: unspecified   
Hardware: Other   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:
Attachments:
Description Flags
intel_display.c:768 dmesg
none
dmesg
none
dmesg
none
dmesg none

Description Guo Jinxian 2014-04-11 02:21:13 UTC
Created attachment 97204 [details]
intel_display.c:768 dmesg

System Environment:
--------------------------
Platform: ILK SNB IVB
kernel:   (drm-intel-nightly)35dc7c8af75a3e5ae52a5469786602ce083a6368

Bug detailed description:
----------------------------
CallTrace: WARNING: CPU: 0 PID: 1335 at drivers/gpu/drm/i915/intel_display.c:768 intel_wait_for_vblank+0x159/0x17c [i915]() while running kms_flip_absolute-wf_vblank on ILK and SNB, the same issue is able to reproduced on IVB while running igt_kms_flip_bcs-wf_vblank-vs-dpms.

15ba30b2ecea353a5f0d5951f21805ba0714d889 is the first bad commit
commit 15ba30b2ecea353a5f0d5951f21805ba0714d889
Author: Jesse Barnes 

Call Trace:
----------------------------
[    1.276787] WARNING: CPU: 0 PID: 1335 at drivers/gpu/drm/i915/intel_display.c:768 intel_wait_for_vblank+0x159/0x17c [i915]()
[    1.276787] vblank wait timed out
[    1.276789] Modules linked in: i915(+) video button drm_kms_helper drm
[    1.276791] CPU: 0 PID: 1335 Comm: udevd Not tainted 3.14.0_drm-intel-nightly_35dc7c_20140410+ #1511
[    1.276791] Hardware name: Dell Inc. OptiPlex 990/0DXWW6, BIOS A02 02/26/2011
[    1.276794]  00000000 c1696876 f81fdd0c c102c7ff f81bc8a7 f4e98000 00070040 000016c0
[    1.276795]  fffb710a c102c87a 00000009 f4db5a38 f81fdd0c f4db5a50 f81bc8a7 f81fc580
[    1.276797]  00000300 f81fdd0c f4e98000 00000001 f4e98000 f5a34000 f81c1936 f53505b4
[    1.276797] Call Trace:
[    1.276800]  [<c1696876>] ? dump_stack+0x3e/0x4e
[    1.276804]  [<c102c7ff>] ? warn_slowpath_common+0x61/0x74
[    1.276821]  [<f81bc8a7>] ? intel_wait_for_vblank+0x159/0x17c [i915]
[    1.276822]  [<c102c87a>] ? warn_slowpath_fmt+0x29/0x2d
[    1.276836]  [<f81bc8a7>] ? intel_wait_for_vblank+0x159/0x17c [i915]
[    1.276851]  [<f81c1936>] ? ironlake_crtc_enable+0x1fd/0x9ce [i915]
[    1.276865]  [<f81c4121>] ? __intel_set_mode+0xf10/0xff7 [i915]
[    1.276880]  [<f81c5af7>] ? intel_set_mode+0x11/0x25 [i915]
[    1.276894]  [<f81c654e>] ? intel_crtc_set_config+0x646/0x8f1 [i915]
[    1.276900]  [<f808d2c4>] ? drm_mode_set_config_internal+0x39/0x9b [drm]
[    1.276901]  [<f80bf2f2>] ? drm_fb_helper_restore_fbdev_mode+0x7c/0x91 [drm_kms_helper]
[    1.276915]  [<f81b9cd7>] ? lpt_disable_clkout_dp+0xa1/0xa1 [i915]
[    1.276916]  [<f80bf60a>] ? drm_fb_helper_set_par+0x3a/0x59 [drm_kms_helper]
[    1.276918]  [<c12bb1de>] ? fbcon_init+0x2c3/0x3a3
[    1.276920]  [<c12fef23>] ? visual_init+0x97/0xe9
[    1.276922]  [<c1300674>] ? do_bind_con_driver+0x16e/0x275
[    1.276923]  [<c1300887>] ? do_take_over_console+0x10c/0x134
[    1.276924]  [<c12ba9a2>] ? do_fbcon_takeover+0x49/0x88
[    1.276926]  [<c169db0a>] ? notifier_call_chain+0x20/0x42
[    1.276927]  [<c10421b0>] ? __blocking_notifier_call_chain+0x34/0x4b
[    1.276928]  [<c10421d0>] ? blocking_notifier_call_chain+0x9/0xc
[    1.276930]  [<c12b32fa>] ? register_framebuffer+0x1f6/0x248
[    1.276932]  [<f80bedf2>] ? drm_fb_helper_initial_config+0x355/0x3d4 [drm_kms_helper]
[    1.276951]  [<f81e5a52>] ? i915_driver_load+0x950/0xbba [i915]
[    1.276953]  [<c1690579>] ? klist_node_init+0x3a/0x3d
[    1.276954]  [<c1690601>] ? klist_add_tail+0x16/0x30
[    1.276956]  [<c1316e47>] ? device_add+0x45d/0x467
[    1.276957]  [<c100303a>] ? show_stack_log_lvl+0x6d/0x8a
[    1.276961]  [<f808935a>] ? drm_minor_register+0xf5/0x149 [drm]
[    1.276965]  [<f8089410>] ? drm_dev_register+0x62/0xc3 [drm]
[    1.276969]  [<f808b046>] ? drm_get_pci_dev+0xd7/0x16a [drm]
[    1.276971]  [<c12a513d>] ? pci_device_probe+0x4e/0x95
[    1.276972]  [<c1318803>] ? driver_probe_device+0x79/0x168
[    1.276973]  [<c1318936>] ? __driver_attach+0x44/0x5f
[    1.276975]  [<c131761f>] ? bus_for_each_dev+0x37/0x61
[    1.276976]  [<c13184d6>] ? driver_attach+0x11/0x13
[    1.276976]  [<c13188f2>] ? driver_probe_device+0x168/0x168
[    1.276977]  [<c1318213>] ? bus_add_driver+0xad/0x167
[    1.276978]  [<c1318d8a>] ? driver_register+0x6b/0x99
[    1.276979]  [<f8216000>] ? 0xf8215fff
[    1.276980]  [<c10003de>] ? do_one_initcall+0x6d/0xe7
[    1.276981]  [<c169db0a>] ? notifier_call_chain+0x20/0x42
[    1.276982]  [<c10421b9>] ? __blocking_notifier_call_chain+0x3d/0x4b
[    1.276984]  [<c1070be3>] ? load_module+0x140b/0x16e5
[    1.276985]  [<c169dae2>] ? __do_page_fault+0x46c/0x46c
[    1.276986]  [<c1070f2f>] ? SyS_init_module+0x72/0x8a
[    1.276988]  [<c169f5da>] ? sysenter_do_call+0x12/0x22
[    1.276989] ---[ end trace 6042e7a2be61cb36 ]---
[    1.297824] usb 1-1: new high-speed USB device number 2 using ehci-pci

Reproduce steps:
---------------------------- 
1.  ./kms_flip --run-subtest absolute-wf_vblank
Comment 1 Jani Nikula 2014-04-11 05:57:01 UTC
commit 15ba30b2ecea353a5f0d5951f21805ba0714d889
Author: Jesse Barnes <jbarnes@virtuousgeek.org>
Date:   Fri Apr 4 16:12:09 2014 -0700

    drm/i915: warn when a vblank wait times out
    
    This always indicates a bug somewhere.
    
    Signed-off-by: Jesse Barnes <jbarnes@virtuousgeek.org>
    Signed-off-by: Daniel Vetter <daniel.vetter@ffwll.ch>
Comment 2 Daniel Vetter 2014-04-11 12:49:09 UTC
Jesse promised to take care of these as they happen!
Comment 3 Daniel Vetter 2014-04-15 16:46:08 UTC
Well it annoyed me too much, so patches to fix this are on the m-l now:

http://patchwork.freedesktop.org/patch/24280/
http://patchwork.freedesktop.org/patch/24281/

Please test these two (need to be applied in the right order).
Comment 4 Daniel Vetter 2014-04-15 21:27:13 UTC
Should be resolved with latest dinq:

commit a5c4d7bc187bd13bc11ac06bb4ea3a0d4001aa4d
Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
Date:   Fri Mar 7 18:32:13 2014 +0200

    drm/i915: Disable/enable planes as the first/last thing during modeset on ILK+

and

commit be6a6f8ec707f2e446e445ad4b8cc93cc85d5d54
Author: Daniel Vetter <daniel.vetter@ffwll.ch>
Date:   Tue Apr 15 18:41:22 2014 +0200

    drm/i915: Don't vblank wait on ilk-ivb after pipe enable
Comment 5 Guo Jinxian 2014-04-23 02:03:57 UTC
Tested on latest -testing(0e078e452654cf09f6342452a3ddeebc1f6edf96) and -nightly(1e771b84e47085ef9b6efea1321e7cb5a8b2c065), this bug still can be reproduce both after boot and after run testdisplay testing. Please check dmesg in attachment for details. Thanks.
Comment 6 Guo Jinxian 2014-04-23 02:05:02 UTC
Created attachment 97792 [details]
dmesg
Comment 7 Guo Jinxian 2014-04-24 03:03:36 UTC
Some other subcase below are able to reproduce this issue too

plane-position-covered-pipe-B-plane-1
plane-position-covered-pipe-B-plane-2
plane-position-covered-pipe-C-plane-1
plane-position-covered-pipe-C-plane-2
plane-position-hole-pipe-B-plane-1
plane-position-hole-pipe-B-plane-2
plane-position-hole-pipe-C-plane-1
plane-position-hole-pipe-C-plane-2
Comment 8 Guo Jinxian 2014-04-24 03:05:30 UTC
Some subcases of kms_plane below are able to reproduce this issue too:

plane-position-covered-pipe-B-plane-1
plane-position-covered-pipe-B-plane-2
plane-position-covered-pipe-C-plane-1
plane-position-covered-pipe-C-plane-2
plane-position-hole-pipe-B-plane-1
plane-position-hole-pipe-B-plane-2
plane-position-hole-pipe-C-plane-1
plane-position-hole-pipe-C-plane-2
Comment 9 Gavin Hindman 2014-05-09 19:26:48 UTC
Who owns the next step on this issue?  We have a customer escalating the resulting timeout delay in their resume path.

Updating importance accordingly.
Comment 10 Jesse Barnes 2014-05-12 16:11:35 UTC
The latest dmesg has a vblank timeout warning from dp_link_down.  But that should only happen on IBX platforms, the wait is gone from all others.  Does your tree have

commit 93c9c19b3d259a76fc2efa4b8f2478dc9f339bee
Author: Jesse Barnes <jbarnes@virtuousgeek.org>
Date:   Fri Apr 11 14:25:41 2014 -0700

    drm/i915: remove unexplained vblank wait in the DP off code

?
Comment 11 Daniel Vetter 2014-05-13 15:17:48 UTC
Please retest with latest -nightly, it should be fixed on all platforms now.
Comment 12 Guo Jinxian 2014-05-15 03:23:34 UTC
(In reply to comment #11)
> Please retest with latest -nightly, it should be fixed on all platforms now.

This bug still able to reproduced on latest -nightly(2be456541ea41728002ccca2de5235f48d14326e) on ILK.
Comment 13 Guo Jinxian 2014-05-15 03:24:00 UTC
Created attachment 99053 [details]
dmesg
Comment 14 Daniel Vetter 2014-05-15 14:25:31 UTC
This is a different calltrace. This bug is about intel_wait_for_vblank

But the calltrace you've spotted is intel_wait_for_pipe_off

That's a different bug, see https://bugs.freedesktop.org/show_bug.cgi?id=54687

The dmesg triage rules in the bug filing BKM tell you how to do this.
Comment 15 Guo Jinxian 2014-05-16 02:00:52 UTC
verified
Comment 16 Guang Yang 2014-05-16 02:39:16 UTC
(In reply to comment #13)
> Created attachment 99053 [details]
> dmesg
Jinxian, please file a new bug if we find new Call trace in this dmesg.
Comment 17 Guo Jinxian 2014-05-16 03:44:27 UTC
(In reply to comment #16)
> (In reply to comment #13)
> > Created attachment 99053 [details]
> > dmesg
> Jinxian, please file a new bug if we find new Call trace in this dmesg.

Done, Bug 78763 was created to track intel_wait_for_pipe_off issue.
Comment 18 Daniel Vetter 2014-05-19 09:20:52 UTC
(In reply to comment #16)
> (In reply to comment #13)
> > Created attachment 99053 [details]
> > dmesg
> Jinxian, please file a new bug if we find new Call trace in this dmesg.

Erhm, I' clearly said that the new backtrace is a dupe of an existing bug. I've fixed it up.
Comment 19 Guo Jinxian 2014-06-16 08:36:26 UTC
Created attachment 101151 [details]
dmesg

This bug still able to reproduce on latest -nightly() on ILK while run cases below:
igt/kms_flip/absolute-wf_vblank
igt/kms_flip/absolute-wf_vblank-interruptible


Dmesg shows:
[  141.708735] WARNING: CPU: 0 PID: 3985 at drivers/gpu/drm/i915/intel_display.c:893 intel_wait_for_vblank+0x156/0x179 [i915]()
[  141.708738] vblank wait timed out
[  141.708740] Modules linked in: dm_mod snd_hda_codec_hdmi snd_hda_codec_idt snd_hda_codec_generic iTCO_wdt iTCO_vendor_support ppdev dcdbas pcspkr firewire_ohci i2c_i801 snd_hda_intel lpc_ich snd_hda_controller mfd_core snd_hda_codec snd_hwdep firewire_core crc_itu_t snd_pcm snd_timer snd soundcore wmi battery parport_pc parport tpm_tis tpm ac acpi_cpufreq joydev i915 video button drm_kms_helper drm
[  141.708776] CPU: 0 PID: 3985 Comm: kms_flip Not tainted 3.15.0-rc8_drm-intel-nightly_b438e8_20140616+ #3594
[  141.708778] Hardware name: Dell Inc. Latitude E6510/0JKDHD, BIOS A05 08/10/2010
[  141.708781]  00000000 c16e77a2 f4ebbc90 c102e6c8 f858528f c24d0000 00071040 000003a2
[  141.708788]  fffd94ec c102e743 00000009 f4ebbc90 f85cb42d f4ebbca8 f858528f f85c9ae4
[  141.708794]  0000037d f85cb42d c24d0000 f596bc80 8004400c c2429400 f859c6e2 c2487000
[  141.708801] Call Trace:
[  141.708810]  [<c16e77a2>] ? dump_stack+0x3e/0x4e
[  141.708815]  [<c102e6c8>] ? warn_slowpath_common+0x65/0x78
[  141.708843]  [<f858528f>] ? intel_wait_for_vblank+0x156/0x179 [i915]
[  141.708847]  [<c102e743>] ? warn_slowpath_fmt+0x29/0x2d
[  141.708866]  [<f858528f>] ? intel_wait_for_vblank+0x156/0x179 [i915]
[  141.708882]  [<f859c6e2>] ? intel_dp_link_down+0x167/0x169 [i915]
[  141.708897]  [<f859c77c>] ? g4x_post_disable_dp+0x19/0xa5 [i915]
[  141.708912]  [<f858a385>] ? ironlake_crtc_disable+0xaa/0x6f8 [i915]
[  141.708920]  [<f804c33d>] ? drm_ut_debug_printk+0x2c/0x30 [drm]
[  141.708936]  [<f858b78d>] ? __intel_set_mode+0x1a8/0x1024 [i915]
[  141.708953]  [<f858c0dc>] ? __intel_set_mode+0xaf7/0x1024 [i915]
[  141.708956]  [<c10593ff>] ? up+0x9/0x2a
[  141.708959]  [<c10621f9>] ? console_unlock+0x309/0x33d
[  141.708962]  [<c16e4ca8>] ? printk+0x16/0x1a
[  141.708976]  [<f858e0a8>] ? intel_set_mode+0x11/0x25 [i915]
[  141.708990]  [<f858eb37>] ? intel_crtc_set_config+0x62f/0x92c [i915]
[  141.708993]  [<c16eb129>] ? __ww_mutex_lock+0xe/0x6d
[  141.709000]  [<f8050267>] ? drm_mode_set_config_internal+0x39/0x8a [drm]
[  141.709007]  [<f805047b>] ? drm_framebuffer_remove+0x70/0xd6 [drm]
[  141.709014]  [<f8053528>] ? drm_mode_rmfb+0xa7/0xcd [drm]
[  141.709021]  [<f8053481>] ? drm_mode_addfb2+0x27/0x27 [drm]
[  141.709026]  [<f80488cf>] ? drm_ioctl+0x22e/0x35f [drm]
[  141.709033]  [<f8053481>] ? drm_mode_addfb2+0x27/0x27 [drm]
[  141.709036]  [<c10b2a4e>] ? release_pages+0x13d/0x153
[  141.709039]  [<c10cd1f8>] ? free_pages_and_swap_cache+0x5e/0x6c
[  141.709042]  [<c10c0923>] ? tlb_flush_mmu_free+0x17/0x2b
[  141.709044]  [<c10c0b0e>] ? tlb_finish_mmu+0x9/0x27
[  141.709046]  [<c10c5152>] ? unmap_region+0x99/0xa1
[  141.709051]  [<f80486a1>] ? drm_copy_field+0x47/0x47 [drm]
[  141.709056]  [<c10e5431>] ? do_vfs_ioctl+0x3fa/0x444
[  141.709062]  [<f804994c>] ? drm_gem_vm_close+0x1f/0x3c [drm]
[  141.709064]  [<c10c5190>] ? remove_vma+0x36/0x3b
[  141.709066]  [<c10c6693>] ? do_munmap+0x1eb/0x206
[  141.709068]  [<c10e54bd>] ? SyS_ioctl+0x42/0x6d
[  141.709072]  [<c16f1dac>] ? sysenter_do_call+0x12/0x22
Comment 20 Guo Jinxian 2014-09-02 05:21:31 UTC
This failure is able to reproduce on ILK on latest -fixes(2a592bec50994597716c633191ed6bf7af14defc) while running tests below:
igt/kms_cursor_crc/cursor-128-onscreen
igt/kms_cursor_crc/cursor-256-onscreen
igt/kms_cursor_crc/cursor-64-onscreen
igt/kms_cursor_crc/cursor-size-change


[root@x-e6510 tests]# ./kms_cursor_crc --run-subtest cursor-size-change
IGT-Version: 1.7-gf473a55 (i686) (Linux: 3.17.0-rc2_drm-intel-fixes_2a592b_20140902+ i686)
Beginning cursor-size-change on pipe A, connector eDP-1

cursor-size-change on pipe A, connector eDP-1: PASSED

Beginning cursor-size-change on pipe B, connector eDP-1

cursor-size-change on pipe B, connector eDP-1: PASSED

Subtest cursor-size-change: SUCCESS
[root@x-e6510 tests]# dmesg -r|egrep "<[1-4]>"|grep drm
<4>[ 2110.919802] WARNING: CPU: 2 PID: 4067 at drivers/gpu/drm/i915/intel_display.c:902 intel_wait_for_vblank+0x156/0x179 [i915]()
<4>[ 2110.919805] Modules linked in: iTCO_wdt b43 mac80211 cfg80211 iTCO_vendor_support ppdev rfkill dm_mod snd_hda_codec_hdmi snd_hda_codec_idt snd_hda_codec_generic dcdbas pcspkr i2c_i801 lpc_ich mfd_core firewire_ohci snd_hda_intel firewire_core snd_hda_controller crc_itu_t snd_hda_codec snd_hwdep snd_pcm snd_timer bcma snd soundcore wmi parport_pc parport battery tpm_tis tpm ac acpi_cpufreq joydev i915 button video drm_kms_helper drm cfbfillrect cfbimgblt cfbcopyarea
<4>[ 2110.919836] CPU: 2 PID: 4067 Comm: kms_cursor_crc Tainted: G        W      3.17.0-rc2_drm-intel-fixes_2a592b_20140902+ #2054
<4>[ 2110.920101]  [<f805019d>] ? drm_mode_set_config_internal+0x39/0x8a [drm]
<4>[ 2110.920112]  [<f80503b1>] ? drm_framebuffer_remove+0x70/0xd6 [drm]
<4>[ 2110.920123]  [<f805367a>] ? drm_mode_rmfb+0xa7/0xcd [drm]
<4>[ 2110.920133]  [<f80535d3>] ? drm_mode_addfb2+0x27/0x27 [drm]
<4>[ 2110.920141]  [<f8049dba>] ? drm_ioctl+0x233/0x35c [drm]
<4>[ 2110.920152]  [<f80535d3>] ? drm_mode_addfb2+0x27/0x27 [drm]
<4>[ 2110.920172]  [<f8049b87>] ? drm_getstats+0xe/0xe [drm]
Comment 21 Daniel Vetter 2014-11-14 08:30:23 UTC
Presumed fixed

commit 08aff3fe26ae7a0d6f302ac2e1b7e2eb9933cd42
Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
Date:   Mon Aug 18 22:16:09 2014 +0300

    drm/i915: Move DP port disable to post_disable for pch platforms

At least we don't have a g4x_post_disable_dp any more, so defintely need a new backtrace if this is still an issue.
Comment 22 Orion Poplawski 2014-11-14 23:34:00 UTC
Can you state what kernel release(s) this is in?  Thanks.
Comment 23 Guo Jinxian 2014-11-17 03:48:14 UTC
The failure unable to reproduce on latest -nightly(3b6da75500fb10e59dfb153eba9845c05f8d82d6)


[root@x-ivb9 tests]# ./kms_flip --run-subtest absolute-wf_vblank
IGT-Version: 1.8-gaa63fc7 (x86_64) (Linux: 3.18.0-rc4_drm-intel-nightly_3b6da7_20141116_debug+ x86_64)
Using monotonic timestamps
Beginning absolute-wf_vblank on crtc 8, connector 18
  1024x768 60 1024 1048 1184 1344 768 771 777 806 0xa 0x40 65000
............................................................
absolute-wf_vblank on crtc 8, connector 18: PASSED

Beginning absolute-wf_vblank on crtc 12, connector 18
  1024x768 60 1024 1048 1184 1344 768 771 777 806 0xa 0x40 65000
............................................................
absolute-wf_vblank on crtc 12, connector 18: PASSED

Beginning absolute-wf_vblank on crtc 16, connector 18
  1024x768 60 1024 1048 1184 1344 768 771 777 806 0xa 0x40 65000
............................................................
absolute-wf_vblank on crtc 16, connector 18: PASSED

Subtest absolute-wf_vblank: SUCCESS (30.382s)
Comment 24 Jari Tahvanainen 2017-02-10 08:41:13 UTC
Closing (>2 years) old Verified+fixed.

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.