uvcvideo: USB isochronous frame lost

[Berryfier]

Symptoms: Moving pictures from a USB webcam are not fluid, they appear jerky or freeze frame. Individual images are delivered with intervals of various lengths between images.

To reproduce the problem:

• use 2013-02-09 raspbian
• plug in a webcam camera to the Pi USB (camera powered seperately - not from Pi)
• at a terminal enter as root:
  sudo echo 0xFFFF > /sys/module/uvcvideo/parameters/trace
• start an application which uses uvcvideo (e.g. mjpg-streamer)
• after a few seconds, stop the application
• at a terminal enter as root:
  sudo echo 0x0000 > /sys/module/uvcvideo/parameters/trace
• look in /var/log/kern.log (example below using UVC Camera Logitech 046d:0991)

Feb 27 22:09:12 raspberrypi kernel: [ 5359.989325] uvcvideo: Frame complete (EOF found).
Feb 27 22:09:12 raspberrypi kernel: [ 5359.989374] uvcvideo: frame 20 stats: 59/1267/1593 packets, 1/39/1593 pts (early initial), 1592/1593 scr, last pts/stc/sof 3111250099/3120608861/1217
Feb 27 22:09:12 raspberrypi kernel: [ 5360.154221] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:12 raspberrypi kernel: [ 5360.166469] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:12 raspberrypi kernel: [ 5360.174708] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:12 raspberrypi kernel: [ 5360.186959] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:12 raspberrypi kernel: [ 5360.187038] uvcvideo: Frame complete (EOF found).
Feb 27 22:09:12 raspberrypi kernel: [ 5360.187069] uvcvideo: frame 21 stats: 59/1259/1583 packets, 1/39/1583 pts (early initial), 1582/1583 scr, last pts/stc/sof 3120851941/3130210964/1417
Feb 27 22:09:12 raspberrypi kernel: [ 5360.387163] uvcvideo: Frame complete (EOF found).
Feb 27 22:09:12 raspberrypi kernel: [ 5360.387237] uvcvideo: frame 22 stats: 59/1274/1599 packets, 1/39/1599 pts (early initial), 1598/1599 scr, last pts/stc/sof 3130453789/3139813066/1617
Feb 27 22:09:12 raspberrypi kernel: [ 5360.387420] uvcvideo: UVC Camera (046d:0991): PTS 3130453789 y 3720.807754 SOF 3720.807754 (x1 2155366602 x2 2156854928 y1 254607360 y2 256638976 SOF offset 250)
Feb 27 22:09:12 raspberrypi kernel: [ 5360.387465] uvcvideo: UVC Camera (046d:0991): SOF 3720.807754 y 994343961 ts 5360.593856 buf ts 5360.427484 (x1 246808576/12726/1837 x2 261554176/12951/1868 y1 1000000000 y2 1028159890)
Feb 27 22:09:12 raspberrypi kernel: [ 5360.387772] uvcvideo: uvc_v4l2_ioctl(VIDIOC_QBUF)
Feb 27 22:09:12 raspberrypi kernel: [ 5360.388090] uvcvideo: uvc_v4l2_ioctl(VIDIOC_DQBUF)
Feb 27 22:09:12 raspberrypi kernel: [ 5360.395368] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:13 raspberrypi kernel: [ 5360.551643] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:13 raspberrypi kernel: [ 5360.568016] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:13 raspberrypi kernel: [ 5360.576270] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:13 raspberrypi kernel: [ 5360.584517] uvcvideo: USB isochronous frame lost (-63).
Feb 27 22:09:13 raspberrypi kernel: [ 5360.588666] uvcvideo: Frame complete (EOF found).
Feb 27 22:09:13 raspberrypi kernel: [ 5360.588705] uvcvideo: frame 23 stats: 57/1265/1583 packets, 1/39/1583 pts (early initial), 1582/1583 scr, last pts/stc/sof 3140055631/3149415169/1817'''

[P33M]

Having spent a while with GPIO/oscilloscope debugging while sorting out other issues, I can say the following:

There is a very large chunk of time spent in_interrupt() when a set of isoc transcations complete, especially with uvcvideo transfers. The driver by default queues 5x URBs of 32 transactions each. Once a 32-burst transaction is complete, the uvcvideo completion handler is called from within the dwc_otg interrupt handler and it blocks for anything up to 700uS. This will cause multiple queued isoc transactions to get dropped due to frame overrun, as seen with the -63 return code. Typical time spent in_interrupt() for a normal xfercomp interrupt handle (no URB completion) is approx 30uS. Still huge, but at least less than a microframe.

I believe this is a rather large smoking gun - given that the dwc driver coders apparently have never heard of bottom-half interrupt handlers, it would definitely be worth splitting completion functions off into a softirq/tasklet.

[ghollingworth]

Except the xfer completion interrupt needs to be called in interrupt
context...

Gordon

On Wednesday, 13 March 2013, P33M wrote:

Having spent a while with GPIO/oscilloscope debugging while sorting out
other issues, I can say the following:

There is a very large chunk of time spent in_interrupt() when a set of
isoc transcations complete, especially with uvcvideo transfers. The driver
by default queues 5x URBs of 32 transactions each. Once a 32-burst
transaction is complete, the uvcvideo completion handler is called from
within the dwc_otg interrupt handler and it blocks for anything up to
700uS. This will cause multiple queued isoc transactions to get dropped due
to frame overrun, as seen with the -63 return code. Typical time spent
in_interrupt() for a normal xfercomp interrupt handle (no URB completion)
is approx 30uS. Still huge, but at least less than a microframe.

I believe this is a rather large smoking gun - given that the dwc driver
coders apparently have never heard of bottom-half interrupt handlers, it
would definitely be worth splitting completion functions off into a
softirq/tasklet.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/238#issuecomment-14834492
.

[ghollingworth]

Sorry I mean the transfer completion callback

Gordon

Gordon Hollingworth, Director of Engineering

On 13 Mar 2013, at 10:44, Gordon Hollingworth gordon@raspberrypi.org wrote:

Except the xfer completion interrupt needs to be called in interrupt context...

Gordon

On Wednesday, 13 March 2013, P33M wrote:
Having spent a while with GPIO/oscilloscope debugging while sorting out other issues, I can say the following:

There is a very large chunk of time spent in_interrupt() when a set of isoc transcations complete, especially with uvcvideo transfers. The driver by default queues 5x URBs of 32 transactions each. Once a 32-burst transaction is complete, the uvcvideo completion handler is called from within the dwc_otg interrupt handler and it blocks for anything up to 700uS. This will cause multiple queued isoc transactions to get dropped due to frame overrun, as seen with the -63 return code. Typical time spent in_interrupt() for a normal xfercomp interrupt handle (no URB completion) is approx 30uS. Still huge, but at least less than a microframe.

I believe this is a rather large smoking gun - given that the dwc driver coders apparently have never heard of bottom-half interrupt handlers, it would definitely be worth splitting completion functions off into a softirq/tasklet.

—
Reply to this email directly or view it on GitHub.

[P33M]

So what would break if we split URB completion off into a tasklet? If using the high priority softirq, nothing else scheduling-wise would be allowed to run until it completed but the myriad of hardware interrupts that the dwc usb core generates would still get serviced.

The only thing I could think of would be multiple calls to a completion tasklet if we got multiple URBs completing in a very short space of time - needing some sort of queuing mechanism should there be a pileup of completed transfers.

@Berryfier: have you tried tweaking the driver parameters? Try modprobe with nodrop=1 which should deliver corrupted frames rather than no frames.

[Berryfier]

@P33M : thank you for your suggestion to tweak the driver parameters. With the camera unplugged, and as root, I entered 'sudo modprobe uvcvideo nodrop=1'. I then plugged in the camera, and started guvcview. The image motion was much more fluid, there were no freeze frames, and the frame rates achieved were much greater; 15fps@320x240, 7 fps@640x480. This is all with the camera sending MJPEG. I notice that with the tweak the CPU is maxed out with the 640x480 picture@7fps. Without the tweak, CPU use is always low, whatever the picture size, the display rarely exceeding 1fps. I also ran the trace and checked the kern.log. I was surprised to still see the large amount of uvcvideo: USB isochronous frame lost (-63) which appears as frequently as occurs without the tweak. It seems a fix is still needed. I've not (yet) noticed any corruption of the pictures either with or without the tweak.

Is it possible this issue is somehow linked to issue #199 ?

[P33M]

Uh

I think I fixed it...

https://gist.github.com/P33M/5213278

What I did was implement a tasklet to split the return of the URB to the various device drivers from the time we spend sitting with interrupts disabled. Previously my crummy uncompressed-frame webcam would fail repeatedly with lost isoc packets when trying uvccapture, now everything works first time.

Comments on the code would be appreciated before I submit a pull request. This is a fairly big structural change for the driver.

I'll test it this evening and let you know. Thanks for the effort.

[ghollingworth]

Would be interesting to now measure the worst case latency with this change, if this reduces down to <uframe time then it make the FIQ stuff not really needed…

Gordon

Gordon Hollingworth, Director of Engineering

On 21 Mar 2013, at 14:13, RKlauco notifications@github.com wrote:

I'll test it this evening and let you know. Thanks for the effort.

—
Reply to this email directly or view it on GitHub.

[P33M]

After playing with it a bit it seems stable with ethernet/usb disk/webcam activity.

I installed guvcview to test streaming from the cam - at 640x480 there is still the odd corrupted frame with nodrop=1 but with corrupted frames dropped I am getting approx 60% valid frames (camera is spitting out 30fps) of uncompressed video at 640x480 - a data rate of 17MB/s. Guvcview is maxing out the CPU anyways so I can't tell if the drops are more due to corruption or lack of cycles.

Increasing USB loading, as expected, does not alter the error rate of the video. Other interrupt sources (sd card, timers, etc) appear to cause a packet drop if they take longer than 125uS to complete, or the isoc transaction happens near the end of a uframe and servicing the interrupt takes it past the SOF for the next frame.

My Sidewinder X4 keyboard - previously unusuable on the pi, as of recent kernels more useable - is still missing keypresses though I think slightly less than before.

Can someone, please, point me out to some guide how to compile the kernel including the patch from P33M?

[P33M]

I've pushed the commit to my repo. https://github.com/P33M/linux

If you follow the standard kernel compilation guide: http://elinux.org/RPi_Kernel_Compilation

But substitute my repo for the official one, you will get the patch. I strongly recommend using cross-compilation from another machine unless you have 12 hours to spare.

Note that you will need to install both the compiled modules AND the kernel.img to your SD card.

Thanks for the effort and the guide. And the tip to cross-compile ;)
I did it accordingly (replacing the raspberrypi by P33M in github address) and all seemed to work well.
I compiled the kernel image and modules, tgz them and moved both to my Pi into appropriate locations.
The Pi booted (HURAY!!!), uname -a shows
3.6.11+ #1 PREEMPT
But, unfortunately, the result is still the same - the camera complains about Non-zero status and even with nodrop=1 and timeout=5000 parameters, the behaviour is exactly the same. After 5 records, the module simply stops responding.
Is there something I should have set/patched during the kernel compilation? Or is the fix not helping in this case?

[P33M]

@RKlauco That's interesting. It's possible there's another issue - the errors that I get are -63 (they do still occur, but much less than previously) which are due to frame overruns.

• What camera produces this result?
• What userland application are you using to stream/record the images?
• Can you do a lsusb -v for the camera and post the output?

Looking at the driver, -5 is returned for periodic transfers when the transfer halted but there are no other interrupts set. I've not seen them in my case - further testing required!

Edit: -5 is a URB state, -63 is a individual iso_desc state - so rather than individual transfers failing, your URB is being aborted.