[ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Sander Eikelenboom]

Hi,

I'm using a webcam (logitech) supported by the uvcvideo module to capture video.
Previously once in a while I would get the "uvcvideo: Failed to resubmit video URB (-27).", but the grabbing continued without a problem.
Now the video grabbing program (motion) seems to lock due to some nested lock if i interpret it right.
Additional problem is that i don't really know what kernel version was still OK, so can't help with that info.

This is on a vanilla 3.4 RC kernel latest commit: c629eaf8392b676b4f83c3dc344e66402bfeec92

--
Sander







[ 3696.753490] ehci_hcd 0000:09:00.1: request ffff880016091400 would overflow (3923+31 >= 3936)
[ 3696.753494] uvcvideo: Failed to resubmit video URB (-27).
[ 3696.753563] ehci_hcd 0000:09:00.1: request ffff880016091800 would overflow (3922+31 >= 3936)
[ 3696.753566] uvcvideo: Failed to resubmit video URB (-27).
[ 3696.753609] ehci_hcd 0000:09:00.1: request ffff880016090800 would overflow (3922+31 >= 3936)
[ 3696.753611] uvcvideo: Failed to resubmit video URB (-27).
[ 3696.753645] ehci_hcd 0000:09:00.1: request ffff880016090c00 would overflow (3922+31 >= 3936)
[ 3696.753647] uvcvideo: Failed to resubmit video URB (-27).
[ 3696.753656] ehci_hcd 0000:09:00.1: request ffff880016091000 would overflow (3922+31 >= 3936)
[ 3696.753657] uvcvideo: Failed to resubmit video URB (-27).
[ 3960.758154] INFO: task motion:7776 blocked for more than 120 seconds.
[ 3960.758168] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3960.758174] motion          D 0000000000000201     0  7776      1 0x00000000
[ 3960.758183]  ffff8800239d9b68 0000000000000216 ffffea0000a50018 ffffffff810a451b
[ 3960.758192]  ffff88002392cf60 0000000000012600 ffff8800239d9fd8 ffff8800239d8010
[ 3960.758200]  0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600
[ 3960.758209] Call Trace:
[ 3960.758219]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 3960.758226]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
[ 3960.758232]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
[ 3960.758238]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 3960.758244]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 3960.758250]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
[ 3960.758257]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30
[ 3960.758264]  [<ffffffff817f8e84>] schedule+0x24/0x70
[ 3960.758269]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
[ 3960.758275]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
[ 3960.758281]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
[ 3960.758287]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 3960.758292]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
[ 3960.758298]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
[ 3960.758304]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
[ 3960.758310]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
[ 3960.758316]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
[ 3960.758322]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
[ 3960.758327]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 3960.758333]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 3960.758338]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 3960.758344]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
[ 3960.758349]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 3960.758740]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
[ 3960.758745]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
[ 3960.758751]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
[ 3960.758756]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 3960.758762]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
[ 3960.758768]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
[ 3960.758773]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
[ 3960.758778]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
[ 3960.758784] 1 lock held by motion/7776:
[ 3960.758788]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4080.758504] INFO: task motion:7776 blocked for more than 120 seconds.
[ 4080.758518] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4080.758524] motion          D 0000000000000201     0  7776      1 0x00000000
[ 4080.758532]  ffff8800239d9b68 0000000000000216 ffffea0000a50018 ffffffff810a451b
[ 4080.758540]  ffff88002392cf60 0000000000012600 ffff8800239d9fd8 ffff8800239d8010
[ 4080.758547]  0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600
[ 4080.758555] Call Trace:
[ 4080.758564]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4080.758570]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
[ 4080.758576]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
[ 4080.758581]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4080.758587]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4080.758592]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
[ 4080.758597]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30
[ 4080.758603]  [<ffffffff817f8e84>] schedule+0x24/0x70
[ 4080.758608]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
[ 4080.758613]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
[ 4080.758618]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
[ 4080.758624]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4080.758629]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
[ 4080.758633]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
[ 4080.758640]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
[ 4080.758645]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
[ 4080.758651]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
[ 4080.758655]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
[ 4080.758661]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4080.758666]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4080.758670]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4080.758675]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
[ 4080.758680]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4080.759167]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
[ 4080.759173]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
[ 4080.759179]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
[ 4080.759184]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4080.759191]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
[ 4080.759196]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
[ 4080.759201]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
[ 4080.759208]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
[ 4080.759214] 1 lock held by motion/7776:
[ 4080.759217]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4200.759699] INFO: task motion:7776 blocked for more than 120 seconds.
[ 4200.759713] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4200.759720] motion          D 0000000000000201     0  7776      1 0x00000000
[ 4200.759729]  ffff8800239d9b68 0000000000000216 ffffea0000a50018 ffffffff810a451b
[ 4200.759738]  ffff88002392cf60 0000000000012600 ffff8800239d9fd8 ffff8800239d8010
[ 4200.759746]  0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600
[ 4200.759754] Call Trace:
[ 4200.759764]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4200.759771]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
[ 4200.759777]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
[ 4200.759783]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4200.759789]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4200.759795]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
[ 4200.759801]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30
[ 4200.759808]  [<ffffffff817f8e84>] schedule+0x24/0x70
[ 4200.759813]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
[ 4200.759819]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
[ 4200.759825]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
[ 4200.759831]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4200.759837]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
[ 4200.759842]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
[ 4200.759848]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
[ 4200.759855]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
[ 4200.759862]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
[ 4200.759868]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
[ 4200.759873]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4200.759879]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4200.759884]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4200.759890]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
[ 4200.759895]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4200.760376]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
[ 4200.760382]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
[ 4200.760389]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
[ 4200.760394]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4200.760401]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
[ 4200.760407]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
[ 4200.760412]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
[ 4200.760417]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
[ 4200.760423] 1 lock held by motion/7776:
[ 4200.760427]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4320.761186] INFO: task motion:7776 blocked for more than 120 seconds.
[ 4320.761199] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4320.761206] motion          D 0000000000000201     0  7776      1 0x00000000
[ 4320.761215]  ffff8800239d9b68 0000000000000216 ffffea0000a50018 ffffffff810a451b
[ 4320.761224]  ffff88002392cf60 0000000000012600 ffff8800239d9fd8 ffff8800239d8010
[ 4320.761232]  0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600
[ 4320.761241] Call Trace:
[ 4320.761250]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4320.761258]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
[ 4320.761264]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
[ 4320.761269]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4320.761276]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4320.761281]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
[ 4320.761288]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30
[ 4320.761295]  [<ffffffff817f8e84>] schedule+0x24/0x70
[ 4320.761300]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
[ 4320.761306]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
[ 4320.761312]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
[ 4320.761318]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4320.761323]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
[ 4320.761329]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
[ 4320.761335]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
[ 4320.761342]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
[ 4320.761348]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
[ 4320.761353]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
[ 4320.761359]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4320.761365]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4320.761370]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4320.761375]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
[ 4320.761380]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4320.761880]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
[ 4320.761885]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
[ 4320.761893]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
[ 4320.761898]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4320.761905]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
[ 4320.761910]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
[ 4320.761915]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
[ 4320.761921]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
[ 4320.761926] 1 lock held by motion/7776:
[ 4320.761930]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4440.761549] INFO: task motion:7776 blocked for more than 120 seconds.
[ 4440.761563] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4440.761570] motion          D 0000000000000201     0  7776      1 0x00000000
[ 4440.761579]  ffff8800239d9b68 0000000000000216 ffffea0000a50018 ffffffff810a451b
[ 4440.761587]  ffff88002392cf60 0000000000012600 ffff8800239d9fd8 ffff8800239d8010
[ 4440.761596]  0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600
[ 4440.761604] Call Trace:
[ 4440.761618]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4440.761626]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
[ 4440.761633]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
[ 4440.761639]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4440.761645]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4440.761651]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
[ 4440.761657]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30
[ 4440.761665]  [<ffffffff817f8e84>] schedule+0x24/0x70
[ 4440.761670]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
[ 4440.761676]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
[ 4440.761682]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
[ 4440.761688]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
[ 4440.761693]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
[ 4440.761699]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
[ 4440.761705]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
[ 4440.761711]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
[ 4440.761717]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
[ 4440.761722]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
[ 4440.761728]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4440.761734]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4440.761739]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
[ 4440.761745]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
[ 4440.761750]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
[ 4440.761984]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
[ 4440.761990]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
[ 4440.761996]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
[ 4440.762001]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
[ 4440.762007]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
[ 4440.762013]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
[ 4440.762018]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
[ 4440.762023]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
[ 4440.762029] 1 lock held by motion/7776:
[ 4440.762032]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Laurent Pinchart]

Hi Sander,

On Saturday 28 April 2012 22:02:46 Sander Eikelenboom wrote:
> Hi,
> 
> I'm using a webcam (logitech) supported by the uvcvideo module to capture
> video. Previously once in a while I would get the "uvcvideo: Failed to
> resubmit video URB (-27).", but the grabbing continued without a problem.
> Now the video grabbing program (motion) seems to lock due to some nested
> lock if i interpret it right.

The uvcvideo driver doesn't use nested locks, this is "just" a normal locking 
issue. The mutex_lock_nested() call in the backtrace comes from lock debugging 
support in your kernel.

A quick look at the code doesn't reveal any obvious locking issue. Do you have 
multiple threads accessing the device at the same time ?

> Additional problem is that i don't really know what kernel version was still
> OK, so can't help with that info.
> 
> This is on a vanilla 3.4 RC kernel latest commit:
> c629eaf8392b676b4f83c3dc344e66402bfeec92
>
> [ 3696.753490] ehci_hcd 0000:09:00.1: request ffff880016091400 would
> overflow (3923+31 >= 3936) [ 3696.753494] uvcvideo: Failed to resubmit
> video URB (-27).
> [ 3696.753563] ehci_hcd 0000:09:00.1: request ffff880016091800 would
> overflow (3922+31 >= 3936) [ 3696.753566] uvcvideo: Failed to resubmit
> video URB (-27).
> [ 3696.753609] ehci_hcd 0000:09:00.1: request ffff880016090800 would
> overflow (3922+31 >= 3936) [ 3696.753611] uvcvideo: Failed to resubmit
> video URB (-27).
> [ 3696.753645] ehci_hcd 0000:09:00.1: request ffff880016090c00 would
> overflow (3922+31 >= 3936) [ 3696.753647] uvcvideo: Failed to resubmit
> video URB (-27).
> [ 3696.753656] ehci_hcd 0000:09:00.1: request ffff880016091000 would
> overflow (3922+31 >= 3936) [ 3696.753657] uvcvideo: Failed to resubmit
> video URB (-27).
> [ 3960.758154] INFO: task motion:7776 blocked for more than 120 seconds.
> [ 3960.758168] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message. [ 3960.758174] motion          D 0000000000000201     0  7776
>      1 0x00000000 [ 3960.758183]  ffff8800239d9b68 0000000000000216
> ffffea0000a50018 ffffffff810a451b [ 3960.758192]  ffff88002392cf60
> 0000000000012600 ffff8800239d9fd8 ffff8800239d8010 [ 3960.758200] 
> 0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600 [
> 3960.758209] Call Trace:
> [ 3960.758219]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
> [ 3960.758226]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
> [ 3960.758232]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
> [ 3960.758238]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
> [ 3960.758244]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
> [ 3960.758250]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
> [ 3960.758257]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30

The backtrace isn't valid, making this a bit harder to debug. Making compiling 
the kernel with debug symbols would help here. Could you also please enable 
lockdep (CONFIG_LOCKDEP=y) if not done already ?

> [ 3960.758264]  [<ffffffff817f8e84>] schedule+0x24/0x70
> [ 3960.758269]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
> [ 3960.758275]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
> [ 3960.758281]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
> [ 3960.758287]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
> [ 3960.758292]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
> [ 3960.758298]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
> [ 3960.758304]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
> [ 3960.758310]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
> [ 3960.758316]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
> [ 3960.758322]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
> [ 3960.758327]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
> [ 3960.758333]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
> [ 3960.758338]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
> [ 3960.758344]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
> [ 3960.758349]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
> [ 3960.758740]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
> [ 3960.758745]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
> [ 3960.758751]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
> [ 3960.758756]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
> [ 3960.758762]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
> [ 3960.758768]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
> [ 3960.758773]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
> [ 3960.758778]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
> [ 3960.758784] 1 lock held by motion/7776:
> [ 3960.758788]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>]

It looks like the driver tries to take the lock queue->mutex lock a second 
time. I don't see any code path that could lead to that.

-- 
Regards,

Laurent Pinchart

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Sander Eikelenboom]

Hello Laurent / Mauro,

I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
I don't see anything specific to uvcvideo anymore, but i do get the possible circular locking dependency below.


--
Sander


[   96.257129] ======================================================
[   96.257129] [ INFO: possible circular locking dependency detected ]
[   96.257129] 3.4.0-rc5-20120506+ #4 Not tainted
[   96.257129] -------------------------------------------------------
[   96.257129] motion/2289 is trying to acquire lock:
[   96.257129]  (&dev->lock){+.+.+.}, at: [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
[   96.257129]
[   96.257129] but task is already holding lock:
[   96.257129]  (&mm->mmap_sem){++++++}, at: [<ffffffff81113cca>] sys_mmap_pgoff+0x1ca/0x220
[   96.257129]
[   96.257129] which lock already depends on the new lock.
[   96.257129]
[   96.257129]
[   96.257129] the existing dependency chain (in reverse order) is:
[   96.257129]
[   96.257129] -> #1 (&mm->mmap_sem){++++++}:
[   96.257129]        [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
[   96.257129]        [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
[   96.257129]        [<ffffffff81108cb8>] might_fault+0x68/0x90
[   96.257129]        [<ffffffff8156d2a1>] video_usercopy+0x1d1/0x4e0
[   96.257129]        [<ffffffff8156d5c0>] video_ioctl2+0x10/0x20
[   96.257129]        [<ffffffff8156c110>] v4l2_ioctl+0xb0/0x180
[   96.257129]        [<ffffffff8114dc3c>] do_vfs_ioctl+0x9c/0x580
[   96.257129]        [<ffffffff8114e16a>] sys_ioctl+0x4a/0x80
[   96.257129]        [<ffffffff81813039>] system_call_fastpath+0x16/0x1b
[   96.257129]
[   96.257129] -> #0 (&dev->lock){+.+.+.}:
[   96.257129]        [<ffffffff810aa529>] validate_chain+0x1259/0x1300
[   96.257129]        [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
[   96.257129]        [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
[   96.257129]        [<ffffffff8180e58c>] mutex_lock_interruptible_nested+0x5c/0x550
[   96.257129]        [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
[   96.257129]        [<ffffffff8111359a>] mmap_region+0x3da/0x5a0
[   96.257129]        [<ffffffff81113ab4>] do_mmap_pgoff+0x354/0x3a0
[   96.257129]        [<ffffffff81113ce9>] sys_mmap_pgoff+0x1e9/0x220
[   96.257129]        [<ffffffff81011ee9>] sys_mmap+0x29/0x30
[   96.257129]        [<ffffffff81813039>] system_call_fastpath+0x16/0x1b
[   96.257129]
[   96.257129] other info that might help us debug this:
[   96.257129]
[   96.257129]  Possible unsafe locking scenario:
[   96.257129]
[   96.257129]        CPU0                    CPU1
[   96.257129]        ----                    ----
[   96.257129]   lock(&mm->mmap_sem);
[   96.257129]                                lock(&dev->lock);
[   96.257129]                                lock(&mm->mmap_sem);
[   96.257129]   lock(&dev->lock);
[   96.257129]
[   96.257129]  *** DEADLOCK ***
[   96.257129]
[   96.257129] 1 lock held by motion/2289:
[   96.257129]  #0:  (&mm->mmap_sem){++++++}, at: [<ffffffff81113cca>] sys_mmap_pgoff+0x1ca/0x220
[   96.257129]
[   96.257129] stack backtrace:
[   96.257129] Pid: 2289, comm: motion Not tainted 3.4.0-rc5-20120506+ #4
[   96.257129] Call Trace:
[   96.257129]  [<ffffffff810a8fb6>] print_circular_bug+0x206/0x300
[   96.257129]  [<ffffffff810aa529>] validate_chain+0x1259/0x1300
[   96.257129]  [<ffffffff810a9417>] ? validate_chain+0x147/0x1300
[   96.257129]  [<ffffffff810ab773>] ? lock_release+0x113/0x260
[   96.257129]  [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
[   96.257129]  [<ffffffff810aa993>] ? __lock_acquire+0x3c3/0xc50
[   96.257129]  [<ffffffff8156024c>] ? tda18271_tune+0x71c/0x9c0
[   96.257129]  [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
[   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
[   96.257129]  [<ffffffff8180e58c>] mutex_lock_interruptible_nested+0x5c/0x550
[   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
[   96.257129]  [<ffffffff810a77ce>] ? mark_held_locks+0x9e/0x130
[   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
[   96.257129]  [<ffffffff811134de>] ? mmap_region+0x31e/0x5a0
[   96.257129]  [<ffffffff810a7900>] ? lockdep_trace_alloc+0xa0/0x130
[   96.257129]  [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
[   96.257129]  [<ffffffff8111359a>] mmap_region+0x3da/0x5a0
[   96.257129]  [<ffffffff81113ab4>] do_mmap_pgoff+0x354/0x3a0
[   96.257129]  [<ffffffff81113ce9>] sys_mmap_pgoff+0x1e9/0x220
[   96.257129]  [<ffffffff8132554e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[   96.257129]  [<ffffffff81011ee9>] sys_mmap+0x29/0x30








Monday, April 30, 2012, 1:05:27 AM, you wrote:

> Hi Sander,

> On Saturday 28 April 2012 22:02:46 Sander Eikelenboom wrote:
>> Hi,
>> 
>> I'm using a webcam (logitech) supported by the uvcvideo module to capture
>> video. Previously once in a while I would get the "uvcvideo: Failed to
>> resubmit video URB (-27).", but the grabbing continued without a problem.
>> Now the video grabbing program (motion) seems to lock due to some nested
>> lock if i interpret it right.

> The uvcvideo driver doesn't use nested locks, this is "just" a normal locking 
> issue. The mutex_lock_nested() call in the backtrace comes from lock debugging 
> support in your kernel.

> A quick look at the code doesn't reveal any obvious locking issue. Do you have 
> multiple threads accessing the device at the same time ?

>> Additional problem is that i don't really know what kernel version was still
>> OK, so can't help with that info.
>> 
>> This is on a vanilla 3.4 RC kernel latest commit:
>> c629eaf8392b676b4f83c3dc344e66402bfeec92
>>
>> [ 3696.753490] ehci_hcd 0000:09:00.1: request ffff880016091400 would
>> overflow (3923+31 >= 3936) [ 3696.753494] uvcvideo: Failed to resubmit
>> video URB (-27).
>> [ 3696.753563] ehci_hcd 0000:09:00.1: request ffff880016091800 would
>> overflow (3922+31 >= 3936) [ 3696.753566] uvcvideo: Failed to resubmit
>> video URB (-27).
>> [ 3696.753609] ehci_hcd 0000:09:00.1: request ffff880016090800 would
>> overflow (3922+31 >= 3936) [ 3696.753611] uvcvideo: Failed to resubmit
>> video URB (-27).
>> [ 3696.753645] ehci_hcd 0000:09:00.1: request ffff880016090c00 would
>> overflow (3922+31 >= 3936) [ 3696.753647] uvcvideo: Failed to resubmit
>> video URB (-27).
>> [ 3696.753656] ehci_hcd 0000:09:00.1: request ffff880016091000 would
>> overflow (3922+31 >= 3936) [ 3696.753657] uvcvideo: Failed to resubmit
>> video URB (-27).
>> [ 3960.758154] INFO: task motion:7776 blocked for more than 120 seconds.
>> [ 3960.758168] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
>> this message. [ 3960.758174] motion          D 0000000000000201     0  7776
>>      1 0x00000000 [ 3960.758183]  ffff8800239d9b68 0000000000000216
>> ffffea0000a50018 ffffffff810a451b [ 3960.758192]  ffff88002392cf60
>> 0000000000012600 ffff8800239d9fd8 ffff8800239d8010 [ 3960.758200] 
>> 0000000000012600 0000000000012600 ffff8800239d9fd8 0000000000012600 [
>> 3960.758209] Call Trace:
>> [ 3960.758219]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
>> [ 3960.758226]  [<ffffffff814e0048>] ? hub_suspend+0xf8/0x130
>> [ 3960.758232]  [<ffffffff814f0024>] ? usbdev_do_ioctl+0x194/0x1000
>> [ 3960.758238]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
>> [ 3960.758244]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
>> [ 3960.758250]  [<ffffffff8108d6cd>] ? sub_preempt_count+0x9d/0xd0
>> [ 3960.758257]  [<ffffffff815c02d2>] ? hdpvr_probe+0x6c2/0xa30

> The backtrace isn't valid, making this a bit harder to debug. Making compiling 
> the kernel with debug symbols would help here. Could you also please enable 
> lockdep (CONFIG_LOCKDEP=y) if not done already ?

>> [ 3960.758264]  [<ffffffff817f8e84>] schedule+0x24/0x70
>> [ 3960.758269]  [<ffffffff817f9363>] schedule_preempt_disabled+0x13/0x20
>> [ 3960.758275]  [<ffffffff817f77c7>] mutex_lock_nested+0x1a7/0x420
>> [ 3960.758281]  [<ffffffff815c62d2>] ? uvc_queue_enable+0x32/0xc0
>> [ 3960.758287]  [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0
>> [ 3960.758292]  [<ffffffff815c941f>] uvc_video_enable+0x12f/0x180
>> [ 3960.758298]  [<ffffffff815c7b55>] uvc_v4l2_do_ioctl+0x555/0x1190
>> [ 3960.758304]  [<ffffffff816c5668>] ? sock_update_classid+0xa8/0x120
>> [ 3960.758310]  [<ffffffff816c1d7e>] ? sock_sendmsg+0xee/0x120
>> [ 3960.758316]  [<ffffffff81561996>] video_usercopy+0x186/0x4c0
>> [ 3960.758322]  [<ffffffff815c7600>] ? uvc_v4l2_set_streamparm+0x190/0x190
>> [ 3960.758327]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
>> [ 3960.758333]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
>> [ 3960.758338]  [<ffffffff8108ba01>] ? get_parent_ip+0x11/0x50
>> [ 3960.758344]  [<ffffffff815c6bc4>] uvc_v4l2_ioctl+0x24/0x70
>> [ 3960.758349]  [<ffffffff810a451b>] ? __lock_acquire+0x5b/0xc00
>> [ 3960.758740]  [<ffffffff8116e474>] ? fsnotify+0x84/0x360
>> [ 3960.758745]  [<ffffffff81560850>] v4l2_ioctl+0xb0/0x180
>> [ 3960.758751]  [<ffffffff81145213>] do_vfs_ioctl+0x93/0x500
>> [ 3960.758756]  [<ffffffff810a559f>] ? lock_release+0xff/0x210
>> [ 3960.758762]  [<ffffffff81134ba7>] ? fget_light+0xd7/0x140
>> [ 3960.758768]  [<ffffffff81134b0b>] ? fget_light+0x3b/0x140
>> [ 3960.758773]  [<ffffffff811456ca>] sys_ioctl+0x4a/0x80
>> [ 3960.758778]  [<ffffffff817fb0f9>] system_call_fastpath+0x16/0x1b
>> [ 3960.758784] 1 lock held by motion/7776:
>> [ 3960.758788]  #0:  (&queue->mutex){......}, at: [<ffffffff815c62d2>]

> It looks like the driver tries to take the lock queue->mutex lock a second 
> time. I don't see any code path that could lead to that.




-- 
Best regards,
 Sander                            mailto:linux@eikelenboom.it

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Laurent Pinchart]

Hi Sanser,

On Sunday 06 May 2012 16:54:40 Sander Eikelenboom wrote:
> Hello Laurent / Mauro,
> 
> I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
> I don't see anything specific to uvcvideo anymore, but i do get the possible
> circular locking dependency below.

Thanks for the report.

We indeed have a serious issue there (CC'ing Hans Verkuil).

Hans, serializing both ioctl handling an mmap with a single device lock as we 
currently do in V4L2 is prone to AB-BA deadlocks (uvcvideo shouldn't be 
affected as it has no device-wide lock).

If we want to keep a device-wide lock we need to take it after the mm-
>mmap_sem lock in all code paths, as there's no way we can change the lock 
ordering for mmap(). The copy_from_user/copy_to_user issue could be solved by 
moving locking from v4l2_ioctl to __video_do_ioctl (device-wide locks would 
then require using video_ioctl2), but I'm not sure whether that will play 
nicely with the QBUF implementation in videobuf2 (which already includes a 
workaround for this particular AB-BA deadlock issue).

> [   96.257129] ======================================================
> [   96.257129] [ INFO: possible circular locking dependency detected ]
> [   96.257129] 3.4.0-rc5-20120506+ #4 Not tainted
> [   96.257129] -------------------------------------------------------
> [   96.257129] motion/2289 is trying to acquire lock:
> [   96.257129]  (&dev->lock){+.+.+.}, at: [<ffffffff8156c04c>]
> v4l2_mmap+0xbc/0xd0
> [   96.257129]
> [   96.257129] but task is already holding lock:
> [   96.257129]  (&mm->mmap_sem){++++++}, at: [<ffffffff81113cca>]
> sys_mmap_pgoff+0x1ca/0x220
> [   96.257129]
> [   96.257129] which lock already depends on the new lock.
> [   96.257129]
> [   96.257129]
> [   96.257129] the existing dependency chain (in reverse order) is:
> [   96.257129]
> [   96.257129] -> #1 (&mm->mmap_sem){++++++}:
> [   96.257129]        [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
> [   96.257129]        [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
> [   96.257129]        [<ffffffff81108cb8>] might_fault+0x68/0x90
> [   96.257129]        [<ffffffff8156d2a1>] video_usercopy+0x1d1/0x4e0
> [   96.257129]        [<ffffffff8156d5c0>] video_ioctl2+0x10/0x20
> [   96.257129]        [<ffffffff8156c110>] v4l2_ioctl+0xb0/0x180
> [   96.257129]        [<ffffffff8114dc3c>] do_vfs_ioctl+0x9c/0x580
> [   96.257129]        [<ffffffff8114e16a>] sys_ioctl+0x4a/0x80
> [   96.257129]        [<ffffffff81813039>] system_call_fastpath+0x16/0x1b
> [   96.257129]
> [   96.257129] -> #0 (&dev->lock){+.+.+.}:
> [   96.257129]        [<ffffffff810aa529>] validate_chain+0x1259/0x1300
> [   96.257129]        [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
> [   96.257129]        [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
> [   96.257129]        [<ffffffff8180e58c>]
> mutex_lock_interruptible_nested+0x5c/0x550
> [   96.257129]        [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
> [   96.257129]        [<ffffffff8111359a>] mmap_region+0x3da/0x5a0
> [   96.257129]        [<ffffffff81113ab4>] do_mmap_pgoff+0x354/0x3a0
> [   96.257129]        [<ffffffff81113ce9>] sys_mmap_pgoff+0x1e9/0x220
> [   96.257129]        [<ffffffff81011ee9>] sys_mmap+0x29/0x30
> [   96.257129]        [<ffffffff81813039>] system_call_fastpath+0x16/0x1b
> [   96.257129]
> [   96.257129] other info that might help us debug this:
> [   96.257129]
> [   96.257129]  Possible unsafe locking scenario:
> [   96.257129]
> [   96.257129]        CPU0                    CPU1
> [   96.257129]        ----                    ----
> [   96.257129]   lock(&mm->mmap_sem);
> [   96.257129]                                lock(&dev->lock);
> [   96.257129]                                lock(&mm->mmap_sem);
> [   96.257129]   lock(&dev->lock);
> [   96.257129]
> [   96.257129]  *** DEADLOCK ***
> [   96.257129]
> [   96.257129] 1 lock held by motion/2289:
> [   96.257129]  #0:  (&mm->mmap_sem){++++++}, at: [<ffffffff81113cca>]
> sys_mmap_pgoff+0x1ca/0x220
> [   96.257129]
> [   96.257129] stack backtrace:
> [   96.257129] Pid: 2289, comm: motion Not tainted 3.4.0-rc5-20120506+ #4
> [   96.257129] Call Trace:
> [   96.257129]  [<ffffffff810a8fb6>] print_circular_bug+0x206/0x300
> [   96.257129]  [<ffffffff810aa529>] validate_chain+0x1259/0x1300
> [   96.257129]  [<ffffffff810a9417>] ? validate_chain+0x147/0x1300
> [   96.257129]  [<ffffffff810ab773>] ? lock_release+0x113/0x260
> [   96.257129]  [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
> [   96.257129]  [<ffffffff810aa993>] ? __lock_acquire+0x3c3/0xc50
> [   96.257129]  [<ffffffff8156024c>] ? tda18271_tune+0x71c/0x9c0
> [   96.257129]  [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
> [   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
> [   96.257129]  [<ffffffff8180e58c>]
> mutex_lock_interruptible_nested+0x5c/0x550
> [   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
> [   96.257129]  [<ffffffff810a77ce>] ? mark_held_locks+0x9e/0x130
> [   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
> [   96.257129]  [<ffffffff811134de>] ? mmap_region+0x31e/0x5a0
> [   96.257129]  [<ffffffff810a7900>] ? lockdep_trace_alloc+0xa0/0x130
> [   96.257129]  [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
> [   96.257129]  [<ffffffff8111359a>] mmap_region+0x3da/0x5a0
> [   96.257129]  [<ffffffff81113ab4>] do_mmap_pgoff+0x354/0x3a0
> [   96.257129]  [<ffffffff81113ce9>] sys_mmap_pgoff+0x1e9/0x220
> [   96.257129]  [<ffffffff8132554e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> [   96.257129]  [<ffffffff81011ee9>] sys_mmap+0x29/0x30

-- 
Regards,

Laurent Pinchart

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Hans Verkuil]

On Monday 07 May 2012 13:06:01 Laurent Pinchart wrote:
> Hi Sanser,
> 
> On Sunday 06 May 2012 16:54:40 Sander Eikelenboom wrote:
> > Hello Laurent / Mauro,
> > 
> > I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
> > I don't see anything specific to uvcvideo anymore, but i do get the possible
> > circular locking dependency below.
> 
> Thanks for the report.
> 
> We indeed have a serious issue there (CC'ing Hans Verkuil).
> 
> Hans, serializing both ioctl handling an mmap with a single device lock as we 
> currently do in V4L2 is prone to AB-BA deadlocks (uvcvideo shouldn't be 
> affected as it has no device-wide lock).
> 
> If we want to keep a device-wide lock we need to take it after the mm-
> >mmap_sem lock in all code paths, as there's no way we can change the lock 
> ordering for mmap(). The copy_from_user/copy_to_user issue could be solved by 
> moving locking from v4l2_ioctl to __video_do_ioctl (device-wide locks would 
> then require using video_ioctl2), but I'm not sure whether that will play 
> nicely with the QBUF implementation in videobuf2 (which already includes a 
> workaround for this particular AB-BA deadlock issue).

I've seen the same thing. It was on my TODO list of things to look into. I think
mmap shouldn't take the device wide lock at all. But it will mean reviewing
affected drivers before I can remove it.

To be honest, I wasn't sure whether or not to take the device lock for mmap when
I first wrote that code.

If you look at irc I had a discussion today with HdG about adding flags to
selectively disable locks for fops. It may be an idea to implement this soon so
we can start updating drivers one-by-one.

Frankly, I do not believe this 'possible circular locking' thing to be a real
bug as I am not aware of drivers that use the device lock *and* lock mmap_sem.
If I understand Sander correctly 'motion' no longer locks up after moving to
3.4-rc5-tip, right?

I have to look into a bit more to see what the best approach it so we can prevent
this message from appearing.

Regards,

	Hans

> 
> > [   96.257129] ======================================================
> > [   96.257129] [ INFO: possible circular locking dependency detected ]
> > [   96.257129] 3.4.0-rc5-20120506+ #4 Not tainted
> > [   96.257129] -------------------------------------------------------
> > [   96.257129] motion/2289 is trying to acquire lock:
> > [   96.257129]  (&dev->lock){+.+.+.}, at: [<ffffffff8156c04c>]
> > v4l2_mmap+0xbc/0xd0
> > [   96.257129]
> > [   96.257129] but task is already holding lock:
> > [   96.257129]  (&mm->mmap_sem){++++++}, at: [<ffffffff81113cca>]
> > sys_mmap_pgoff+0x1ca/0x220
> > [   96.257129]
> > [   96.257129] which lock already depends on the new lock.
> > [   96.257129]
> > [   96.257129]
> > [   96.257129] the existing dependency chain (in reverse order) is:
> > [   96.257129]
> > [   96.257129] -> #1 (&mm->mmap_sem){++++++}:
> > [   96.257129]        [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
> > [   96.257129]        [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
> > [   96.257129]        [<ffffffff81108cb8>] might_fault+0x68/0x90
> > [   96.257129]        [<ffffffff8156d2a1>] video_usercopy+0x1d1/0x4e0
> > [   96.257129]        [<ffffffff8156d5c0>] video_ioctl2+0x10/0x20
> > [   96.257129]        [<ffffffff8156c110>] v4l2_ioctl+0xb0/0x180
> > [   96.257129]        [<ffffffff8114dc3c>] do_vfs_ioctl+0x9c/0x580
> > [   96.257129]        [<ffffffff8114e16a>] sys_ioctl+0x4a/0x80
> > [   96.257129]        [<ffffffff81813039>] system_call_fastpath+0x16/0x1b
> > [   96.257129]
> > [   96.257129] -> #0 (&dev->lock){+.+.+.}:
> > [   96.257129]        [<ffffffff810aa529>] validate_chain+0x1259/0x1300
> > [   96.257129]        [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
> > [   96.257129]        [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
> > [   96.257129]        [<ffffffff8180e58c>]
> > mutex_lock_interruptible_nested+0x5c/0x550
> > [   96.257129]        [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
> > [   96.257129]        [<ffffffff8111359a>] mmap_region+0x3da/0x5a0
> > [   96.257129]        [<ffffffff81113ab4>] do_mmap_pgoff+0x354/0x3a0
> > [   96.257129]        [<ffffffff81113ce9>] sys_mmap_pgoff+0x1e9/0x220
> > [   96.257129]        [<ffffffff81011ee9>] sys_mmap+0x29/0x30
> > [   96.257129]        [<ffffffff81813039>] system_call_fastpath+0x16/0x1b
> > [   96.257129]
> > [   96.257129] other info that might help us debug this:
> > [   96.257129]
> > [   96.257129]  Possible unsafe locking scenario:
> > [   96.257129]
> > [   96.257129]        CPU0                    CPU1
> > [   96.257129]        ----                    ----
> > [   96.257129]   lock(&mm->mmap_sem);
> > [   96.257129]                                lock(&dev->lock);
> > [   96.257129]                                lock(&mm->mmap_sem);
> > [   96.257129]   lock(&dev->lock);
> > [   96.257129]
> > [   96.257129]  *** DEADLOCK ***
> > [   96.257129]
> > [   96.257129] 1 lock held by motion/2289:
> > [   96.257129]  #0:  (&mm->mmap_sem){++++++}, at: [<ffffffff81113cca>]
> > sys_mmap_pgoff+0x1ca/0x220
> > [   96.257129]
> > [   96.257129] stack backtrace:
> > [   96.257129] Pid: 2289, comm: motion Not tainted 3.4.0-rc5-20120506+ #4
> > [   96.257129] Call Trace:
> > [   96.257129]  [<ffffffff810a8fb6>] print_circular_bug+0x206/0x300
> > [   96.257129]  [<ffffffff810aa529>] validate_chain+0x1259/0x1300
> > [   96.257129]  [<ffffffff810a9417>] ? validate_chain+0x147/0x1300
> > [   96.257129]  [<ffffffff810ab773>] ? lock_release+0x113/0x260
> > [   96.257129]  [<ffffffff810aa972>] __lock_acquire+0x3a2/0xc50
> > [   96.257129]  [<ffffffff810aa993>] ? __lock_acquire+0x3c3/0xc50
> > [   96.257129]  [<ffffffff8156024c>] ? tda18271_tune+0x71c/0x9c0
> > [   96.257129]  [<ffffffff810ab2e8>] lock_acquire+0xc8/0x110
> > [   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
> > [   96.257129]  [<ffffffff8180e58c>]
> > mutex_lock_interruptible_nested+0x5c/0x550
> > [   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
> > [   96.257129]  [<ffffffff810a77ce>] ? mark_held_locks+0x9e/0x130
> > [   96.257129]  [<ffffffff8156c04c>] ? v4l2_mmap+0xbc/0xd0
> > [   96.257129]  [<ffffffff811134de>] ? mmap_region+0x31e/0x5a0
> > [   96.257129]  [<ffffffff810a7900>] ? lockdep_trace_alloc+0xa0/0x130
> > [   96.257129]  [<ffffffff8156c04c>] v4l2_mmap+0xbc/0xd0
> > [   96.257129]  [<ffffffff8111359a>] mmap_region+0x3da/0x5a0
> > [   96.257129]  [<ffffffff81113ab4>] do_mmap_pgoff+0x354/0x3a0
> > [   96.257129]  [<ffffffff81113ce9>] sys_mmap_pgoff+0x1e9/0x220
> > [   96.257129]  [<ffffffff8132554e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> > [   96.257129]  [<ffffffff81011ee9>] sys_mmap+0x29/0x30
> 
> 

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Laurent Pinchart]

Hi Hans,

On Monday 07 May 2012 13:44:59 Hans Verkuil wrote:
> On Monday 07 May 2012 13:06:01 Laurent Pinchart wrote:
> > On Sunday 06 May 2012 16:54:40 Sander Eikelenboom wrote:
> > > Hello Laurent / Mauro,
> > > 
> > > I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
> > > I don't see anything specific to uvcvideo anymore, but i do get the
> > > possible circular locking dependency below.
> > 
> > Thanks for the report.
> > 
> > We indeed have a serious issue there (CC'ing Hans Verkuil).
> > 
> > Hans, serializing both ioctl handling an mmap with a single device lock as
> > we currently do in V4L2 is prone to AB-BA deadlocks (uvcvideo shouldn't
> > be affected as it has no device-wide lock).
> > 
> > If we want to keep a device-wide lock we need to take it after the mm-
> > 
> > >mmap_sem lock in all code paths, as there's no way we can change the lock
> > 
> > ordering for mmap(). The copy_from_user/copy_to_user issue could be solved
> > by moving locking from v4l2_ioctl to __video_do_ioctl (device-wide locks
> > would then require using video_ioctl2), but I'm not sure whether that
> > will play nicely with the QBUF implementation in videobuf2 (which already
> > includes a workaround for this particular AB-BA deadlock issue).
> 
> I've seen the same thing. It was on my TODO list of things to look into. I
> think mmap shouldn't take the device wide lock at all. But it will mean
> reviewing affected drivers before I can remove it.
> 
> To be honest, I wasn't sure whether or not to take the device lock for mmap
> when I first wrote that code.
>
> If you look at irc I had a discussion today with HdG about adding flags to
> selectively disable locks for fops. It may be an idea to implement this soon
> so we can start updating drivers one-by-one.
> 
> Frankly, I do not believe this 'possible circular locking' thing to be a
> real bug as I am not aware of drivers that use the device lock *and* lock
> mmap_sem. If I understand Sander correctly 'motion' no longer locks up
> after moving to 3.4-rc5-tip, right?

copy_from_user()/copy_to_user() perform a down_read(&mm->mmap_sem) when a page 
fault occurs. All drivers thus potentially take mm->mmap_sem when an ioctl is 
performed.
 
> I have to look into a bit more to see what the best approach it so we can
> prevent this message from appearing.

-- 
Regards,

Laurent Pinchart

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Hans Verkuil]

On Monday 07 May 2012 13:47:45 Laurent Pinchart wrote:
> Hi Hans,
> 
> On Monday 07 May 2012 13:44:59 Hans Verkuil wrote:
> > On Monday 07 May 2012 13:06:01 Laurent Pinchart wrote:
> > > On Sunday 06 May 2012 16:54:40 Sander Eikelenboom wrote:
> > > > Hello Laurent / Mauro,
> > > > 
> > > > I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
> > > > I don't see anything specific to uvcvideo anymore, but i do get the
> > > > possible circular locking dependency below.
> > > 
> > > Thanks for the report.
> > > 
> > > We indeed have a serious issue there (CC'ing Hans Verkuil).
> > > 
> > > Hans, serializing both ioctl handling an mmap with a single device lock as
> > > we currently do in V4L2 is prone to AB-BA deadlocks (uvcvideo shouldn't
> > > be affected as it has no device-wide lock).
> > > 
> > > If we want to keep a device-wide lock we need to take it after the mm-
> > > 
> > > >mmap_sem lock in all code paths, as there's no way we can change the lock
> > > 
> > > ordering for mmap(). The copy_from_user/copy_to_user issue could be solved
> > > by moving locking from v4l2_ioctl to __video_do_ioctl (device-wide locks
> > > would then require using video_ioctl2), but I'm not sure whether that
> > > will play nicely with the QBUF implementation in videobuf2 (which already
> > > includes a workaround for this particular AB-BA deadlock issue).
> > 
> > I've seen the same thing. It was on my TODO list of things to look into. I
> > think mmap shouldn't take the device wide lock at all. But it will mean
> > reviewing affected drivers before I can remove it.
> > 
> > To be honest, I wasn't sure whether or not to take the device lock for mmap
> > when I first wrote that code.
> >
> > If you look at irc I had a discussion today with HdG about adding flags to
> > selectively disable locks for fops. It may be an idea to implement this soon
> > so we can start updating drivers one-by-one.
> > 
> > Frankly, I do not believe this 'possible circular locking' thing to be a
> > real bug as I am not aware of drivers that use the device lock *and* lock
> > mmap_sem. If I understand Sander correctly 'motion' no longer locks up
> > after moving to 3.4-rc5-tip, right?
> 
> copy_from_user()/copy_to_user() perform a down_read(&mm->mmap_sem) when a page 
> fault occurs. All drivers thus potentially take mm->mmap_sem when an ioctl is 
> performed.

Ah, I didn't know that. Interesting.

Regards,

	Hans

>  
> > I have to look into a bit more to see what the best approach it so we can
> > prevent this message from appearing.
> 
> 

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Hans de Goede]

Hi,

On 05/07/2012 01:44 PM, Hans Verkuil wrote:
> On Monday 07 May 2012 13:06:01 Laurent Pinchart wrote:
>> Hi Sanser,
>>
>> On Sunday 06 May 2012 16:54:40 Sander Eikelenboom wrote:
>>> Hello Laurent / Mauro,
>>>
>>> I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
>>> I don't see anything specific to uvcvideo anymore, but i do get the possible
>>> circular locking dependency below.
>>
>> Thanks for the report.
>>
>> We indeed have a serious issue there (CC'ing Hans Verkuil).
>>
>> Hans, serializing both ioctl handling an mmap with a single device lock as we
>> currently do in V4L2 is prone to AB-BA deadlocks (uvcvideo shouldn't be
>> affected as it has no device-wide lock).
>>
>> If we want to keep a device-wide lock we need to take it after the mm-
>>> mmap_sem lock in all code paths, as there's no way we can change the lock
>> ordering for mmap(). The copy_from_user/copy_to_user issue could be solved by
>> moving locking from v4l2_ioctl to __video_do_ioctl (device-wide locks would
>> then require using video_ioctl2), but I'm not sure whether that will play
>> nicely with the QBUF implementation in videobuf2 (which already includes a
>> workaround for this particular AB-BA deadlock issue).
>
> I've seen the same thing. It was on my TODO list of things to look into. I think
> mmap shouldn't take the device wide lock at all. But it will mean reviewing
> affected drivers before I can remove it.
>
> To be honest, I wasn't sure whether or not to take the device lock for mmap when
> I first wrote that code.
>
> If you look at irc I had a discussion today with HdG about adding flags to
> selectively disable locks for fops. It may be an idea to implement this soon so
> we can start updating drivers one-by-one.

I've a patch almost ready for this, when I'm happy with it I'll send of a new
version of the (ever growing) gspca use control framework patchset both me and
the other Hans have been working on, which will include this patch.

Regards,

Hans

Re: [ 3960.758784] 1 lock held by motion/7776: [ 3960.758788] #0: (&queue->mutex){......}, at: [<ffffffff815c62d2>] uvc_queue_enable+0x32/0xc0

[Sander Eikelenboom]

Monday, May 7, 2012, 3:28:36 PM, you wrote:

> Hi,

> On 05/07/2012 01:44 PM, Hans Verkuil wrote:
>> On Monday 07 May 2012 13:06:01 Laurent Pinchart wrote:
>>> Hi Sanser,
>>>
>>> On Sunday 06 May 2012 16:54:40 Sander Eikelenboom wrote:
>>>> Hello Laurent / Mauro,
>>>>
>>>> I have updated to latest 3.4-rc5-tip, running multiple video grabbers.
>>>> I don't see anything specific to uvcvideo anymore, but i do get the possible
>>>> circular locking dependency below.
>>>
>>> Thanks for the report.
>>>
>>> We indeed have a serious issue there (CC'ing Hans Verkuil).
>>>
>>> Hans, serializing both ioctl handling an mmap with a single device lock as we
>>> currently do in V4L2 is prone to AB-BA deadlocks (uvcvideo shouldn't be
>>> affected as it has no device-wide lock).
>>>
>>> If we want to keep a device-wide lock we need to take it after the mm-
>>>> mmap_sem lock in all code paths, as there's no way we can change the lock
>>> ordering for mmap(). The copy_from_user/copy_to_user issue could be solved by
>>> moving locking from v4l2_ioctl to __video_do_ioctl (device-wide locks would
>>> then require using video_ioctl2), but I'm not sure whether that will play
>>> nicely with the QBUF implementation in videobuf2 (which already includes a
>>> workaround for this particular AB-BA deadlock issue).
>>
>> I've seen the same thing. It was on my TODO list of things to look into. I think
>> mmap shouldn't take the device wide lock at all. But it will mean reviewing
>> affected drivers before I can remove it.
>>
>> To be honest, I wasn't sure whether or not to take the device lock for mmap when
>> I first wrote that code.
>>
>> If you look at irc I had a discussion today with HdG about adding flags to
>> selectively disable locks for fops. It may be an idea to implement this soon so
>> we can start updating drivers one-by-one.

> I've a patch almost ready for this, when I'm happy with it I'll send of a new
> version of the (ever growing) gspca use control framework patchset both me and
> the other Hans have been working on, which will include this patch.

Hi Hans,

Is there any progress on this ?
It still happens when booting with a 3.5-rc4 kernel.
Probably with either the PWC or the em28xx driver.

--
Sander

> Regards,

> Hans




-- 
Best regards,
 Sander                            mailto:linux@eikelenboom.it