Created attachment 528749 [details] lsusb -v & lspci -v Description of problem: There is a bug in ehci_hcd module working with uvcvideo and v4l2. My webcam works well with kernel 2.6.32 and v4l1-compat module but every kernel newer then 2.6.32 hangs up with message in dmesg: [ 100.764645] uvcvideo: Failed to resubmit video URB (-27). [ 100.764671] uvcvideo: Failed to resubmit video URB (-27). [ 100.764691] uvcvideo: Failed to resubmit video URB (-27). [ 100.764711] uvcvideo: Failed to resubmit video URB (-27). [ 100.764731] uvcvideo: Failed to resubmit video URB (-27). The attempt to modprobe -r ehci_hcd; modprobe uhci_hcd; don't help too much. Also on other computer this webcam runs without error messages. How reproducible: Run: 1. LD_PRELOAD=/usr/lib/libv4l/v4l2convert.so mplayer tv:// -tv driver=v4l2:width=640:height=480:device=/dev/video0 2. LD_PRELOAD=/usr/lib/libv4l/v4l1compat.so mplayer tv:// -tv driver=v4l2:width=640:height=480:device=/dev/video0 3. mplayer tv:// -tv driver=v4l2:width=640:height=480:device=/dev/video0 Additional info: The notebook model is Dell Inspiron 1300. Output of lspci -v & lsusb -v is in attachment.
-27 means that there's not enough bandwidth available for the camera. Did you try plugging it into a different port, or disconnecting other attached devices?
Sorry for long delay. I tested different systems. > Did you try plugging it into a different port, or disconnecting other attached devices? Of cource, nothing helped. I have other computer (Athlon64/gt7600/2GB) with 3xUSB 2.0. Everything works in any jacks from kernel 2.6.32 to 2.6.40 to 3.1.0. I suspect that it's buggy hardware. >[ 100.764731] uvcvideo: Failed to resubmit video URB (-27). I am ready to apply any patches you provide.
> -27 means that there's not enough bandwidth available for the camera The webcam also work via a USB 1.1 controller.
I've tested a few webcams. - Logitech Webcam C210 (046d:0819) - Logitech Webcam C310 (046d:081d) They are recognized as supported by uvcvideo on http://www.ideasonboard.org/uvc/. But they also does not work for me on my hardware (Dell Inspiron 1300).
It sounds amazing but after mounting usbfs as # mount -t usbfs none /proc/bus/usb The webcam works perfectly!
Created attachment 560860 [details] usbmon output
(In reply to comment #5) > It sounds amazing but after mounting usbfs as > > # mount -t usbfs none /proc/bus/usb > > > The webcam works perfectly Unfortunately the webcam has returned to previous state with "Failed to resubmit video URB (-27)." after reboot :( Output from usbmon is in attachments.
I have this bug too with webcam Logitech C110. It hang after few hours of work [162892.645192] uvcvideo: Failed to resubmit video URB (-27). [162892.645206] uvcvideo: Failed to resubmit video URB (-27). [162892.645216] uvcvideo: Failed to resubmit video URB (-27). [162892.645226] uvcvideo: Failed to resubmit video URB (-27). [162892.645235] uvcvideo: Failed to resubmit video URB (-27).
[mass update] kernel-3.3.0-4.fc16 has been pushed to the Fedora 16 stable repository. Please retest with this update.
> kernel-3.3.0-4.fc16 has been pushed to the Fedora 16 stable repository. > Please retest with this update. The same wrong behavior. bash-4.2$ uname -a Linux nemesis 3.3.0-4.fc16.i686 #1 SMP Tue Mar 20 18:45:14 UTC 2012 i686 i686 i386 GNU/Linux bash-4.2$ bash-4.2$ dmesg [ 320.137117] uvcvideo: Failed to resubmit video URB (-27). [ 320.137117] uvcvideo: Failed to resubmit video URB (-27). [ 320.137117] uvcvideo: Failed to resubmit video URB (-27). [ 320.137117] uvcvideo: Failed to resubmit video URB (-27). [ 320.137117] ALSA sound/usb/endpoint.c:180 cannot submit urb (err = -27) [ 320.137117] uvcvideo: Failed to resubmit video URB (-27). [ 330.184296] retire_capture_urb: 10 callbacks suppressed [ 330.184413] ALSA sound/usb/endpoint.c:180 cannot submit urb (err = -27) [ 370.376505] retire_capture_urb: 8 callbacks suppressed [ 370.376620] ALSA sound/usb/endpoint.c:180 cannot submit urb (err = -27) [ 380.424527] retire_capture_urb: 8 callbacks suppressed [ 380.424647] ALSA sound/usb/endpoint.c:180 cannot submit urb (err = -27) [ 430.717342] retire_capture_urb: 9 callbacks suppressed [ 430.717943] uvcvideo: Failed to resubmit video URB (-27). [ 430.717988] uvcvideo: Failed to resubmit video URB (-27). [ 430.718030] uvcvideo: Failed to resubmit video URB (-27). [ 430.718061] ALSA sound/usb/endpoint.c:180 cannot submit urb (err = -27) [ 430.718099] uvcvideo: Failed to resubmit video URB (-27). [ 430.718122] uvcvideo: Failed to resubmit video URB (-27). bash-4.2$ mplayer tv:// -tv driver=v4l2:width=640:height=480:device=/dev/video0 v4l2: select timeout V: 0.0 418/418 ??% ??% ??,?% 0 0 v4l2: select timeout V: 0.0 420/420 ??% ??% ??,?% 0 0 v4l2: select timeout V: 0.0 422/422 ??% ??% ??,?% 0 0 v4l2: select timeout V: 0.0 424/424 ??% ??% ??,?% 0 0 v4l2: select timeout V: 0.0 425/425 ??% ??% ??,?% 0 0 v4l2: select timeout v4l2: ioctl set mute failed: Invalid argument v4l2: 417 frames successfully processed, 431 frames dropped.
Created attachment 572419 [details] lsusb (for Bus identification) && usbmon output
This link can be useful https://lkml.org/lkml/2012/1/3/94
bash-4.2$ uname -a Linux nemesis 3.3.1-3.fc16.i686 #1 SMP Wed Apr 4 19:07:24 UTC 2012 i686 i686 i386 GNU/Linux bash-4.2$ The same wrong behavior.
bash-4.2$ uname -a Linux nemesis 3.4.0-1.fc17.i686 #1 SMP Sun Jun 3 07:16:04 UTC 2012 i686 i686 i386 GNU/Linux bash-4.2$ The problem is still here.
reported this upstream to linux-usb. Hopefully someone there has some idea.
My logfile is filling up with these. The callbacks suppressed are quite large. I assume this is chewing up a significant amount of CPU time. Its certainly adding many megs to my /var/log/messages file. Linux arbol.wsrcc.com 3.4.4-3.fc17.x86_64 #1 SMP Tue Jun 26 20:54:56 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux 2012-07-03T04:28:56.470458-07:00 arbol kernel: [164182.365490] retire_capture_urb: 4368 callbacks suppressed 2012-07-03T04:29:01.477444-07:00 arbol kernel: [164187.358727] retire_capture_urb: 4368 callbacks suppressed 2012-07-03T04:29:06.476898-07:00 arbol kernel: [164192.351365] retire_capture_urb: 4368 callbacks suppressed 2012-07-03T04:29:11.481860-07:00 arbol kernel: [164197.345555] retire_capture_urb: 4368 callbacks suppressed 2012-07-03T04:29:16.491832-07:00 arbol kernel: [164202.338339] retire_capture_urb: 4368 callbacks suppressed 2012-07-03T04:29:21.483821-07:00 arbol kernel: [164207.331374] retire_capture_urb: 4367 callbacks suppressed 2012-07-03T04:29:26.493744-07:00 arbol kernel: [164212.323288] retire_capture_urb: 4367 callbacks suppressed 2012-07-03T04:29:31.487467-07:00 arbol kernel: [164217.316075] retire_capture_urb: 4368 callbacks suppressed 2012-07-03T04:29:36.489444-07:00 arbol kernel: [164222.308779] retire_capture_urb: 4367 callbacks suppressed 2012-07-03T04:29:41.494830-07:00 arbol kernel: [164227.301024] retire_capture_urb: 4367 callbacks suppressed
I mentioned this in the upstream kernel mailing list (see http://marc.info/?l=linux-usb&m=134012064011610&w=2), but apparently the information never got into this bug report. The usbmon trace shows that the problem occurred when interrupts were blocked for over 52 milliseconds. Either IRQs were lost or else some driver disabled interrupts for far too long. Perhaps the irqsoff tracer can help identify the guilty party.
Created attachment 600345 [details] MPlayer && Skype usbmon output
> Does the altsetting array contain altsetting 0 ? If not, the patch should fix > the issue. >> diff --git a/drivers/media/video/uvc/uvc_video.c >> b/drivers/media/video/uvc/uvc_video.c >> index b76b0ac..d1e7cb2 100644 >> --- a/drivers/media/video/uvc/uvc_video.c >> +++ b/drivers/media/video/uvc/uvc_video.c >> @@ -1594,7 +1594,7 @@ static int uvc_init_video(struct uvc_streaming >> *stream, gfp_t gfp_flags) >> psize = le16_to_cpu(ep->desc.wMaxPacketSize); >> psize = (psize & 0x07ff) * (1 + ((psize >> 11) & 3)); >> if (psize >= bandwidth && psize <= best_psize) { >> - altsetting = i; >> + altsetting = alts->desc.bAlternateSetting; >> best_psize = psize; >> best_ep = ep; >> } > -- > Regards, > Laurent Pinchart __ I will repost a message with irqsoff tracer logs into the usb maillist later __ Bus 001 Device 002: ID 046d:081b Logitech, Inc. Webcam C310 Interface Descriptor: bLength 9 bDescriptorType 4 bInterfaceNumber 0 (!!!) bAlternateSetting 0 bNumEndpoints 1 bInterfaceClass 14 Video bInterfaceSubClass 1 Video Control bInterfaceProtocol 0 iInterface 0
The new usbmon log shows the same symptom as the earlier one. The errors start to occur just after a 50-millisecond gap during which there are no I/O events. Hopefully the irqsoff tracer will show the reason for this gap.
Created attachment 600480 [details] MPlayer && Skype irqsoff tracer logs
Created attachment 600489 [details] MPlayer2 under the irqsoff tracer on the system where the webcam works
Was the tracer log in comment #23 active while a failure occurred? It shows a maximum latency of only 6 ms, not 50 ms.
(In reply to comment #25) > Was the tracer log in comment #23 active while a failure occurred? It shows > a maximum latency of only 6 ms, not 50 ms. Yes, it was captured while a failure had occurred.
That means disabled interrupts aren't the cause of the problem. Either the EHCI hardware isn't generating an IRQ when it should, or else the operating system isn't handling the interrupt request properly. Hardware error seems to be the most likely explanation. Especially since you mentioned that the webcam works okay on other computers. If you want, I could write a patch to test this. Do you think it is worthwhile?
This means i have to test the webcam under Windows. I will post results later.
Created attachment 600909 [details] The output of usbmon with Mplayer under 2.6.32 kernel
> Hardware error seems to be the most likely explanation. But under Windows and 2,6,32 kernel with v4l1 subsystem included the webcam somehow works. I've attached the output from 2.6.32 kernel. I hope it can be useful. But i don't know how much uvcvideo has changed since removal of v4l1 api. > I could write a patch to test this. i you can, please.
> i you can, please. if you can
Ah -- I missed the fact that the webcam works okay with 2.6.32 but not with 2.6.33. You may be able to find the point at which the errors started to occur by using git bisect between those two kernels. Can you do that? On the other hand, some changes were made to fix some bugs in the scheduling code in ehci-hcd around that time frame. It wouldn't be surprising if bisection led you to those changes. Perhaps the 2.6.32 driver isn't working right either, but because of the bugs the symptoms aren't so obvious. I haven't looked through your 2.6.32 usbmon trace in any detail, but I can tell you what to look for. As an example, here's an extract from the mplayer usbmon log in comment #20 (I have truncated the lines to make them easier to read): f067b800 335348672 S Zi:1:003:1 -115:1:0 32 f2f57800 335349098 S Zi:1:003:1 -115:1:0 32 f2f57000 335349159 S Zi:1:003:1 -115:1:0 32 f2f57400 335349172 S Zi:1:003:1 -115:1:0 32 f2f57c00 335349183 S Zi:1:003:1 -115:1:0 32 This is 5 lines in a row all matching an " S Zi:*:*:1 -115:1:0 32 " pattern. That's the start of the video data transfer from the webcam. Following that we have: f067b800 335361851 C Zi:1:003:1 0:1:656:0 32 f067b800 335361887 S Zi:1:003:1 -115:1:656 32 f2f57800 335365852 C Zi:1:003:1 0:1:688:0 32 f2f57800 335365875 S Zi:1:003:1 -115:1:688 32 f2f57000 335369851 C Zi:1:003:1 0:1:720:0 32 f2f57000 335369869 S Zi:1:003:1 -115:1:720 32 These are alternating lines containing " C " and " S ". This pattern continues as long as the transfer is working. The important thing to note here is the number just before each "C": 335361851 335365852 335369851 These are timestamps, in microseconds. When everything is working right, the time interval between successive "C" lines should be close to 4000 microseconds, as in the example above. The errors are shown by lines that contain "E" where the "C" or "S" would normally be. 12 lines before the first "E" in the log, we have: f067b800 339282507 C Zi:1:003:1 0:1:7440:0 32 f067b800 339282539 S Zi:1:003:1 -115:1:7440 32 f2f57800 339336622 C Zi:1:003:1 0:1:7472:0 32 f2f57800 339336650 S Zi:1:003:1 -115:1:7472 32 f2f57000 339336667 C Zi:1:003:1 0:1:7504:0 32 Notice that the time interval between the first two "C" lines is about 54100 microseconds, and the next time interval is only 45 microseconds. That's where the problems began; any interval much different from 4000 is a clear sign of trouble. So now you can scan through your own usbmon traces, verifying that the pattern of 4000-microsecond intervals is always present. If it isn't -- if you see a big jump like 54000 microseconds -- then something is wrong, even if the mplayer program doesn't crash.
I've bought the ST-Lab C-470 expresscard/34 USB 3.0 laptop adapter. The webcam works okay. From a user's viewpoint the problem is fixed, but i still wanna investigate what is going on with the USB 2.0/ECHI module. I will check out usbmon logs a little bit later and i will on connection at least next 2 days. Thanks.
(In reply to comment #33) > I've bought the ST-Lab C-470 expresscard/34 USB 3.0 laptop adapter. The > webcam works okay. From a user's viewpoint the problem is fixed, but i still > wanna investigate what is going on with the USB 2.0/ECHI module. I will > check out usbmon logs a little bit later and i will on connection at least > next 2 days. > > Thanks. Any updates / new information on this ?
The main trouble is that i need help to analyse usbmon logs. I am really not familiar with parsing usb frames. Also kernel stuff with my USB3.0 adapter is broken in 3.6 kernel. The sound disappears after 10-20 seconds? but it's another story,
I think I'm having the same or a very similar problem, but for me it only happens in a VMware (Workstation 9) guest. Same error messages, same kernels. 2.6.32 is fine, anything newer has been a problem. The cam is fine on the host with everything I've tried - 2.6.32, 2.6.39, and 3.2.x. I tried with USB 2.0 or 3.0 compatibility, adjusting a the autosuspend options, and a number of uvcvideo and vmware (USB) quirks but none of it has helped. I'm generally seeing things like this in dmesg: [ 2689.750543] uvcvideo: Failed to resubmit video URB (-27). [ 386.596686] 2:1:1: usb_set_interface failed [ 387.596208] 2:1:1: cannot set freq 16000 to ep 0x86 [ 54.270821] uvcvideo: Failed to set UVC probe control : -110 (exp. 26). The VMware log will show this: 2012-07-02T18:37:22.509-06:00| vmx| W110: USBGL: Failed to cancel URB (-1 22)
Alan Stern released several patches for 3.6.0 kernel for my case(delays in usb comminucation that packets come in the wrong order ). See the start of the tech discussion here: http://www.spinics.net/lists/linux-usb/msg69998.html But i don't know are they included in the mainstream kernel or not. I have not test them yet.
Yes,i've found that patches by Alan Stern will be in Linux kernel 3.8 http://www.spinics.net/lists/linux-usb/msg75938.html
Mike, you should try using git bisect to pinpoint the exact change between 2.6.32 and 2.6.33 that caused your problems to start. Ilya, I suspect the changes in 3.8 won't help your problem. Have you tried using a 3.6-rc1 kernel? The pattern to look for in the usbmon logs is fairly simple, although you may want to write a program to do it for you because the logs are so long. You should look for a sequence like this: f067b800 339282507 C Zi:1:003:1 0:1:7440:0 32 ,,, f067b800 339282539 S Zi:1:003:1 -115:1:7440 32 ,,, f2f57800 339336622 C Zi:1:003:1 0:1:7472:0 32 ,,, where the first and third lines both contain "C Zi" and the difference between the numbers in the second column of those lines is much larger than 4000 (i.e., 339336622 - 339282507 = 54115 > 4000). If you find this pattern occurring every time the problem shows up, I'll try to figure out some way to see what's causing the problem.
There is a book called "ProGit" which is freely available. Just in case if someone( like Mike ) wants to detect the problem via git bisect. I will try 3.8-rc1 kernel in next several days. //wbr
Well that wasn't much fun but I think I made some progress.. git clone git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git git bisect start git bisect good v2.6.32 git bisect bad v2.6.33 needed some patches - http://lkml.indiana.edu/hypermail/linux/kernel/0912.2/00531.html https://patchwork.kernel.org/patch/1301031/ git bisect good 5f1141eb352ea79d849920039503e40dd623fffa git bisect bad bf931a01a2c024a54204b4b02276af6e8d99a2c0 git bisect bad 2e8c12436f540d3c40137ebf10268803dc972f6a one more patch - http://www.spinics.net/lists/linux-usb/msg25390.html git bisect bad 5de76b18d1a7193c49c1a4ee72261421a17de57c git bisect bad 0e2f7b837600979d5b6f174a6ff695b85942e985 git bisect good 76e407980728123223fac5c2e8273bc6e7e43cfd git bisect bad 8e4ceb38eb5bbaef22fc00abe9bc11e26bea2ab5 git bisect bad c1479a92cf0a7792298d364e44a781550621cb58 git bisect good 4f0f0baef017dfd5d62b749716ab980a825e1071 git bisect bad 93f937405bd5280ced9bf845f620d1de19b9bf7d git bisect bad 253e05724f9230910344357b1142ad8642ff9f5a git bisect good d7e055f1975cac560427c924d2bff4b5d41fe442 That left me with d697cdda43939a80432863e2e26df6701ce72b63 - http://tima-sls.imag.fr/viewgit/general/?a=commitdiff&p=Linux&h=d697cdda43939a80432863e2e26df6701ce72b63 After I reverted that my webcam appears to be working much better inside a VM with 2.6.23. I also tested this on 3.2.35 by changing the function names from usb_buffer_{alloc,free} to usb_{alloc,free}_coherent. I still got the "Failed to resubmit video URB (-27)" error a few times on 2.6.33 (nothing so far on 3.2.x) but the cam hasn't been hanging up. But I believe I'm having a second issue. After a few seconds or a few minutes (usually the former) my Firefox plugin-container starts chewing up CPU. Initially starting in the 8-12% range (normal) but then it'll get up into the 90s. Originally I thought this was all the same issue but maybe these are a few different problems here. Since my original testing showed problems with both EHCI and XHCI I'm hopeful that I'm in the right track by touching on shared code in drivers/usb/core/hub.c. Anyone familiar with this code able to look at the checkin and see something obvious? I do a bit of programming but nothing in the kernel. At first glance the allocation stuff looks ok but those transfer dma lines in the middle of the patch are just gone completely in newer kernels. Maybe the issue is there.
I've tried 3.8-rc1 kernel and can definitely say that it's Alan's triumph. My webcam ( Logitech C-310 ) worked bugless 30 minutes with USB2.0 interface. Thanks again!
It looks like mine is a different bug then, 3.8.0-rc1 didn't help me. I ended up with a flash crash and a hung task after a few minutes: [ 599.274375] INFO: task plugin-containe:2862 blocked for more than 120 seconds. [ 599.274379] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 599.274380] plugin-containe D 7e8e2ab1 0 2862 2831 0x00000004 [ 599.274384] f70fec00 00200082 f5f7bd98 7e8e2ab1 00000069 f70fec00 00000000 00200286 [ 599.274387] d5ae0c00 00200286 f807f1e1 fffffffe f81b5078 d5ae0c00 f72ce400 fffffffe [ 599.274390] f81135e6 00200202 d5ae0c00 00000000 fffffffe d5ae0c00 00200246 d5ae0c00 [ 599.274392] Call Trace: [ 599.274427] [<f807f1e1>] ? ehci_urb_dequeue+0x7d/0x85 [ehci_hcd] [ 599.274435] [<f81135e6>] ? unlink1+0x82/0x8c [usbcore] [ 599.274442] [<f8114b6c>] ? usb_kill_urb+0x77/0x8e [usbcore] [ 599.274446] [<c10361b2>] ? finish_wait+0x3e/0x3e [ 599.274451] [<f855bd76>] ? uvc_uninit_video+0x27/0x53 [uvcvideo] [ 599.274455] [<f855d9ec>] ? uvc_video_enable+0x10/0x10c [uvcvideo] [ 599.274457] [<f855ba36>] ? uvc_v4l2_do_ioctl+0xdcd/0xf91 [uvcvideo] [ 599.274461] [<c12a8fbe>] ? _cond_resched+0x5/0x18 [ 599.274464] [<c114bbcf>] ? _copy_from_user+0x28/0x49 [ 599.274469] [<f8590bba>] ? video_usercopy+0x219/0x2cc [videodev] [ 599.274472] [<f855ac69>] ? kzalloc.constprop.3+0xa/0xa [uvcvideo] [ 599.274474] [<c103fb53>] ? set_next_buddy+0xe/0x28 [ 599.274475] [<c103fd6f>] ? check_preempt_wakeup+0x102/0x15e [ 599.274478] [<c103dbcd>] ? check_preempt_curr+0x4f/0x5f [ 599.274480] [<c103dc19>] ? ttwu_do_wakeup.constprop.86+0x3c/0x46 [ 599.274482] [<c103dc90>] ? try_to_wake_up+0x6d/0x75 [ 599.274485] [<c104fa92>] ? wake_futex+0x48/0x4e [ 599.274486] [<c10500e5>] ? futex_wake+0xb1/0xbb [ 599.274489] [<f855a771>] ? uvc_v4l2_ioctl+0x44/0x4a [uvcvideo] [ 599.274492] [<f855ac69>] ? kzalloc.constprop.3+0xa/0xa [uvcvideo] [ 599.274496] [<f858d3e6>] ? v4l2_ioctl+0x5f/0xd3 [videodev] [ 599.274499] [<f858d387>] ? v4l2_open+0xa4/0xa4 [videodev] [ 599.274501] [<c10bc26a>] ? do_vfs_ioctl+0x45e/0x495 [ 599.274503] [<c103d85d>] ? finish_task_switch.isra.75+0x2b/0x82 [ 599.274505] [<c12a8f64>] ? __schedule+0x38d/0x3ae [ 599.274507] [<c10055e7>] ? read_tsc+0xa/0x28 [ 599.274527] [<c1048fda>] ? timekeeping_get_ns.constprop.11+0x11/0x60 [ 599.274530] [<c10bc2e9>] ? sys_ioctl+0x48/0x67 [ 599.274532] [<c12ad559>] ? sysenter_do_call+0x12/0x28 Sorry for the crossover and all the noise. I'll take my problems elsewhere.
If it solved in UPSTREAM give us link to commit please.
Vasiliy, I don't know which commit fixed the problem. All I know is what Ilya reported in comment #42.