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
--
To unsubscribe from this list: send the line "unsubscribe linux-media" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
