infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Pi 4B: UVC cameras stop sending frames after random interval

Thu Sep 17, 2020 8:03 am

I've got a Pi 4B 2GB that is exhibiting some behavior I can't readily explain. I have 3 UVC cameras attached and simultaneously streaming via GStreamer, 2 of them 720p60 MJPEG, 1 720p30 MJPEG. Invariably, at least one camera will stop sometime between 15 min and 15 hours.

Sometimes, GStreamer will show a helpful message:

Code: Select all

7:44:17.054354951 ^[[332m 5665^[[00m  0x1873fb0 ^[[33;01mWARN   ^[[00m ^[[00m             v4l2src gstv4l2src.c:998:gst_v4l2src_create:<v4l2src0>^[[00m error: Failed to allocate a buffer
Sometimes, it doesn't, though... the v4l2src will just stop sending frames. I turned on some kernel-level debugging with :

Code: Select all

echo 0xffff | tee /sys/class/video4linux/video0/dev_debug
echo 0xffff | tee /sys/class/video4linux/video2/dev_debug
echo 0xffff | tee /sys/class/video4linux/video4/dev_debug
echo 0x1f5f | tee /sys/module/uvcvideo/parameters/trace
Sometimes, the USB device disconnects (video4, which was at frame 426180... note it gets a few more frames with repeated timing info, then the 'Failed to resubmit URB (-19).' messages start showing up and no frame 426189 ever shows up):

Code: Select all

...
Aug 18 09:20:10 hel-microdas kernel: [ 7221.531025] uvcvideo: frame 185963 stats: 0/289/289 packets, 0/0/289 pts (!early initial), 288/289 scr, last pts/stc/sof 4171260713/4172340861/1316
Aug 18 09:20:10 hel-microdas kernel: [ 7221.532024] uvcvideo: frame 426181 stats: 0/3/3 packets, 0/0/3 pts (!early initial), 2/3 scr, last pts/stc/sof 4191876618/4192070873/1758
Aug 18 09:20:10 hel-microdas kernel: [ 7221.532036] uvcvideo: frame 426182 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 4192127946/4192130871/1762
Aug 18 09:20:10 hel-microdas kernel: [ 7221.540026] uvcvideo: frame 426183 stats: 0/2/2 packets, 0/0/2 pts (!early initial), 1/2 scr, last pts/stc/sof 4192127946/4192190871/1766
Aug 18 09:20:10 hel-microdas kernel: [ 7221.540038] uvcvideo: frame 426184 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 4191876618/4191950872/1750
Aug 18 09:20:10 hel-microdas kernel: [ 7221.547995] uvcvideo: frame 118914 stats: 0/131/480 packets, 0/0/480 pts (!early initial), 479/480 scr, last pts/stc/sof 4205548233/4206447798/622
Aug 18 09:20:10 hel-microdas kernel: [ 7221.552151] uvcvideo: frame 426185 stats: 0/3/3 packets, 0/0/3 pts (!early initial), 2/3 scr, last pts/stc/sof 4191876618/4192070873/1758
Aug 18 09:20:10 hel-microdas kernel: [ 7221.552162] uvcvideo: frame 426186 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 4192127946/4192130871/1762
Aug 18 09:20:10 hel-microdas kernel: [ 7221.558598] usb 1-1.4: USB disconnect, device number 6
Aug 18 09:20:10 hel-microdas kernel: [ 7221.560153] uvcvideo: frame 426187 stats: 0/2/2 packets, 0/0/2 pts (!early initial), 1/2 scr, last pts/stc/sof 4192127946/4192190871/1766
Aug 18 09:20:10 hel-microdas kernel: [ 7221.560164] uvcvideo: frame 426188 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 4191876618/4191950872/1750
Aug 18 09:20:10 hel-microdas kernel: [ 7221.560176] uvcvideo: Failed to resubmit video URB (-19).
...
Sometimes, the stream seems to get hung up in the v4l2_poll() call, while the uvcvideo driver keeps sending 4 frames with the same timing information over and over again as above, except in this case there is no USB disconnect message and the 4 frames with the repeated timing are sent until stream off. I've annotated the contents of the /var/log/debug from that run to illustrate:

Code: Select all

*** uvcvideo frame message that has a frame number that matches the last sequence number reported by video0 below, this triggers the last return from v4l2_poll and DQBUF
Aug 28 10:08:17 hel-microdas kernel: [ 8551.780429] uvcvideo: frame 193656 stats: 0/131/400 packets, 0/0/400 pts (!early initial), 399/400 scr, last pts/stc/sof 3073816655/3074566285/1012 <-- frame matches sequence number in last DQBUF below
*** Last poll that doesn't timeout before the freeze ***:
Aug 28 10:08:17 hel-microdas kernel: [ 8551.796439] videodev: v4l2_poll: video0: poll: 00000041
...
*** Last DQBUF ***:
Aug 28 10:08:17 hel-microdas kernel: [ 8551.796482] video0: VIDIOC_DQBUF: 02:22:31.00787348 index=5, type=vid-cap, flags=0x00012001, field=none, sequence=193656, memory=mmap, bytesused=76424, offset/userptr=0x8cf000, length=1843789
Aug 28 10:08:17 hel-microdas kernel: [ 8551.796509] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
Aug 28 10:08:17 hel-microdas kernel: [ 8551.796708] videodev: v4l2_poll: video0: poll: 00000000 <-- poll times out?
Aug 28 10:08:17 hel-microdas kernel: [ 8551.796738] video0: VIDIOC_QBUF: 00:00:00.00000000 index=18, type=vid-cap, flags=0x00012003, field=none, sequence=0, memory=mmap, bytesused=0, offset/userptr=0x1fb6000, length=1843789 <-- QBUF a
*** video0 isn't heard from again until stop of stream, but uvcvideo keeps reporting frames, seemingly at a rather high rate based on log timestamps, and repeating the same 4 sets of PTS/STC/SOF ad infinitum
...
Aug 28 10:08:17 hel-microdas kernel: [ 8551.828486] uvcvideo: frame 193657 stats: 0/130/401 packets, 0/0/401 pts (!early initial), 400/401 scr, last pts/stc/sof 3074567615/3075318163/1062
Aug 28 10:08:17 hel-microdas kernel: [ 8551.836419] uvcvideo: frame 193658 stats: 0/40/43 packets, 0/0/43 pts (!early initial), 42/43 scr, last pts/stc/sof 3075318575/3075398797/1067
Aug 28 10:08:17 hel-microdas kernel: [ 8551.836430] uvcvideo: frame 193659 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3074567615/3075128788/1049
...
Aug 28 10:08:17 hel-microdas kernel: [ 8551.852382] uvcvideo: frame 193660 stats: 0/4/4 packets, 0/0/4 pts (!early initial), 3/4 scr, last pts/stc/sof 3074567615/3075308788/1061
Aug 28 10:08:17 hel-microdas kernel: [ 8551.852394] uvcvideo: frame 193661 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3075318575/3075368794/1065
Aug 28 10:08:17 hel-microdas kernel: [ 8551.856388] uvcvideo: frame 193662 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3075318575/3075368794/1065
Aug 28 10:08:17 hel-microdas kernel: [ 8551.856401] uvcvideo: frame 193663 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3074567615/3075128788/1049
Aug 28 10:08:17 hel-microdas kernel: [ 8551.860440] uvcvideo: frame 171535 stats: 0/131/480 packets, 0/0/480 pts (!early initial), 479/480 scr, last pts/stc/sof 3065653578/3066552577/551 <--frame for a different device
Aug 28 10:08:17 hel-microdas kernel: [ 8551.872534] uvcvideo: frame 193664 stats: 0/4/4 packets, 0/0/4 pts (!early initial), 3/4 scr, last pts/stc/sof 3074567615/3075308788/1061
Aug 28 10:08:17 hel-microdas kernel: [ 8551.872546] uvcvideo: frame 193665 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3075318575/3075368794/1065
Aug 28 10:08:17 hel-microdas kernel: [ 8551.876535] uvcvideo: frame 193666 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3075318575/3075368794/1065
Aug 28 10:08:17 hel-microdas kernel: [ 8551.876546] uvcvideo: frame 193667 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3074567615/3075128788/1049
*** These 4 sets are still repeating, 7.5 hours later ***
...
Aug 28 17:38:58 hel-microdas kernel: [35592.762059] uvcvideo: frame 5579196 stats: 0/4/4 packets, 0/0/4 pts (!early initial), 3/4 scr, last pts/stc/sof 3074567615/3075308788/1061
Aug 28 17:38:58 hel-microdas kernel: [35592.762072] uvcvideo: frame 5579197 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3075318575/3075368794/1065
Aug 28 17:38:58 hel-microdas kernel: [35592.763322] uvcvideo: frame 1344751 stats: 0/131/161 packets, 0/0/161 pts (!early initial), 160/161 scr, last pts/stc/sof 598397722/598697866/1577
Aug 28 17:38:58 hel-microdas kernel: [35592.766052] uvcvideo: frame 5579198 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3075318575/3075368794/1065
Aug 28 17:38:58 hel-microdas kernel: [35592.766063] uvcvideo: frame 5579199 stats: 0/1/1 packets, 0/0/1 pts (!early initial), 0/1 scr, last pts/stc/sof 3074567615/3075128788/1049
...
*** V4L2, though, remains "frozen" until stopping the stream, returning from poll with 0 result, meaning timeout ***:
Aug 28 17:38:58 hel-microdas kernel: [35592.807622] videodev: v4l2_poll: video0: poll: 00000000
...
Aug 28 17:38:58 hel-microdas kernel: [35592.855284] video0: VIDIOC_QBUF: 00:00:00.00000000 index=5, type=vid-cap, flags=0x00012003, field=none, sequence=0, memory=mmap, bytesused=0, offset/userptr=0x8cf000, length=1843789 <-- finally QBUFs the last buffer it successfully DQBUF'd 7.5 hours previously
...
Aug 28 17:38:58 hel-microdas kernel: [35592.900709] video0: VIDIOC_STREAMOFF: type=vid-cap
...
Aug 28 17:38:58 hel-microdas kernel: [35592.912452] video0: VIDIOC_REQBUFS: count=0, type=vid-cap, memory=mmap
...
Aug 28 17:38:59 hel-microdas kernel: [35592.927767] videodev: v4l2_release: video0: release
There does not seem to be any rhyme or reason to which camera becomes afflicted with which problem at any particular time, and there are 2 different manufacturer/models of camera in play. USB VCC seems stable enough on the osciliscope.

Anyone have any insight as to what might be going on? Do we still have USB hardware issues in the Pi 4? I feel like these are actually symptoms of maybe more than one problem, but the repeated timing info in those frames getting blasted through seems particularly insidious and like there might be a driver issue either in V4L2 or UVC.

Thanks in advance!

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2508
Joined: Thu Jul 11, 2013 2:37 pm

Re: Pi 4B: UVC cameras stop sending frames after random interval

Thu Sep 17, 2020 9:38 am

Spurious device disconnects are usually indicative of power issues - which may be marginal or transient in nature. Three cameras plugged in at once may be pushing it.

What happens if you use a powered hub between the Pi and the cameras?
Rockets are loud.
https://astro-pi.org

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Sat Sep 19, 2020 2:54 am

I had a scope across VCC and GND on the dual USB2 stack set to trigger at 4.75VDC, and didn't catch anything, but I also suspected power for the disconnect. I'll try and get my hands on a powered hub.

Any idea what might be happening under the circumstances where no disconnect happens?

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Fri Oct 09, 2020 4:37 am

Finally got around to trying a powered hub, but unfortunately it did not solve the problem. The system recorded for about 2 hours, then the hub itself experienced a disconnect from the Pi, taking all three cameras with it, after which the whole ensemble immediately reconnected:

Code: Select all

Oct  3 06:46:11 hel-microdas kernel: [ 1151.147040] usb 1-1.3: USB disconnect, device number 4
Oct  3 06:46:11 hel-microdas kernel: [ 1151.147050] usb 1-1.3.1: USB disconnect, device number 6
Oct  3 06:46:11 hel-microdas kernel: [ 1151.147992] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.149122] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.149998] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.152117] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.153123] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.153999] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.156134] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.157253] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.158012] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.160126] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.161268] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.162004] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.164142] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.165223] uvcvideo: Failed to resubmit video URB (-19).
Oct  3 06:46:11 hel-microdas kernel: [ 1151.166283] usb 1-1.3.2: USB disconnect, device number 7
Oct  3 06:46:11 hel-microdas kernel: [ 1151.187950] usb 1-1.3.3: USB disconnect, device number 8
Oct  3 06:46:11 hel-microdas kernel: [ 1151.388282] usb 1-1.3: new high-speed USB device number 9 using xhci_hcd
Oct  3 06:46:11 hel-microdas kernel: [ 1151.466593] usb 1-1.3: New USB device found, idVendor=0409, idProduct=005a, bcdDevice= 1.00
Oct  3 06:46:11 hel-microdas kernel: [ 1151.466603] usb 1-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Oct  3 06:46:11 hel-microdas kernel: [ 1151.468384] hub 1-1.3:1.0: USB hub found
Oct  3 06:46:11 hel-microdas kernel: [ 1151.468505] hub 1-1.3:1.0: 4 ports detected
Oct  3 06:46:12 hel-microdas kernel: [ 1151.757307] usb 1-1.3.1: new high-speed USB device number 10 using xhci_hcd
Oct  3 06:46:12 hel-microdas kernel: [ 1151.886297] usb 1-1.3.1: New USB device found, idVendor=058f, idProduct=3822, bcdDevice= 0.00
Oct  3 06:46:12 hel-microdas kernel: [ 1151.886308] usb 1-1.3.1: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Oct  3 06:46:12 hel-microdas kernel: [ 1151.886314] usb 1-1.3.1: Product: USB 2.0 HD Camera
Oct  3 06:46:12 hel-microdas kernel: [ 1151.891346] uvcvideo: Found UVC 1.00 device USB 2.0 HD Camera  (058f:3822)
Oct  3 06:46:12 hel-microdas kernel: [ 1151.919059] uvcvideo 1-1.3.1:1.0: Entity type for entity Processing 2 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1151.919070] uvcvideo 1-1.3.1:1.0: Entity type for entity Extension 6 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1151.919080] uvcvideo 1-1.3.1:1.0: Entity type for entity Camera 1 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1151.921034] input: USB 2.0 HD Camera : USB 2.0 HD  as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.1/1-1.3.1:1.0/input/input3
Oct  3 06:46:12 hel-microdas kernel: [ 1151.997282] usb 1-1.3.2: new high-speed USB device number 11 using xhci_hcd
Oct  3 06:46:12 hel-microdas kernel: [ 1152.161188] usb 1-1.3.2: New USB device found, idVendor=05a3, idProduct=9230, bcdDevice= 1.00
Oct  3 06:46:12 hel-microdas kernel: [ 1152.161197] usb 1-1.3.2: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct  3 06:46:12 hel-microdas kernel: [ 1152.161203] usb 1-1.3.2: Product: USB 2.0 Camera
Oct  3 06:46:12 hel-microdas kernel: [ 1152.161209] usb 1-1.3.2: Manufacturer: HD Camera Manufacturer
Oct  3 06:46:12 hel-microdas kernel: [ 1152.169968] uvcvideo: Found UVC 1.00 device USB 2.0 Camera (05a3:9230)
Oct  3 06:46:12 hel-microdas kernel: [ 1152.226698] uvcvideo 1-1.3.2:1.0: Entity type for entity Extension 3 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1152.226710] uvcvideo 1-1.3.2:1.0: Entity type for entity Processing 2 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1152.226717] uvcvideo 1-1.3.2:1.0: Entity type for entity Camera 1 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1152.227062] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.2/1-1.3.2:1.0/input/input4
Oct  3 06:46:12 hel-microdas kernel: [ 1152.306276] usb 1-1.3.3: new high-speed USB device number 12 using xhci_hcd
Oct  3 06:46:12 hel-microdas kernel: [ 1152.480539] usb 1-1.3.3: New USB device found, idVendor=05a3, idProduct=9230, bcdDevice= 1.00
Oct  3 06:46:12 hel-microdas kernel: [ 1152.480549] usb 1-1.3.3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct  3 06:46:12 hel-microdas kernel: [ 1152.480555] usb 1-1.3.3: Product: USB 2.0 Camera
Oct  3 06:46:12 hel-microdas kernel: [ 1152.480561] usb 1-1.3.3: Manufacturer: HD Camera Manufacturer
Oct  3 06:46:12 hel-microdas kernel: [ 1152.487308] uvcvideo: Found UVC 1.00 device USB 2.0 Camera (05a3:9230)
Oct  3 06:46:12 hel-microdas kernel: [ 1152.541910] uvcvideo 1-1.3.3:1.0: Entity type for entity Extension 3 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1152.541921] uvcvideo 1-1.3.3:1.0: Entity type for entity Processing 2 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1152.541928] uvcvideo 1-1.3.3:1.0: Entity type for entity Camera 1 was not initialized!
Oct  3 06:46:12 hel-microdas kernel: [ 1152.542165] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.3/1-1.3.3:1.0/input/input5
Oct  3 06:46:14 hel-microdas mtp-probe: checking bus 1, device 12: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.3"
Oct  3 06:46:14 hel-microdas mtp-probe: bus: 1, device: 12 was not an MTP device
Oct  3 06:46:14 hel-microdas mtp-probe: checking bus 1, device 11: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.2"
Oct  3 06:46:14 hel-microdas mtp-probe: bus: 1, device: 11 was not an MTP device
Oct  3 06:46:14 hel-microdas systemd-udevd[12105]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct  3 06:46:14 hel-microdas systemd-udevd[12109]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct  3 06:46:14 hel-microdas systemd-udevd[13026]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct  3 06:46:16 hel-microdas mtp-probe: checking bus 1, device 11: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.2"
Oct  3 06:46:16 hel-microdas mtp-probe: checking bus 1, device 10: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.1"
Oct  3 06:46:16 hel-microdas mtp-probe: bus: 1, device: 11 was not an MTP device
Oct  3 06:46:16 hel-microdas mtp-probe: bus: 1, device: 10 was not an MTP device
Oct  3 06:46:16 hel-microdas mtp-probe: checking bus 1, device 12: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3.3"
Oct  3 06:46:16 hel-microdas mtp-probe: bus: 1, device: 12 was not an MTP device
I think we can rule out power draw from the cameras causing the disconnects at this point.

Any ideas where to go from here?

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2508
Joined: Thu Jul 11, 2013 2:37 pm

Re: Pi 4B: UVC cameras stop sending frames after random interval

Fri Oct 09, 2020 12:14 pm

Weird - the whole tree is indeed disconnecting.

This may sound like an odd suggestion, but can you plug the hub in via the USB3.0 ports and not the USB2.0 ports? There may be something mechanical going on.
Rockets are loud.
https://astro-pi.org

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Wed Oct 14, 2020 1:46 am

We'll try the hub in the USB 3.0 port, but honestly we've had cameras disconnect from there, as well. This is happening on multiple Pi 4 B boards, so it's not just one single board having an issue, either.

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Thu Oct 15, 2020 9:18 pm

We tried the hub in the USB 3.0 port, and saw it disconnect after 12 minutes of collecting video on all 3 cameras:

Code: Select all

Oct 14 17:12:10 hel-microdas kernel: [  736.052993] IPv6: ADDRCONF(NETDEV_CHANGE): can0: link becomes ready
Oct 14 17:12:10 hel-microdas kernel: [  736.430660] usb 1-1.1: USB disconnect, device number 3
Oct 14 17:12:10 hel-microdas kernel: [  736.430674] usb 1-1.1.1: USB disconnect, device number 5
Oct 14 17:12:10 hel-microdas kernel: [  736.431002] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.432252] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.433395] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.435041] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.436259] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.437401] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.439050] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.440261] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.441404] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.443042] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.444395] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.445381] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.447043] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.448382] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.449371] uvcvideo: Failed to resubmit video URB (-19).
Oct 14 17:12:10 hel-microdas kernel: [  736.451888] usb 1-1.1.2: USB disconnect, device number 7
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event4'
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event5'
Oct 14 17:12:10 hel-microdas kernel: [  736.483602] usb 1-1.1.3: USB disconnect, device number 8
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event6'
Oct 14 17:12:10 hel-microdas kernel: [  736.500716] usb 1-1.1.4: USB disconnect, device number 9
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event0'
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event1'
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event2'
Oct 14 17:12:10 hel-microdas thd[369]: Error reading device '/dev/input/event3'
Oct 14 17:12:11 hel-microdas kernel: [  736.765300] usb 1-1.1: new high-speed USB device number 10 using xhci_hcd
Oct 14 17:12:11 hel-microdas kernel: [  736.842734] usb 1-1.1: New USB device found, idVendor=0409, idProduct=005a, bcdDevice= 1.00
Oct 14 17:12:11 hel-microdas kernel: [  736.842744] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Oct 14 17:12:11 hel-microdas kernel: [  736.844258] hub 1-1.1:1.0: USB hub found
Oct 14 17:12:11 hel-microdas kernel: [  736.844348] hub 1-1.1:1.0: 4 ports detected
Oct 14 17:12:11 hel-microdas kernel: [  737.136301] usb 1-1.1.1: new high-speed USB device number 11 using xhci_hcd
Oct 14 17:12:11 hel-microdas kernel: [  737.306879] usb 1-1.1.1: New USB device found, idVendor=05a3, idProduct=9230, bcdDevice= 1.00
Oct 14 17:12:11 hel-microdas kernel: [  737.306890] usb 1-1.1.1: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 14 17:12:11 hel-microdas kernel: [  737.306896] usb 1-1.1.1: Product: USB 2.0 Camera
Oct 14 17:12:11 hel-microdas kernel: [  737.306902] usb 1-1.1.1: Manufacturer: HD Camera Manufacturer
Oct 14 17:12:11 hel-microdas kernel: [  737.313645] uvcvideo: Found UVC 1.00 device USB 2.0 Camera (05a3:9230)
Oct 14 17:12:11 hel-microdas kernel: [  737.368637] uvcvideo 1-1.1.1:1.0: Entity type for entity Extension 3 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.368652] uvcvideo 1-1.1.1:1.0: Entity type for entity Processing 2 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.368660] uvcvideo 1-1.1.1:1.0: Entity type for entity Camera 1 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.369407] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/input/input7
Oct 14 17:12:11 hel-microdas kernel: [  737.453647] usb 1-1.1.2: new high-speed USB device number 12 using xhci_hcd
Oct 14 17:12:11 hel-microdas kernel: [  737.616404] usb 1-1.1.2: New USB device found, idVendor=05a3, idProduct=9230, bcdDevice= 1.00
Oct 14 17:12:11 hel-microdas kernel: [  737.616414] usb 1-1.1.2: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 14 17:12:11 hel-microdas kernel: [  737.616419] usb 1-1.1.2: Product: USB 2.0 Camera
Oct 14 17:12:11 hel-microdas kernel: [  737.616425] usb 1-1.1.2: Manufacturer: HD Camera Manufacturer
Oct 14 17:12:11 hel-microdas kernel: [  737.623130] uvcvideo: Found UVC 1.00 device USB 2.0 Camera (05a3:9230)
Oct 14 17:12:11 hel-microdas kernel: [  737.679394] uvcvideo 1-1.1.2:1.0: Entity type for entity Extension 3 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.679405] uvcvideo 1-1.1.2:1.0: Entity type for entity Processing 2 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.679412] uvcvideo 1-1.1.2:1.0: Entity type for entity Camera 1 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.680035] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0/input/input8
Oct 14 17:12:12 hel-microdas kernel: [  737.759287] usb 1-1.1.3: new high-speed USB device number 13 using xhci_hcd
Oct 14 17:12:12 hel-microdas kernel: [  737.888392] usb 1-1.1.3: New USB device found, idVendor=058f, idProduct=3822, bcdDevice= 0.00
Oct 14 17:12:12 hel-microdas kernel: [  737.888416] usb 1-1.1.3: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Oct 14 17:12:12 hel-microdas kernel: [  737.888422] usb 1-1.1.3: Product: USB 2.0 HD Camera
Oct 14 17:12:12 hel-microdas kernel: [  737.893208] uvcvideo: Found UVC 1.00 device USB 2.0 HD Camera  (058f:3822)
Oct 14 17:12:12 hel-microdas kernel: [  737.920092] uvcvideo 1-1.1.3:1.0: Entity type for entity Processing 2 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.368660] uvcvideo 1-1.1.1:1.0: Entity type for entity Camera 1 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.369407] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/input/input7
Oct 14 17:12:11 hel-microdas kernel: [  737.453647] usb 1-1.1.2: new high-speed USB device number 12 using xhci_hcd
Oct 14 17:12:11 hel-microdas kernel: [  737.616404] usb 1-1.1.2: New USB device found, idVendor=05a3, idProduct=9230, bcdDevice= 1.00
Oct 14 17:12:11 hel-microdas kernel: [  737.616414] usb 1-1.1.2: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 14 17:12:11 hel-microdas kernel: [  737.616419] usb 1-1.1.2: Product: USB 2.0 Camera
Oct 14 17:12:11 hel-microdas kernel: [  737.616425] usb 1-1.1.2: Manufacturer: HD Camera Manufacturer
Oct 14 17:12:11 hel-microdas kernel: [  737.623130] uvcvideo: Found UVC 1.00 device USB 2.0 Camera (05a3:9230)
Oct 14 17:12:11 hel-microdas kernel: [  737.679394] uvcvideo 1-1.1.2:1.0: Entity type for entity Extension 3 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.679405] uvcvideo 1-1.1.2:1.0: Entity type for entity Processing 2 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.679412] uvcvideo 1-1.1.2:1.0: Entity type for entity Camera 1 was not initialized!
Oct 14 17:12:11 hel-microdas kernel: [  737.680035] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0/input/input8
Oct 14 17:12:12 hel-microdas kernel: [  737.759287] usb 1-1.1.3: new high-speed USB device number 13 using xhci_hcd
Oct 14 17:12:12 hel-microdas kernel: [  737.888392] usb 1-1.1.3: New USB device found, idVendor=058f, idProduct=3822, bcdDevice= 0.00
Oct 14 17:12:12 hel-microdas kernel: [  737.888416] usb 1-1.1.3: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Oct 14 17:12:12 hel-microdas kernel: [  737.888422] usb 1-1.1.3: Product: USB 2.0 HD Camera
Oct 14 17:12:12 hel-microdas kernel: [  737.893208] uvcvideo: Found UVC 1.00 device USB 2.0 HD Camera  (058f:3822)
Oct 14 17:12:12 hel-microdas kernel: [  737.920092] uvcvideo 1-1.1.3:1.0: Entity type for entity Processing 2 was not initialized!
Oct 14 17:12:12 hel-microdas kernel: [  737.920105] uvcvideo 1-1.1.3:1.0: Entity type for entity Extension 6 was not initialized!
Oct 14 17:12:12 hel-microdas kernel: [  737.920114] uvcvideo 1-1.1.3:1.0: Entity type for entity Camera 1 was not initialized!
Oct 14 17:12:12 hel-microdas kernel: [  737.920382] input: USB 2.0 HD Camera : USB 2.0 HD  as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.3/1-1.1.3:1.0/input/input9
Oct 14 17:12:12 hel-microdas kernel: [  738.000286] usb 1-1.1.4: new low-speed USB device number 14 using xhci_hcd
Oct 14 17:12:12 hel-microdas kernel: [  738.101138] usb 1-1.1.4: New USB device found, idVendor=05c7, idProduct=2012, bcdDevice= 1.03
Oct 14 17:12:12 hel-microdas kernel: [  738.101148] usb 1-1.1.4: New USB device strings: Mfr=0, Product=1, SerialNumber=0
Oct 14 17:12:12 hel-microdas kernel: [  738.101154] usb 1-1.1.4: Product: USB Keyboard + Mouse
Oct 14 17:12:12 hel-microdas kernel: [  738.115190] input: USB Keyboard + Mouse as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4/1-1.1.4:1.0/0003:05C7:2012.0003/input/input10
Oct 14 17:12:12 hel-microdas kernel: [  738.167118] hid-generic 0003:05C7:2012.0003: input,hidraw0: USB HID v1.10 Keyboard [USB Keyboard + Mouse] on usb-0000:01:00.0-1.1.4/input0
Oct 14 17:12:12 hel-microdas kernel: [  738.180064] input: USB Keyboard + Mouse Mouse as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4/1-1.1.4:1.1/0003:05C7:2012.0004/input/input11
Oct 14 17:12:12 hel-microdas kernel: [  738.181013] input: USB Keyboard + Mouse System Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4/1-1.1.4:1.1/0003:05C7:2012.0004/input/input12
Oct 14 17:12:12 hel-microdas kernel: [  738.233319] input: USB Keyboard + Mouse Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4/1-1.1.4:1.1/0003:05C7:2012.0004/input/input13
Oct 14 17:12:12 hel-microdas kernel: [  738.234145] hid-generic 0003:05C7:2012.0004: input,hidraw1: USB HID v1.10 Mouse [USB Keyboard + Mouse] on usb-0000:01:00.0-1.1.4/input1
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 13: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.3"
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 12: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.2"
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 11: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.1"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 12 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 14: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 11 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 14 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 13 was not an MTP device
Oct 14 17:12:13 hel-microdas systemd-udevd[9173]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9177]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9187]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9175]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9173]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9184]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9177]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9187]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 14: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 14 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 14: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 14 was not an MTP device
Oct 14 17:12:15 hel-microdas mtp-probe: checking bus 1, device 11: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.1"
Oct 14 17:12:15 hel-microdas mtp-probe: bus: 1, device: 11 was not an MTP device
Oct 14 17:12:15 hel-microdas mtp-probe: checking bus 1, device 12: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.2"
Oct 14 17:12:15 hel-microdas mtp-probe: bus: 1, device: 12 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 14: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 11 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 14 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 13 was not an MTP device
Oct 14 17:12:13 hel-microdas systemd-udevd[9173]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9177]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9187]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9175]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9173]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9184]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9177]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas systemd-udevd[9187]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 14: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 14 was not an MTP device
Oct 14 17:12:13 hel-microdas mtp-probe: checking bus 1, device 14: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.4"
Oct 14 17:12:13 hel-microdas mtp-probe: bus: 1, device: 14 was not an MTP device
Oct 14 17:12:15 hel-microdas mtp-probe: checking bus 1, device 11: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.1"
Oct 14 17:12:15 hel-microdas mtp-probe: bus: 1, device: 11 was not an MTP device
Oct 14 17:12:15 hel-microdas mtp-probe: checking bus 1, device 12: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.2"
Oct 14 17:12:15 hel-microdas mtp-probe: bus: 1, device: 12 was not an MTP device
Oct 14 17:12:15 hel-microdas mtp-probe: checking bus 1, device 13: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1.3"
Oct 14 17:12:15 hel-microdas mtp-probe: bus: 1, device: 13 was not an MTP device
We're still really stumped.

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Fri Oct 23, 2020 6:30 am

@jdb, any other suggestions? This seems like something in the driver stack or the VL805 itself is getting hosed.

lingon
Posts: 168
Joined: Fri Aug 26, 2011 7:31 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Fri Oct 23, 2020 8:50 am

Have you read the UVC FAQ at http://www.ideasonboard.org/uvc/faq/? Disabling USB autosuspend, adding quirks or reducing USB bandwidth might be worth trying according to the instructions on that page.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2508
Joined: Thu Jul 11, 2013 2:37 pm

Re: Pi 4B: UVC cameras stop sending frames after random interval

Fri Oct 23, 2020 11:43 am

I'm out of ideas at this point.

lingon wrote:
Fri Oct 23, 2020 8:50 am
Have you read the UVC FAQ at http://www.ideasonboard.org/uvc/faq/? Disabling USB autosuspend, adding quirks or reducing USB bandwidth might be worth trying according to the instructions on that page.
Disabling autosuspend might be worth investigating indeed. UVC cameras are one of the few classes of devices that Linux enables suspend on by default (with the implication that the whole USB tree is suspended if all downstream cameras are).
Rockets are loud.
https://astro-pi.org

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Tue Oct 27, 2020 7:38 am

lingon wrote:
Fri Oct 23, 2020 8:50 am
Have you read the UVC FAQ at http://www.ideasonboard.org/uvc/faq/? Disabling USB autosuspend, adding quirks or reducing USB bandwidth might be worth trying according to the instructions on that page.
I have had to dip into that FAQ many a time over the years, actually :). I spend a not-insignificant part of my job configuring systems that record video from between 1-8 UVC devices simultaneously, but the Raspberry Pi is the only system that is exhibiting these particular symptoms with these cameras. The others are x86_64-based, and are not having these issues with these cameras. Autosuspend is currently the default 2, but our use case has the cameras start streaming and continue until just before the system shuts down, so they are never idle. I'll still try disabling it, though. The cameras aren't exhibiting any behavior that the quirks address. I've run into bandwidth issues mentioned in the FAQ in the past, but that bites you when you try to start the stream, not in the middle of all of the cameras actively streaming.

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Mon Nov 02, 2020 6:13 am

No luck with autosuspend. I switched every USB and Video4Linux2 power control flag to on:

Code: Select all

#!/bin/bash

for dev in /sys/bus/usb/devices/*/power/control; do
        echo $dev
        echo on > $dev
done
for dev in /sys/class/video4linux/video*/power/control; do
        echo $dev
        echo on > $dev
done
...but still had a camera reset within an hour of turning on all three streams:

Code: Select all

Oct 28 09:40:18 hel-microdas kernel: [89610.608228] usb 1-1.4: USB disconnect, device number 6
Oct 28 09:40:18 hel-microdas kernel: [89610.612024] uvcvideo: Failed to resubmit video URB (-19).
Oct 28 09:40:18 hel-microdas kernel: [89610.616023] uvcvideo: Failed to resubmit video URB (-19).
Oct 28 09:40:18 hel-microdas kernel: [89610.620018] uvcvideo: Failed to resubmit video URB (-19).
Oct 28 09:40:18 hel-microdas kernel: [89610.798997] usb 1-1.4: new high-speed USB device number 8 using xhci_hcd
Oct 28 09:40:18 hel-microdas kernel: [89610.958091] usb 1-1.4: New USB device found, idVendor=05a3, idProduct=9230, bcdDevice= 1.00
Oct 28 09:40:18 hel-microdas kernel: [89610.958106] usb 1-1.4: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 28 09:40:18 hel-microdas kernel: [89610.958112] usb 1-1.4: Product: USB 2.0 Camera
Oct 28 09:40:18 hel-microdas kernel: [89610.958118] usb 1-1.4: Manufacturer: HD Camera Manufacturer
Oct 28 09:40:18 hel-microdas kernel: [89610.965907] uvcvideo: Found UVC 1.00 device USB 2.0 Camera (05a3:9230)
Oct 28 09:40:18 hel-microdas kernel: [89611.022089] uvcvideo 1-1.4:1.0: Entity type for entity Extension 3 was not initialized!
Oct 28 09:40:18 hel-microdas kernel: [89611.022100] uvcvideo 1-1.4:1.0: Entity type for entity Processing 2 was not initialized!
Oct 28 09:40:18 hel-microdas kernel: [89611.022107] uvcvideo 1-1.4:1.0: Entity type for entity Camera 1 was not initialized!
Oct 28 09:40:18 hel-microdas kernel: [89611.022330] input: USB 2.0 Camera: HD USB Camera as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.0/input/input3
Oct 28 09:40:20 hel-microdas kernel: <1052>[89612.715462] systemd-udevd[6347]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
After the reset, the power control was back to auto, while the other two cameras were still on:

Code: Select all

$ cat /sys/bus/usb/devices/1-1.4/power/control 
auto
$ cat /sys/bus/usb/devices/1-1.3/power/control 
on
$ cat /sys/bus/usb/devices/1-1.1.2/power/control 
on
Still very stumped.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2508
Joined: Thu Jul 11, 2013 2:37 pm

Re: Pi 4B: UVC cameras stop sending frames after random interval

Mon Nov 02, 2020 12:56 pm

Hang on, if I search for the vid:pid of the cameras in question, I get several hits about them randomly disconnecting - not just on Pi 4s. Pi 4 appears to be different in that the entire downstream tree gets disconnected and not just the device.

Key phrase was "ARC international" which appears to be what Linux thinks the manufacturer is.

I would assume that these are available in retail channels - do you have a supplier for the model you are using?
Rockets are loud.
https://astro-pi.org

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Wed Nov 18, 2020 8:40 am

Sorry for the delay in my response; I didn't see the reply come through for some reason!
Hang on, if I search for the vid:pid of the cameras in question, I get several hits about them randomly disconnecting - not just on Pi 4s. Pi 4 appears to be different in that the entire downstream tree gets disconnected and not just the device.
We've not seen the disconnects happening with these cameras on our x86_64-based platforms installed in similar (sometimes identical) conditions. Can't say I'm getting the same results from googling "05a3:9230 disconnect", although I see some recent patches in UVC video drivers and a similar post on the Raspberry Pi . Could you point me in the right direction?
I would assume that these are available in retail channels - do you have a supplier for the model you are using?
They are various lens and color/BW combos of ELP-USBFHD01M, pretty widely available on Amazon US, and I see at least one model on Amazon UK. We get them in bulk directly from www.elpcctv.com, though.

Thanks for the speedy reply; again sorry I didn't see it until now!

infiniteloup
Posts: 11
Joined: Sat Dec 14, 2019 8:57 am

Re: Pi 4B: UVC cameras stop sending frames after random interval

Thu Nov 19, 2020 7:20 pm

Hang on, if I search for the vid:pid of the cameras in question, I get several hits about them randomly disconnecting - not just on Pi 4s. Pi 4 appears to be different in that the entire downstream tree gets disconnected and not just the device.
I'd also explicitly point out, that only two of the cameras in question are ARC International. The third also drops randomly, and is a different model.

Return to “Troubleshooting”