Re: WARNING: CPU: 0 PID: 3634 at drivers/gpu/drm/drm_irq.c:1141 drm_wait_one_vblank

From: Daniel Vetter
Date: Tue Jun 30 2015 - 10:31:17 EST

Next message: Jan Kara: "Re: [PATCH 26/51] writeback: let balance_dirty_pages() work on the matching cgroup bdi_writeback"
Previous message: Sasha Levin: "Linux 3.18.17"
In reply to: Michal Hocko: "WARNING: CPU: 0 PID: 3634 at drivers/gpu/drm/drm_irq.c:1141 drm_wait_one_vblank"
Next in thread: Michal Hocko: "Re: WARNING: CPU: 0 PID: 3634 at drivers/gpu/drm/drm_irq.c:1141 drm_wait_one_vblank"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Tue, Jun 30, 2015 at 01:57:07PM +0200, Michal Hocko wrote:
> Hi,
> I am getting the following warning when I switch to the text console
> from X. I do not know when this has started because I have noticed
> that only now (in 4.1 kernel). I can try some older kernels if this is
> useful.
>
> I have tried to instrument drm_wait_one_vblank and dump drm_vblank_count
> before the wait_event and the value when it returns (see the diff below)
> and it seems to be increasing with new switching to the text console:
> $ dmesg | grep XXX
> [ 6.531908] XXX: last:36
> [ 6.545852] XXX: drm_vblank_count:37
> [ 9.038658] XXX: last:186
> [ 9.051332] XXX: drm_vblank_count:187
> [ 9.051424] XXX: last:187
> [ 9.068036] XXX: drm_vblank_count:188
> [ 16.962193] XXX: last:660
> [ 16.968683] XXX: drm_vblank_count:661
> [ 30.592874] XXX: last:1476
> [ 30.598656] XXX: drm_vblank_count:1477
> [ 30.598768] XXX: last:1477
> [ 30.615339] XXX: drm_vblank_count:1478
> [ 37.313338] XXX: last:1879
> [ 37.330102] XXX: drm_vblank_count:1880
> [ 39.726809] XXX: last:2023
> [ 39.735265] XXX: drm_vblank_count:2024
> [ 39.735375] XXX: last:2024
> [ 39.752094] XXX: drm_vblank_count:2025
> [ 60.842401] XXX: last:3287
> [ 60.848437] XXX: drm_vblank_count:3288
> [ 62.149546] XXX: last:3365
> [ 62.151277] XXX: drm_vblank_count:3366
> [ 62.151411] XXX: last:3366
> [ 62.249376] XXX: drm_vblank_count:3366
> [ 92.198305] XXX: last:5160
> [ 92.297091] XXX: drm_vblank_count:5160
> [ 93.822331] XXX: last:5253
> [ 93.922153] XXX: drm_vblank_count:5253
> [ 93.922424] XXX: last:5254
> [ 94.022213] XXX: drm_vblank_count:5254
> [ 100.877802] XXX: last:5665
> [ 100.974740] XXX: drm_vblank_count:5665
>
> I am sorry about the lack of information in this report but I am really
> not sure what might be helpful. I can only tell that I haven't observed
> anything wrong going on after the warning so it might be harmless.
>
> Let me know what kind of information might be helpful.

Looks like the vblank is actually running, just the wakeup somehow doesn't
happen in time. What machine is this (lspci -nn)? Also please boot with
drm.debug=0xe and grab dmesg after this happens for the first time.
logfile will be large, you might need to increase the buffer size with
log_buf_len or grab
it from the hd.

Also what happens when you increase the timeout to 1000 (just to make sure
it's not just a silly delay somewhere). Also have you any special features
like psr, fbc or something similar enabled?

Really surprising since we have all the checks in place that should ensure
that the vblank stuff is indeed up&running.
-Daniel

>
> [ 7322.444556] ------------[ cut here ]------------
> [ 7322.444569] WARNING: CPU: 0 PID: 3634 at drivers/gpu/drm/drm_irq.c:1141 drm_wait_one_vblank+0x144/0x16f [drm]()
> [ 7322.444570] vblank wait timed out on crtc 0
> [ 7322.444586] Modules linked in: i915 fbcon cfbfillrect bitblit softcursor cfbimgblt font i2c_algo_bit cfbcopyarea drm_kms_helper drm fb fbdev binfmt_misc snd_hda_codec_hdmi uvcvideo videobuf2_vmalloc videobuf2_memops snd_hda_codec_idt i2c_i801 snd_hda_codec_generic snd_hda_intel snd_hda_controller videobuf2_core arc4 snd_hda_codec snd_hda_core snd_pcm_oss v4l2_common snd_mixer_oss videodev iwldvm media i2c_core mac80211 video iwlwifi backlight snd_pcm sdhci_pci sdhci mmc_core cfg80211 snd_timer snd
> [ 7322.444588] CPU: 0 PID: 3634 Comm: Xorg Not tainted 4.1.0 #587
> [ 7322.444589] Hardware name: Dell Inc. Latitude E6320/09PHH9, BIOS A08 10/18/2011
> [ 7322.444591] 0000000000000009 ffff8800c5bb7888 ffffffff8151b709 0000000080000000
> [ 7322.444592] ffff8800c5bb78d8 ffff8800c5bb78c8 ffffffff8104550a ffff8800c5bb7958
> [ 7322.444593] ffffffffa02d414e 0000000000000000 0000000000000000 ffff8800c58d7000
> [ 7322.444594] Call Trace:
> [ 7322.444599] [<ffffffff8151b709>] dump_stack+0x4f/0x7b
> [ 7322.444601] [<ffffffff8104550a>] warn_slowpath_common+0xa1/0xbb
> [ 7322.444608] [<ffffffffa02d414e>] ? drm_wait_one_vblank+0x144/0x16f [drm]
> [ 7322.444609] [<ffffffff8104556a>] warn_slowpath_fmt+0x46/0x48
> [ 7322.444611] [<ffffffff81075b7d>] ? finish_wait+0x59/0x62
> [ 7322.444617] [<ffffffffa02d414e>] drm_wait_one_vblank+0x144/0x16f [drm]
> [ 7322.444618] [<ffffffff81075c9d>] ? wait_woken+0x76/0x76
> [ 7322.444624] [<ffffffffa02d4196>] drm_crtc_wait_one_vblank+0x1d/0x21 [drm]
> [ 7322.444628] [<ffffffffa0331baa>] drm_plane_helper_commit+0x1b3/0x240 [drm_kms_helper]
> [ 7322.444631] [<ffffffffa0331cfe>] drm_plane_helper_update+0xc7/0xd6 [drm_kms_helper]
> [ 7322.444652] [<ffffffffa03cd9a5>] intel_crtc_set_config+0x95e/0xc4f [i915]
> [ 7322.444661] [<ffffffffa02db020>] drm_mode_set_config_internal+0x5c/0xe8 [drm]
> [ 7322.444666] [<ffffffffa0338ae3>] drm_fb_helper_pan_display+0xa2/0xd8 [drm_kms_helper]
> [ 7322.444668] [<ffffffffa02be312>] fb_pan_display+0xee/0x131 [fb]
> [ 7322.444670] [<ffffffffa0353254>] bit_update_start+0x20/0x43 [bitblit]
> [ 7322.444672] [<ffffffffa035fa24>] fbcon_switch+0x3b7/0x438 [fbcon]
> [ 7322.444674] [<ffffffff812f7f0d>] redraw_screen+0x112/0x1e3
> [ 7322.444676] [<ffffffff812f0711>] complete_change_console+0x3e/0xc7
> [ 7322.444678] [<ffffffff812f1684>] vt_ioctl+0xeea/0x117f
> [ 7322.444680] [<ffffffff812e7538>] tty_ioctl+0xa01/0xa74
> [ 7322.444682] [<ffffffff81065154>] ? preempt_count_sub+0xc6/0xd3
> [ 7322.444684] [<ffffffff81156204>] do_vfs_ioctl+0x377/0x425
> [ 7322.444685] [<ffffffff8115e2a9>] ? __fget+0x70/0x7b
> [ 7322.444686] [<ffffffff811562f6>] SyS_ioctl+0x44/0x63
> [ 7322.444688] [<ffffffff81520197>] system_call_fastpath+0x12/0x6a
> [ 7322.444689] ---[ end trace 9d3b554e7f553db3 ]---
> [ 7326.066994] ------------[ cut here ]------------
>
> Debugging patch
> --
> diff --git a/drivers/gpu/drm/drm_irq.c b/drivers/gpu/drm/drm_irq.c
> index af9662e58272..446f4ce02a9d 100644
> --- a/drivers/gpu/drm/drm_irq.c
> +++ b/drivers/gpu/drm/drm_irq.c
> @@ -1126,17 +1126,19 @@ EXPORT_SYMBOL(drm_crtc_vblank_put);
> void drm_wait_one_vblank(struct drm_device *dev, int crtc)
> {
> int ret;
> - u32 last;
> + u32 last, l;
>
> ret = drm_vblank_get(dev, crtc);
> if (WARN(ret, "vblank not available on crtc %i, ret=%i\n", crtc, ret))
> return;
>
> last = drm_vblank_count(dev, crtc);
> + pr_info("XXX: last:%u\n", last);
>
> ret = wait_event_timeout(dev->vblank[crtc].queue,
> - last != drm_vblank_count(dev, crtc),
> + last != (l = drm_vblank_count(dev, crtc)),
> msecs_to_jiffies(100));
> + pr_info("XXX: drm_vblank_count:%u\n", l);
>
> WARN(ret == 0, "vblank wait timed out on crtc %i\n", crtc);
>
> --
> Michal Hocko
> SUSE Labs

--
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Jan Kara: "Re: [PATCH 26/51] writeback: let balance_dirty_pages() work on the matching cgroup bdi_writeback"
Previous message: Sasha Levin: "Linux 3.18.17"
In reply to: Michal Hocko: "WARNING: CPU: 0 PID: 3634 at drivers/gpu/drm/drm_irq.c:1141 drm_wait_one_vblank"
Next in thread: Michal Hocko: "Re: WARNING: CPU: 0 PID: 3634 at drivers/gpu/drm/drm_irq.c:1141 drm_wait_one_vblank"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]