GStreamer lost frames issue

digit

Hi there,
I was trying to do a Logitech BRIO 4K webcam streaming by the following GStreamer pipeline:

GST_DEBUG=3 gst-launch-1.0 -v v4l2src device=/dev/video9 io-mode=2 do-timestamp=false ! "image/jpeg,width=(int)3840,height=(int)2160,framerate=(fraction)30/1" ! mppjpegdec ! fpsdisplaysink video-sink=kmssink text-overlay=false fps-update-interval=10000 sync=false

It looked perfect in the beginning, but a lot of v4l2src lost frames WARNNINGs always start to appear in 20 mins and last for 5 ~ 6 mins. Simultaneously, I could see some kernel error logs appeared.
It's a periodically event because it would happen again and again in the next perfect 20 mins.

Platform: ROC-RK3566-PC_Buildroot_v1.2.4a
Kernel version: 4.19.232
GStreamer version: 1.20.0

Does anyone have any idea? Thanks in advance!

============================================================================================================================================

GStreamer logs:

0:11:10.136382621   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:11:08.740513147
0:11:10.236435423   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:11:08.840477855
0:11:10.334472266   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:11:08.940432938
0:11:10.934919330   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:11:09.540527813
...
...
...
0:16:53.807398054   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 2 - ts: 0:16:52.413444438
0:16:53.907282836   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 2 - ts: 0:16:52.513450146
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 28515, dropped: 0, current: 28.10, average: 28.18
0:16:58.907391425   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:16:57.513668480
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 28814, dropped: 0, current: 29.88, average: 28.20
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 29115, dropped: 0, current: 30.00, average: 28.22
0:17:18.706663087   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:17:17.314456480
0:17:18.806855698   961     0x10628120 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:17:17.414456439

============================================================================================================================================

dmesg logs:

Jul 15 02:03:42 RK356X kern.warn kernel: [  752.896860] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:03:42 RK356X kern.warn kernel: [  752.996874] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:03:42 RK356X kern.warn kernel: [  753.096806] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:03:42 RK356X kern.err kernel: [  753.096863] xhci-hcd xhci-hcd.4.auto: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 1
Jul 15 02:03:42 RK356X kern.warn kernel: [  753.096879] xhci-hcd xhci-hcd.4.auto: Looking for event-dma 00000000ef1320e0 trb-start 00000000ef1320f0 trb-end 00000000ef132140 seg-start 00000000ef132000 seg-end 00000000ef132ff0
Jul 15 02:03:43 RK356X kern.warn kernel: [  753.696897] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:03:43 RK356X kern.err kernel: [  753.697002] xhci-hcd xhci-hcd.4.auto: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 1
Jul 15 02:03:43 RK356X kern.warn kernel: [  753.697043] xhci-hcd xhci-hcd.4.auto: Looking for event-dma 00000000ef132fe0 trb-start 00000000ef001000 trb-end 00000000ef001050 seg-start 00000000ef001000 seg-end 00000000ef001ff0
Jul 15 02:03:43 RK356X kern.warn kernel: [  753.796857] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:03:43 RK356X kern.err kernel: [  753.796965] xhci-hcd xhci-hcd.4.auto: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 1
Jul 15 02:03:43 RK356X kern.warn kernel: [  753.797007] xhci-hcd xhci-hcd.4.auto: Looking for event-dma 00000000ef003d10 trb-start 00000000ef003d20 trb-end 00000000ef003d70 seg-start 00000000ef003000 seg-end 00000000ef003ff0
...
...
...
Jul 15 02:09:25 RK356X kern.warn kernel: [ 1096.257124] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:09:25 RK356X kern.err kernel: [ 1096.257235] xhci-hcd xhci-hcd.4.auto: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 1
Jul 15 02:09:25 RK356X kern.warn kernel: [ 1096.257278] xhci-hcd xhci-hcd.4.auto: Looking for event-dma 00000000ef002ec0 trb-start 00000000ef002ed0 trb-end 00000000ef002f20 seg-start 00000000ef002000 seg-end 00000000ef002ff0
Jul 15 02:09:25 RK356X kern.warn kernel: [ 1096.557123] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:09:25 RK356X kern.err kernel: [ 1096.557228] xhci-hcd xhci-hcd.4.auto: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 1
Jul 15 02:09:25 RK356X kern.warn kernel: [ 1096.557270] xhci-hcd xhci-hcd.4.auto: Looking for event-dma 00000000ef003650 trb-start 00000000ef003660 trb-end 00000000ef0036b0 seg-start 00000000ef003000 seg-end 00000000ef003ff0
Jul 15 02:09:26 RK356X kern.warn kernel: [ 1096.657121] xhci-hcd xhci-hcd.4.auto: WARN: HC couldn't access mem fast enough for slot 1 ep 2
Jul 15 02:09:26 RK356X kern.err kernel: [ 1096.657218] xhci-hcd xhci-hcd.4.auto: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 1
Jul 15 02:09:26 RK356X kern.warn kernel: [ 1096.657261] xhci-hcd xhci-hcd.4.auto: Looking for event-dma 00000000ef134380 trb-start 00000000ef134390 trb-end 00000000ef1343e0 seg-start 00000000ef134000 seg-end 00000000ef134ff0

============================================================================================================================================

Liuth

To play 4K image, you have to enable AFBC first
export GST_MPP_VIDEODEC_DEFAULT_ARM_AFBC=1
Then use video-sink="waylandsink fullscreen=true" instead of kmssink

digit

Hi Liuth,

Thanks for your reply.
I had tried the following pipeline, but no luck.

export GST_MPP_VIDEODEC_DEFAULT_ARM_AFBC=1
GST_DEBUG=3 gst-launch-1.0 -v v4l2src device=/dev/video9 io-mode=2 do-timestamp=false ! "image/jpeg,width=(int)3840,height=(int)2160,framerate=(fraction)30/1" ! mppjpegdec ! fpsdisplaysink video-sink="waylandsink fullscreen=true" text-overlay=false fps-update-interval=10000 sync=false

Lots of v4l2src lost frames WARNNINGs still start to appear in 10 mins and last for 5 ~ 6 mins. I could see the same kernel errors appeared simultaneously.
Moreover, waylandsink seemed like rendering in 15~20fps although fpsdisplaysink shown that it was almost 30fps.

Does AFBC support mppjpegdec?

============================================================================================================================================

GStreamer logs:

/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 17726, dropped: 0, current: 29.98, average: 29.99
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 18027, dropped: 0, current: 30.04, average: 29.99
0:10:04.365817500   972     0x1ee2f580 WARN                  mppdec gstmppdec.c:870:gst_mpp_dec_loop:<mppjpegdec0> can't process this frame
0:10:04.380713822   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 2 - ts: 0:10:04.272944195
0:10:09.039025151   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:08.929021737
0:10:09.637534590   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:09.528899361
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 18325, dropped: 0, current: 29.80, average: 29.99
0:10:16.703086427   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:16.593011779
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 18625, dropped: 0, current: 29.88, average: 29.99
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 18926, dropped: 0, current: 30.03, average: 29.99
0:10:35.833906821   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:35.728882070
0:10:36.039984316   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:35.928829612
0:10:38.269524480   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:38.160844362
0:10:41.434795602   972     0x1ee2ede0 WARN                 v4l2src gstv4l2src.c:1123:gst_v4l2src_create:<v4l2src0> lost frames detected: count = 1 - ts: 0:10:41.328791362
...
...

============================================================================================================================================