yet another v4l2h264enc problem

[cantilever52]

Hi all,

after lots of reading I've got videostreaming from Auvidea's TC358743 B101 board somehow working with Gstreamer. I'm using the following command:

Code: Select all

gst-launch-1.0 -v v4l2src io-mode=4 ! video/x-raw, format=UYVY, framerate=30/1 ! v4l2h264enc output-io-mode=5 ! video/x-h264 ! h264parse  ! mpegtsmux ! udpsink host=192.168.1.14 port=1234

On target machine (192.168.1.14) I can view stream with VLC, sadly with approx 1.5 secs delay that's not a main problem though. After I start and stop streaming few times (trying to tweak params to minimize delay), it stops working at all and dmesg contains beautiful messages like

Code: Select all

[ 3594.237005] videobuf2_common: driver bug: stop_streaming operation is leaving buf 1f8f17d2 in active state
[ 3608.086107] vc_sm_cma_vchi_rx_ack: received response 65568, throw away...
[ 3621.291157] vc_sm_cma_import_dmabuf: imported vc_sm_cma_get_buffer failed -512
[ 3621.291171] bcm2835_mmal_vchiq: vchiq_mmal_submit_buffer: vc_sm_import_dmabuf_fd failed, ret -512
[ 3621.291182] bcm2835-codec bcm2835-codec: device_run: Failed submitting ip buffer
[ 3621.291348] vc_sm_cma_import_dmabuf: imported vc_sm_cma_get_buffer failed -12
[ 3621.291358] bcm2835_mmal_vchiq: vchiq_mmal_submit_buffer: vc_sm_import_dmabuf_fd failed, ret -12
[ 3621.291368] bcm2835-codec bcm2835-codec: device_run: Failed submitting op buffer
[ 3621.291522] vc_sm_cma_import_dmabuf: imported vc_sm_cma_get_buffer failed -12
[ 3621.291532] bcm2835_mmal_vchiq: vchiq_mmal_submit_buffer: vc_sm_import_dmabuf_fd failed, ret -12
[ 3621.291542] bcm2835-codec bcm2835-codec: device_run: Failed submitting op buffer
[ 3621.291693] vc_sm_cma_import_dmabuf: imported vc_sm_cma_get_buffer failed -12
[ 3621.291703] bcm2835_mmal_vchiq: vchiq_mmal_submit_buffer: vc_sm_import_dmabuf_fd failed, ret -12
[ 3621.291712] bcm2835-codec bcm2835-codec: device_run: Failed submitting op buffer
[ 3621.291864] vc_sm_cma_import_dmabuf: imported vc_sm_cma_get_buffer failed -12
[ 3621.291874] bcm2835_mmal_vchiq: vchiq_mmal_submit_buffer: vc_sm_import_dmabuf_fd failed, ret -12
[ 3621.291883] bcm2835-codec bcm2835-codec: device_run: Failed submitting op buffer
[ 3621.314443] ------------[ cut here ]------------
[ 3621.314494] WARNING: CPU: 2 PID: 1163 at drivers/media/common/videobuf2/videobuf2-core.c:1688 __vb2_queue_cancel+0x158/0x1c8 [videobuf2_common]
[ 3621.314505] Modules linked in: bnep hci_uart btbcm serdev bluetooth ecdh_generic 8021q garp stp llc tc358743 brcmfmac brcmutil sha256_generic cfg80211 rfkill bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_unicam v4l2_mem2mem v4l2_dv_timings raspberrypi_hwmon bcm2835_mmal_vchiq(C) hwmon v4l2_fwnode videobuf2_dma_contig vc_sm_cma(C) v4l2_common videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev media i2c_bcm2835 rpivid_mem uio_pdrv_genirq uio cuse fuse i2c_dev ip_tables x_tables ipv6
[ 3621.314646] CPU: 2 PID: 1163 Comm: v4l2h264enc0:sr Tainted: G        WC        4.19.97-v7l+ #1294
[ 3621.314654] Hardware name: BCM2835
[ 3621.314688] [<c0212e04>] (unwind_backtrace) from [<c020d5e0>] (show_stack+0x20/0x24)
[ 3621.314709] [<c020d5e0>] (show_stack) from [<c09b15c8>] (dump_stack+0xe0/0x124)
[ 3621.314730] [<c09b15c8>] (dump_stack) from [<c0222544>] (__warn+0x104/0x11c)
[ 3621.314747] [<c0222544>] (__warn) from [<c0222694>] (warn_slowpath_null+0x50/0x58)
[ 3621.314780] [<c0222694>] (warn_slowpath_null) from [<bf20a104>] (__vb2_queue_cancel+0x158/0x1c8 [videobuf2_common])
[ 3621.314830] [<bf20a104>] (__vb2_queue_cancel [videobuf2_common]) from [<bf20abdc>] (vb2_core_queue_release+0x28/0x48 [videobuf2_common])
[ 3621.314871] [<bf20abdc>] (vb2_core_queue_release [videobuf2_common]) from [<bf23e5d8>] (vb2_queue_release+0x18/0x1c [videobuf2_v4l2])
[ 3621.314908] [<bf23e5d8>] (vb2_queue_release [videobuf2_v4l2]) from [<bf2fb5a8>] (v4l2_m2m_ctx_release+0x24/0x38 [v4l2_mem2mem])
[ 3621.314947] [<bf2fb5a8>] (v4l2_m2m_ctx_release [v4l2_mem2mem]) from [<bf325d9c>] (bcm2835_codec_release+0x64/0xcc [bcm2835_codec])
[ 3621.315032] [<bf325d9c>] (bcm2835_codec_release [bcm2835_codec]) from [<bf17e5b8>] (v4l2_release+0x48/0x8c [videodev])
[ 3621.315112] [<bf17e5b8>] (v4l2_release [videodev]) from [<c03d66fc>] (__fput+0xa4/0x1e8)
[ 3621.315133] [<c03d66fc>] (__fput) from [<c03d68b0>] (____fput+0x18/0x1c)
[ 3621.315154] [<c03d68b0>] (____fput) from [<c02426dc>] (task_work_run+0xbc/0xe0)
[ 3621.315173] [<c02426dc>] (task_work_run) from [<c0226bd0>] (do_exit+0x44c/0xc18)
[ 3621.315190] [<c0226bd0>] (do_exit) from [<c0227434>] (do_group_exit+0x4c/0xe4)
[ 3621.315209] [<c0227434>] (do_group_exit) from [<c0233780>] (get_signal+0x1a4/0x8cc)
[ 3621.315225] [<c0233780>] (get_signal) from [<c020c73c>] (do_signal+0x84/0x474)
[ 3621.315239] [<c020c73c>] (do_signal) from [<c020cd38>] (do_work_pending+0xdc/0xf4)
[ 3621.315254] [<c020cd38>] (do_work_pending) from [<c0201034>] (slow_work_pending+0xc/0x20)
[ 3621.315263] Exception stack(0xd9c65fb0 to 0xd9c65ff8)
[ 3621.315275] 5fa0:                                     b3200e38 00000002 00000000 00000000
[ 3621.315287] 5fc0: 00000008 b6fd3968 00000000 00000150 b45fe612 b3bff450 b63b7000 b3bfebec
[ 3621.315298] 5fe0: 00000002 b3bfe998 00000000 b6b83de0 80000010 b3200e38
[ 3621.315309] ---[ end trace 7af038655bc5baba ]---

I'm using Pi 4 with 4 GB of RAM, I have

Code: Select all

cma=256M

in kernel cmdline and

Code: Select all

gpu_mem=256

in config.txt

Code: Select all

Linux raspberry 4.19.97-v7l+ #1294 SMP Thu Jan 30 13:21:14 GMT 2020 armv7l GNU/Linux

Code: Select all

$ sudo rpi-update
 *** Raspberry Pi firmware updater by Hexxeh, enhanced by AndrewS and Dom
 *** Performing self-update
 *** Relaunching after update
 *** Raspberry Pi firmware updater by Hexxeh, enhanced by AndrewS and Dom
 *** Your firmware is already up to date
 

Running with

Code: Select all

GST_DEBUG=3

doesn't yield anything new but only this:

Code: Select all

0:00:00.004833179  1246  0x2016ec0 WARN         GST_PERFORMANCE gstbuffer.c:486:_priv_gst_buffer_initialize: No 64-bit atomic int defined for this platform/toolchain!
Setting pipeline to PAUSED ...
0:00:00.112124600  1246  0x2016ec0 WARN                    v4l2 gstv4l2object.c:4204:gst_v4l2_object_probe_caps:<v4l2h264enc0:src> Failed to probe pixel aspect ratio with VIDIOC_CROPCAP: Invalid argument

Reboot fixes it, but it would be cool to have it working without one. To me it looks like buffers somehow didn't get free after gstreamer termination and few subsequent runs just depleted all available memory...

[6by9]

Thanks for the report. I'm fairly certain that this is the same issue we tripped over the other day and a fix should be pushed imminently.

The id that is sent to the GPU is a 32 bit value, but when storing it in the list of outstanding messages it got stored as a 16 bit value. When the response comes back, if you've sent over 65536 messages then it can't find the matching command to complete. Looking at your "vc_sm_cma_vchi_rx_ack: received response 65568, throw away..." log lines, that's exactly the point you've hit.

[6by9]

If you flip the buffer allocation around the other way with

Code: Select all

v4l2src io-mode=5 ! video/x-raw, format=UYVY, framerate=30/1 ! v4l2h264enc output-io-mode=4 

then you should avoid the issue until we get the patch released.

[cantilever52]

If you flip the buffer allocation around the other way with

Code: Select all

v4l2src io-mode=5 ! video/x-raw, format=UYVY, framerate=30/1 ! v4l2h264enc output-io-mode=4 

then you should avoid the issue until we get the patch released.

This has helped, thanks!

Do you by any chance have a clue how delay can be reduced? It seems that

Code: Select all

v4l2h264enc

doesn't have "ultrafast" and "zerolatency" options like regular x264 encoder does...

[6by9]

How have you measured this delay?
The encode takes about 40ms for a 1080p frame, scaling down nearly linearly with frame size (the CABAC phase is linear with bitrate, but that's about 8ms of the 40).
There is an image conversion stage first which uses the ISP. Assuming no contention for the hardware block then it's 8-10ms.

Set the module parameter bcm2835_codec.debug to 5, and it'll log to the kernel log information on every frame in and out. Match the timestamp in and out to get a latency through the encoder.

Generally the delay is in the receiving end as it is expecting the stream to be received over the internet where latency varies, so having a receive buffer allows those variations to be smoothed out.

[cantilever52]

How have you measured this delay?
The encode takes about 40ms for a 1080p frame, scaling down nearly linearly with frame size (the CABAC phase is linear with bitrate, but that's about 8ms of the 40).
There is an image conversion stage first which uses the ISP. Assuming no contention for the hardware block then it's 8-10ms.

Set the module parameter bcm2835_codec.debug to 5, and it'll log to the kernel log information on every frame in and out. Match the timestamp in and out to get a latency through the encoder.

Generally the delay is in the receiving end as it is expecting the stream to be received over the internet where latency varies, so having a receive buffer allows those variations to be smoothed out.

Wow, that 40ms is nice to know, thanks!

I've been measuring locally with stopwatch (not very precise, I know) – comparing to raw streaming over local network, which's around 100ms, but takes ~ 300 Mbps for 640x480 image, using encoder is max 15 Mbps but slow...maybe it's receiver buffering or something indeed. I will try measuring delay with kernel debug

[6by9]

Encode was originally specced to be 1080p30 from the camera, therefore has to keep up with a new 1080p frame submitted every 33ms.
The camera/ISP can provide the image data in exactly the right format for the encoder, therefore it can bypass the image conversion stage, but otherwise it's the same.
There's a thread somewhere where I broke down exactly the time taken in each phase of image capture. Whilst mainly looking at the camera, it covered the encoder as well.
Encode is roughly speaking 3 phases - motion estimation, encode of residuals, and then entropy coding (CABAC or CAVLC). There are independent hardware blocks for each, therefore particularly entropy coding is done in parallel with the other bits.

[NKnuelle]

Hi there,

I found this thread and my problem seems to relate to this, too. My stream stops after some minutes and I can't get it working again without rebooting the Pi. I tried to change the values of io-modes. This didn't work, too. If I omit the io-values like this:

Code: Select all

GST_DEBUG=2 gst-launch-1.0 flvmux streamable=true name=mux ! rtmpsink location="rtmp://localhost:1935/live/stream" v4l2src ! "video/x-raw,framerate=50/1,format=UYVY" ! v4l2h264enc extra-controls="controls,video_bitrate=6000000;" ! video/x-h264,profile=high ! h264parse ! queue ! mux.

I get these errors, but my stream is working:

Code: Select all

0:00:00.565431342   717  0x1a911b0 WARN          v4l2bufferpool gstv4l2bufferpool.c:790:gst_v4l2_buffer_pool_start:<v4l2h264enc0:pool:src> Uncertain or not enough buffers, enabling copy threshold
0:00:00.578946339   717 0xb3902a00 WARN          v4l2bufferpool gstv4l2bufferpool.c:1189:gst_v4l2_buffer_pool_dqbuf:<v4l2h264enc0:pool:src> Driver should never set v4l2_buffer.field to ANY
0:00:00.595606640   717 0xb3902a00 WARN            v4l2videoenc gstv4l2videoenc.c:670:gst_v4l2_video_enc_loop:<v4l2h264enc0> Encoder is producing too many buffers

This still seems to be a buffer problem with the encoder.. Is it possible to limit the buffers for the encoders or speciify a buffer amount to test if a hardcoded buffer size is working?

[6by9]

Hi there,

I found this thread and my problem seems to relate to this, too. My stream stops after some minutes and I can't get it working again without rebooting the Pi. I tried to change the values of io-modes. This didn't work, too. If I omit the io-values like this:

Code: Select all

GST_DEBUG=2 gst-launch-1.0 flvmux streamable=true name=mux ! rtmpsink location="rtmp://localhost:1935/live/stream" v4l2src ! "video/x-raw,framerate=50/1,format=UYVY" ! v4l2h264enc extra-controls="controls,video_bitrate=6000000;" ! video/x-h264,profile=high ! h264parse ! queue ! mux.

I get these errors, but my stream is working:

Code: Select all

0:00:00.565431342   717  0x1a911b0 WARN          v4l2bufferpool gstv4l2bufferpool.c:790:gst_v4l2_buffer_pool_start:<v4l2h264enc0:pool:src> Uncertain or not enough buffers, enabling copy threshold
0:00:00.578946339   717 0xb3902a00 WARN          v4l2bufferpool gstv4l2bufferpool.c:1189:gst_v4l2_buffer_pool_dqbuf:<v4l2h264enc0:pool:src> Driver should never set v4l2_buffer.field to ANY
0:00:00.595606640   717 0xb3902a00 WARN            v4l2videoenc gstv4l2videoenc.c:670:gst_v4l2_video_enc_loop:<v4l2h264enc0> Encoder is producing too many buffers

This still seems to be a buffer problem with the encoder.. Is it possible to limit the buffers for the encoders or speciify a buffer amount to test if a hardcoded buffer size is working?

Totally unrelated to this thread. Please don't spam multiple threads that aren't directly related.
If you're having an issue then you're better off starting a new thread and allowing us to provide links to others, rather than taking them off on a total tangent.

[NKnuelle]

Oh sorry,

for me this seemed to be a very similar problem.

I'm going to start a fresh new thread describing my problem over there.

Thank you