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
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
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).
...
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
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!