Re: (radeon?) WARNING: drivers/gpu/drm/drm_irq.c:1195 drm_vblank_put (v4.11-12441-g56868a4)

[Daniel Vetter]

On Thu, May 18, 2017 at 07:43:51PM +0300, Tommi Rantala wrote:
> 2017-05-11 5:51 GMT+03:00 Michel Dänzer <michel@xxxxxxxxxxx>:
> > On 11/05/17 04:33 AM, Tommi Rantala wrote:
> >> Complete kernel log:
> >> http://termbin.com/dzy5
> >>
> >> [  249.952546] ------------[ cut here ]------------
> >> [  249.952593] WARNING: CPU: 5 PID: 0 at
> >> /home/ttrantal/git/linux/drivers/gpu/drm/drm_irq.c:1195
> >> drm_vblank_put+0xc4/0x120 [drm]
> >> [  249.952596] Modules linked in: fuse tun bridge stp llc af_packet
> >> pl2303 usbserial shpchp acpi_cpufreq binfmt_misc amdgpu hid_generic
> >> uhci_hcd radeon 3c59x mii tg3 ehci_pci ehci_hcd i2c_algo_bit
> >> drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm
> >> agpgart unix autofs4
> >> [  249.952675] CPU: 5 PID: 0 Comm: swapper/5 Tainted: G        W
> >> 4.11.0+ #4
> >> [  249.952678] Hardware name: Hewlett-Packard HP xw6600
> >> Workstation/0A9Ch, BIOS 786F4 v01.46 09/20/2012
> >> [  249.952681] task: ffff88080aea0000 task.stack: ffffc900031b0000
> >> [  249.952695] RIP: 0010:drm_vblank_put+0xc4/0x120 [drm]
> >> [  249.952698] RSP: 0018:ffff88080f003d70 EFLAGS: 00010046
> >> [  249.952703] RAX: 0000000000000000 RBX: ffff880801d53000 RCX: 0000000000000000
> >> [  249.952706] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88080a4ac000
> >> [  249.952709] RBP: ffff88080f003d88 R08: 0000000000000001 R09: 0000000000000003
> >> [  249.952711] R10: ffff88080f003d08 R11: 00000000001da540 R12: ffff88080a4ac000
> >> [  249.952714] R13: 0000000000000000 R14: 0000000000000086 R15: ffff8808019a0000
> >> [  249.952717] FS:  0000000000000000(0000) GS:ffff88080f000000(0000)
> >> knlGS:0000000000000000
> >> [  249.952720] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >> [  249.952723] CR2: 00007f8bcc3a5810 CR3: 0000000808789000 CR4: 00000000000006e0
> >> [  249.952726] Call Trace:
> >> [  249.952731]  <IRQ>
> >> [  249.952746]  drm_crtc_vblank_put+0x1b/0x30 [drm]
> >> [  249.952813]  radeon_crtc_handle_flip+0xdc/0x140 [radeon]
> >> [  249.952843]  si_irq_process+0x610/0x1e90 [radeon]
> >> [  249.952872]  radeon_driver_irq_handler_kms+0x39/0xc0 [radeon]
> >> [  249.952881]  __handle_irq_event_percpu+0x60/0x580
> >> [  249.952887]  handle_irq_event_percpu+0x20/0x90
> >> [  249.952892]  handle_irq_event+0x46/0xb0
> >> [  249.952897]  handle_edge_irq+0x13d/0x370
> >> [  249.952903]  handle_irq+0x66/0x210
> >> [  249.952908]  ? __local_bh_enable+0x34/0x50
> >> [  249.952914]  do_IRQ+0x7e/0x1b0
> >> [  249.952920]  common_interrupt+0x95/0x95
> >
> > Weird, not sure how this could happen. Can you bisect?
> 
> Hi,
> 
> Bisection points to this (also manually applied commit 9739e74646
> while testing, got kernel oops otherwise):
> 
> commit 29dc0d1de18239cf3ef8bab578b8321ed340d81c
> Author: Daniel Vetter <daniel.vetter@xxxxxxxx>
> Date:   Wed Mar 22 22:50:49 2017 +0100
> 
>     drm: Roll out acquire context for the page_flip ioctl
> 
>     Again just prep work.
> 
>     Reviewed-by: Harry Wentland <harry.wentland@xxxxxxx>
>     Signed-off-by: Daniel Vetter <daniel.vetter@xxxxxxxxx>
>     Link: http://patchwork.freedesktop.org/patch/msgid/20170322215058.8671-11-daniel.vetter@xxxxxxxx
> 
> 
> I'm also seeing some more warnings in this version:

Yeah I think the locking stuff we've fixed, at least if you don't see it
in 4.12 it should be all good. And I think I spotted the bug you've
bisected to, patch is on dri-devel, pls test.

Thanks for the bug report.
-Daniel

> 
> 
> May 18 19:21:55 xw6600 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp14s0:
> link becomes ready
> May 18 19:21:57 xw6600 kernel: ------------[ cut here ]------------
> May 18 19:21:57 xw6600 kernel: WARNING: CPU: 5 PID: 4607 at
> /home/ttrantal/git/linux/drivers/gpu/drm/drm_modeset_lock.c:193
> drm_modeset_lock_crtc+0xe5/0x100 [drm]
> May 18 19:21:57 xw6600 kernel: Modules linked in: tun bridge stp llc
> af_packet pl2303 usbserial shpchp acpi_cpufreq binfmt_misc amdgpu
> hid_generic uhci_hcd radeon 3c59x mii i2c_algo_bit drm_kms_helper tg3
> syscopyarea sysfillrect sysimgblt
> May 18 19:21:57 xw6600 kernel: CPU: 5 PID: 4607 Comm: gnome-shell Not
> tainted 4.11.0-rc3-00944-g29dc0d1-dirty #30
> May 18 19:21:57 xw6600 kernel: Hardware name: Hewlett-Packard HP
> xw6600 Workstation/0A9Ch, BIOS 786F4 v01.46 09/20/2012
> May 18 19:21:57 xw6600 kernel: Call Trace:
> May 18 19:21:57 xw6600 kernel:  dump_stack+0x69/0x9b
> May 18 19:21:57 xw6600 kernel:  __warn+0xff/0x140
> May 18 19:21:57 xw6600 kernel:  warn_slowpath_null+0x18/0x20
> May 18 19:21:57 xw6600 kernel:  drm_modeset_lock_crtc+0xe5/0x100 [drm]
> May 18 19:21:57 xw6600 kernel:  drm_mode_cursor_common+0xbd/0x200 [drm]
> May 18 19:21:57 xw6600 kernel:  drm_mode_cursor_ioctl+0x3c/0x40 [drm]
> May 18 19:21:57 xw6600 kernel:  drm_ioctl+0x3ea/0x870 [drm]
> May 18 19:21:57 xw6600 kernel:  ? drm_mode_setplane+0x1a0/0x1a0 [drm]
> May 18 19:21:57 xw6600 kernel:  ? trace_hardirqs_on_caller+0x1ad/0x2c0
> May 18 19:21:57 xw6600 kernel:  ? trace_hardirqs_on+0xd/0x10
> May 18 19:21:57 xw6600 kernel:  radeon_drm_ioctl+0x6e/0x110 [radeon]
> May 18 19:21:57 xw6600 kernel:  do_vfs_ioctl+0xac/0x9d0
> May 18 19:21:57 xw6600 kernel:  ? security_file_ioctl+0x4c/0x80
> May 18 19:21:57 xw6600 kernel:  SyS_ioctl+0x74/0x80
> May 18 19:21:57 xw6600 kernel:  entry_SYSCALL_64_fastpath+0x18/0xad
> May 18 19:21:57 xw6600 kernel: RIP: 0033:0x7f98d9e52787
> May 18 19:21:57 xw6600 kernel: RSP: 002b:00007ffe12ca5938 EFLAGS:
> 00000246 ORIG_RAX: 0000000000000010
> May 18 19:21:57 xw6600 kernel: RAX: ffffffffffffffda RBX:
> 0000000000000046 RCX: 00007f98d9e52787
> May 18 19:21:57 xw6600 kernel: RDX: 00007ffe12ca5970 RSI:
> 00000000c01c64a3 RDI: 0000000000000008
> May 18 19:21:57 xw6600 kernel: RBP: 000000000000000b R08:
> 0000000000000000 R09: 0000560c5a5c9ac0
> May 18 19:21:57 xw6600 kernel: R10: 0000560c5a2988d8 R11:
> 0000000000000246 R12: 0000000000000008
> May 18 19:21:57 xw6600 kernel: R13: 0000000000000001 R14:
> 0000560c5c121d20 R15: 0000560c5a30ded0
> May 18 19:21:57 xw6600 kernel: ---[ end trace bbca894b04cf0b16 ]---
> May 18 19:21:57 xw6600 kernel: ------------[ cut here ]------------
> May 18 19:21:57 xw6600 kernel: WARNING: CPU: 5 PID: 4607 at
> /home/ttrantal/git/linux/drivers/gpu/drm/drm_modeset_lock.c:193
> drm_modeset_lock_crtc+0xe5/0x100 [drm]
> May 18 19:21:57 xw6600 kernel: Modules linked in: tun bridge stp llc
> af_packet pl2303 usbserial shpchp acpi_cpufreq binfmt_misc amdgpu
> hid_generic uhci_hcd radeon 3c59x mii i2c_algo_bit drm_kms_helper tg3
> syscopyarea sysfillrect sysimgblt
> May 18 19:21:57 xw6600 kernel: CPU: 5 PID: 4607 Comm: gnome-shell
> Tainted: G        W       4.11.0-rc3-00944-g29dc0d1-dirty #30
> May 18 19:21:57 xw6600 kernel: Hardware name: Hewlett-Packard HP
> xw6600 Workstation/0A9Ch, BIOS 786F4 v01.46 09/20/2012
> May 18 19:21:57 xw6600 kernel: Call Trace:
> May 18 19:21:57 xw6600 kernel:  dump_stack+0x69/0x9b
> May 18 19:21:57 xw6600 kernel:  __warn+0xff/0x140
> May 18 19:21:57 xw6600 kernel:  warn_slowpath_null+0x18/0x20
> May 18 19:21:57 xw6600 kernel:  drm_modeset_lock_crtc+0xe5/0x100 [drm]
> May 18 19:21:57 xw6600 kernel:  drm_mode_getcrtc+0x82/0x2c0 [drm]
> May 18 19:21:57 xw6600 kernel:  drm_ioctl+0x3ea/0x870 [drm]
> May 18 19:21:57 xw6600 kernel:  ? drm_crtc_create_fence+0x80/0x80 [drm]
> May 18 19:21:57 xw6600 kernel:  radeon_drm_ioctl+0x6e/0x110 [radeon]
> May 18 19:21:57 xw6600 kernel:  do_vfs_ioctl+0xac/0x9d0
> May 18 19:21:57 xw6600 kernel:  ? security_file_ioctl+0x4c/0x80
> May 18 19:21:57 xw6600 kernel:  SyS_ioctl+0x74/0x80
> May 18 19:21:57 xw6600 kernel:  entry_SYSCALL_64_fastpath+0x18/0xad
> May 18 19:21:57 xw6600 kernel: RIP: 0033:0x7f98d9e52787
> May 18 19:21:57 xw6600 kernel: RSP: 002b:00007ffe12ca53f8 EFLAGS:
> 00000246 ORIG_RAX: 0000000000000010
> May 18 19:21:57 xw6600 kernel: RAX: ffffffffffffffda RBX:
> 0000000000000046 RCX: 00007f98d9e52787
> May 18 19:21:57 xw6600 kernel: RDX: 00007ffe12ca5430 RSI:
> 00000000c06864a1 RDI: 0000000000000008
> May 18 19:21:57 xw6600 kernel: RBP: 0000560c5a2bbdb0 R08:
> 0000000000000008 R09: 0000560c5a48bf20
> May 18 19:21:57 xw6600 kernel: R10: 0000560c5a485330 R11:
> 0000000000000246 R12: 0000560c5b66a540
> May 18 19:21:57 xw6600 kernel: R13: 0000560c5bddaf90 R14:
> 0000560c5a88e5e0 R15: 00007ffe12c95c40
> May 18 19:21:57 xw6600 kernel: ---[ end trace bbca894b04cf0b17 ]---
> May 18 19:21:57 xw6600 kernel: ------------[ cut here ]------------
> May 18 19:21:57 xw6600 kernel: WARNING: CPU: 1 PID: 0 at
> /home/ttrantal/git/linux/drivers/gpu/drm/drm_irq.c:1186
> drm_vblank_put+0xec/0x150 [drm]
> May 18 19:21:57 xw6600 kernel: Modules linked in: tun bridge stp llc
> af_packet pl2303 usbserial shpchp acpi_cpufreq binfmt_misc amdgpu
> hid_generic uhci_hcd radeon 3c59x mii i2c_algo_bit drm_kms_helper tg3
> syscopyarea sysfillrect sysimgblt
> May 18 19:21:57 xw6600 kernel: CPU: 1 PID: 0 Comm: swapper/1 Tainted:
> G        W       4.11.0-rc3-00944-g29dc0d1-dirty #30
> May 18 19:21:57 xw6600 kernel: Hardware name: Hewlett-Packard HP
> xw6600 Workstation/0A9Ch, BIOS 786F4 v01.46 09/20/2012
> May 18 19:21:57 xw6600 kernel: Call Trace:
> May 18 19:21:57 xw6600 kernel:  <IRQ>
> May 18 19:21:57 xw6600 kernel:  dump_stack+0x69/0x9b
> May 18 19:21:57 xw6600 kernel:  __warn+0xff/0x140
> May 18 19:21:57 xw6600 kernel:  ? drm_vblank_count_and_time+0x9e/0x1b0 [drm]
> May 18 19:21:57 xw6600 kernel:  warn_slowpath_null+0x18/0x20
> May 18 19:21:57 xw6600 kernel:  drm_vblank_put+0xec/0x150 [drm]
> May 18 19:21:57 xw6600 kernel:  drm_crtc_vblank_put+0x1b/0x30 [drm]
> May 18 19:21:57 xw6600 kernel:  radeon_crtc_handle_flip+0xdc/0x140 [radeon]
> May 18 19:21:57 xw6600 kernel:  si_irq_process+0x611/0x1e90 [radeon]
> May 18 19:21:57 xw6600 kernel:  ? sched_clock_cpu+0x1c/0x160
> May 18 19:21:57 xw6600 kernel:  radeon_driver_irq_handler_kms+0x39/0xc0 [radeon]
> May 18 19:21:57 xw6600 kernel:  __handle_irq_event_percpu+0x60/0x590
> May 18 19:21:57 xw6600 kernel:  handle_irq_event_percpu+0x20/0x90
> May 18 19:21:57 xw6600 kernel:  handle_irq_event+0x46/0xb0
> May 18 19:21:57 xw6600 kernel:  handle_edge_irq+0x13d/0x370
> May 18 19:21:57 xw6600 kernel:  handle_irq+0x66/0x230
> May 18 19:21:57 xw6600 kernel:  ? __local_bh_enable+0x38/0x90
> May 18 19:21:57 xw6600 kernel:  ? _local_bh_enable+0x1d/0x60
> May 18 19:21:57 xw6600 kernel:  do_IRQ+0x7e/0x1b0
> May 18 19:21:57 xw6600 kernel:  common_interrupt+0x95/0x95
> May 18 19:21:57 xw6600 kernel: RIP: 0010:mwait_idle+0x9c/0x3a0
> May 18 19:21:57 xw6600 kernel: RSP: 0018:ffffc90003193e68 EFLAGS:
> 00000246 ORIG_RAX: ffffffffffffff4d
> May 18 19:21:57 xw6600 kernel: RAX: 0000000000000000 RBX:
> ffff88080ae71900 RCX: 0000000000000000
> May 18 19:21:57 xw6600 kernel: RDX: 0000000000000001 RSI:
> 0000000000000001 RDI: ffff88080ae71900
> May 18 19:21:57 xw6600 kernel: RBP: ffffc90003193e98 R08:
> 0000000000000006 R09: 0000000000000000
> May 18 19:21:57 xw6600 kernel: R10: 0000000000000000 R11:
> 0000000000000000 R12: ffff88080ae71900
> May 18 19:21:57 xw6600 kernel: R13: 0000000000000001 R14:
> ffffffff839cbd28 R15: 0000000000000000
> May 18 19:21:57 xw6600 kernel:  </IRQ>
> May 18 19:21:57 xw6600 kernel:  ? mwait_idle+0x93/0x3a0
> May 18 19:21:57 xw6600 kernel:  arch_cpu_idle+0xa/0x10
> May 18 19:21:57 xw6600 kernel:  default_idle_call+0x24/0x40
> May 18 19:21:57 xw6600 kernel:  do_idle+0x154/0x230
> May 18 19:21:57 xw6600 kernel:  cpu_startup_entry+0x18/0x20
> May 18 19:21:57 xw6600 kernel:  start_secondary+0x159/0x1f0
> May 18 19:21:57 xw6600 kernel:  start_cpu+0x14/0x14
> May 18 19:21:57 xw6600 kernel: ---[ end trace bbca894b04cf0b18 ]---
> May 18 19:21:57 xw6600 kernel: ------------[ cut here ]------------
> 
> 
> -Tommi
> _______________________________________________
> dri-devel mailing list
> dri-devel@xxxxxxxxxxxxxxxxxxxxx
> https://lists.freedesktop.org/mailman/listinfo/dri-devel

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch