video_encode:21:RIL: no space in FIFO for headers in vcdbg while using v4l2 h264 encode with Repeat Sequence Headers

[apu727]

Is this the right place for my bug report?
I believe it is associated with the v4l encode device.

Describe the bug
video_encode:21:RIL: no space in FIFO for headers is printed in sudo vcdbg log msg with vcgencmd set_logging level=0x400100C0 while encoding with REPEAT_SEQ_HEADER set to 1.

The error message does not appear initially, but consistently after ~20000 frames encoded. The timing of when it appears doesn't appear to be too spread out
The error message also does not appear if REPEAT_SEQ_HEADER=0

While using ffmpeg in code, frame write and packet read also became inconsistent after a while, which I traced back to all(16) output (data going to driver) buffers being in driver after a certain period which coincided with the error messages being produced. There were few outstanding capture (from driver) buffers, i.e the problem was not lack of capture buffers in driver.

Note: I am using ffmpeg only to generate and encode the video, I do not believe it is a problem with ffmpeg.

To reproduce
get ffmpeg-4.4 release
modify v4l2_m2m_enc.c to include and set REPEAT_SEQ_HEADER to 1. as seen in this patch which was found: here
build ffmpeg (any compile flags should be good I have attached the used ffmpeg -version)

run vcgencmd set_logging level=0x400100C0
run ffmpeg -re -loglevel info -f lavfi -i color=size=1408x1086:rate=30 -codec h264_v4l2m2m -pix_fmt yuv420p -b:v 8M -f null -
run sudo vcdbg log msg and eventually the errors start appearing

ffmpeg_version.txt

Expected behaviour
No error messages and no backlog of output(to driver) buffers

Actual behaviour
Error messages and all output buffers stored in driver

System
https://pastebin.com/37j7k6E2

I have removed dmesg and vcdbg from raspinfo as i will attach the relevant parts below. Let me know if you need this too (it is the same I believe)

Logs
I have created logs of dmesg and vcdbg log msg they are named good/bad for when REPEAT_SEQ_HEADER is enabled/disabled respectively.
For dmesg echo Y > /sys/module/v4l2_mem2mem/parameters/debug was set.
For 'bad' vcdbg i have created a sample of the logs at ~5000 frame intervals

dmesgbad.txt
dmesggood.txt
vcdbgloggood.txt
vcdbglogbad5000.txt
vcdbglogbad10000.txt
vcdbglogbad15000.txt
vcdbglogbad20000.txt
vcdbglogbad25000.txt

Additional context
I believe it is to do with job_ready only allowing a job to proceed if both src and dest buffers are available, in specific in
static int job_ready(void *priv) in bcm2835-v4l2-codec.c

When testing it in code I had a breakpoint set for if all output buffers fill. When this breakpoint was hit video_encode:21:RIL: no space in FIFO for headers was printed continuously while the program was paused with no intermediate messages(vcgencmd set_logging level=0x400100**4**0) I have logs of that too if needed.

The weird size and static colour are to replicate the images I was using when I noticed it. The width was also chosen to be 64 byte aligned. see #4419 which I believe affects bcm2835-v4l2-codec too (seperate issue)

[6by9]

I believe it is to do with job_ready only allowing a job to proceed if both src and dest buffers are available, in specific in
static int job_ready(void *priv) in bcm2835-v4l2-codec.c

job_ready returns 0 if there are BOTH src or dest have NO buffers, therefore returns 1 if either have buffers to process.

	if (!v4l2_m2m_num_src_bufs_ready(ctx->fh.m2m_ctx) &&
	    !v4l2_m2m_num_dst_bufs_ready(ctx->fh.m2m_ctx))
		return 0;

	return 1;

It's also why we call v4l2_m2m_set_[src|dest]_buffered to tell the m2m framework that we will accept buffers on the 2 queues independently.

The error message no space in FIFO for headers means what it says, although it should apply for any encoded output.
The FIFO is created with 200 entries, so at a default Intra-IDR period of 60 frames I would have expected that to be exhausted at around 12000 frames if it were a simple leak every time we added the extra headers. V4L2 does differ from the MMAL/IL clients in that it sets a flag to request that the header bytes are prepended to the I/IDR frame, rather than sent as separate buffers.

Rereading the V4L2 spec, I do see V4L2_CID_MPEG_VIDEO_HEADER_MODE, which FFmpeg sets to V4L2_MPEG_VIDEO_HEADER_MODE_SEPARATE to ask for the headers separate from the I/IDR frame. That one should be fairly simple to add as a control.

The other possibility I can think of is that the codec has produced a frame that exceeds the V4L2 buffer size. This is one of the ugly parts of the V4L2 codec spec that it mandates that a frame must fit into a single CAPTURE buffer, but you can never guarantee the max size of an encoded frame when doing a 1-pass encode.
The spec does state

If a CAPTURE buffer is too small then it is just returned with the V4L2_BUF_FLAG_ERROR flag set. More work is needed to detect that this error occurred because the buffer was too small, and to provide support to free existing buffers that were too small.

which we don't currently do, and will return a second CAPTURE buffer with the remaining part of the encoded frame. I don't know if that will upset FFmpeg if it is relying on a 1-in, 1-out behaviour. Fixing that one could be trickier.

Yes #4419 applies to the codec too - we use the ISP hardware block for the conversion on both the input of the encoder and the output of decoder. I'll sort the patch for that now.

[6by9]

Rereading the V4L2 spec, I do see V4L2_CID_MPEG_VIDEO_HEADER_MODE, which FFmpeg sets to V4L2_MPEG_VIDEO_HEADER_MODE_SEPARATE to ask for the headers separate from the I/IDR frame. That one should be fairly simple to add as a control.

Been there already! 1dee2e6

[apu727]

The error message no space in FIFO for headers means what it says, although it should apply for any encoded output.
The FIFO is created with 200 entries, so at a default Intra-IDR period of 60 frames I would have expected that to be exhausted at around 12000 frames if it were a simple leak every time we added the extra headers. V4L2 does differ from the MMAL/IL clients in that it sets a flag to request that the header bytes are prepended to the I/IDR frame, rather than sent as separate buffers.

I have looked at the logs i posted again and the error starts somewhere between 10000 and 15000 frames. so that fits with the 12000 if it is a leak.

The frames are small as seen from the vcdbg logs, (55 bytes for type 1, 450 bytes for type 5, 50 bytes for type 7/8 together)

866912.317: video_encode:15:RIL: releasing output buffer for 497600000, nFilledLen 55, nOffset 0, nFlags 0410
866912.347: calling processed_buffer callback for (3f112168)
866912.395: video_encode:15:RIL:ve_process_thread:job 3f0b6f44(1,0)
866912.441: video_encode:15:RIL:ve_process_thread:enc_getbytes status 0, flags 0x200 bytes 9 (0x9) data 0xb80e6710
866912.455: writing job 3f0b6f44 to fifo
866912.490: video_encode:15:RIL: wrote 9 bytes for ts(504066667) md(0) flags 0x0 into fifo, pData b80e6710, frame complete No
866912.516: video_encode:15:RIL:ve_process_thread:job 3f0b6f44(1,0)
866912.559: video_encode:15:RIL:ve_process_thread:enc_getbytes status 0, flags 0x221 bytes 46 (0x2e) data 0xb80e6719
866912.579: writing job 3f0b6f44 to fifo
866912.613: video_encode:15:RIL: wrote 46 bytes for ts(504066667) md(0) flags 0x410 into fifo, pData b80e6719, frame complete Yes
866912.636: updated free Q after freeing job 3f0b6f44 rc:15175 wc:15243
866912.657: video_encode:15:RIL: no space in FIFO for headers

Above: an example of the size of one of the frames

Interestingly I have discovered the error does not happen if the frames are larger. e.g using testsrc2 instead of color for the input filter

I think FFMPEG has received all the frames it expected: 16877 frames encoded; 17159 packets muxed where the packet number is correctly 16877 + 16877 % 60 + 1, this is for the case where the error is reported.

I don't think I have 1dee2e6 yet as Header mode is not listed in v4l-ctl -d 11 -L. How can i get the version of the module I have installed?