Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ffmpeg freezes when enconding with h264_omx at 1080p or 720p #1087

Closed
andreluisos opened this issue Dec 27, 2018 · 38 comments
Closed

ffmpeg freezes when enconding with h264_omx at 1080p or 720p #1087

andreluisos opened this issue Dec 27, 2018 · 38 comments

Comments

@andreluisos
Copy link

andreluisos commented Dec 27, 2018

I don't know what happens, it simply freezes after 1-6mins of real time encoding, deppending on the resolution.

ffmpeg -f v4l2 -re -video_size 1024x576 -r 2 -vsync 1 -i /dev/video0 -f alsa -async 1 -i hw:1,0 -c:v h264_omx -b:v 1000k -c:a aac -b:a 170k -f segment -strftime 1 -segment_time 300 -reset_timestamps 1 -segment_format mkv rec_%Y-%m-%d_%H-%M-%S.mkv

It doesn't freeze if I use 1024x576 or lower resolution, apparently. Also, it only happens with h264_omx.

I'm using an USB camera (Logitech C922).

@JamesH65
Copy link
Contributor

JamesH65 commented Jan 9, 2019

Have you tried removing option until the problem goes away to see if you can narrow down exactly where the problem is?

We don't have any cameras like that in the office, and all this code is someone elses, so unlikely we would be able to help much here. Might be worth posting on the forums as it will get more viewers who might be able to help.

@evanglasgow
Copy link

I've noticed what I believe to be a similar issue with ffmpeg h264_omx lockup. I haven't had a chance to debug it further, but a workaround I've used is revert to an older firmware version 4.14.52 with the command sudo rpi-update 5315c7a2f806c123e9e4ee26980f0019c43b9f69. That advice is from this issue (#1051).

@andreluisos
Copy link
Author

I've noticed what I believe to be a similar issue with ffmpeg h264_omx lockup. I haven't had a chance to debug it further, but a workaround I've used is revert to an older firmware version 4.14.52 with the command sudo rpi-update 5315c7a2f806c123e9e4ee26980f0019c43b9f69. That advice is from this issue (#1051).

I'd debug it if you or someone else guide me through. It could also be related to this issue: #851

@evanglasgow
Copy link

evanglasgow commented Jan 13, 2019

If this is helpful, here is a 30s sample MPEG2-TS file that almost always triggers the hang during encoding (https://www.dropbox.com/s/w7n9nn4eeeyq7qc/sample.ts?dl=1). The ffmpeg command I use is ffmpeg -c:v mpeg2_mmal -i sample.ts -c:v h264_omx -b:v 15M sample.mkv.

Trying the steps listed here might be useful in analyzing the frozen state. Might also be able to use gdb to see where ffmpeg is stuck.

EDIT: I gave it a go. sudo vcdbg log assert didn't show anything beyond the first two expected log messages. Here's the backtrace for the hung ffmpeg thread (link to omx.c)

#0  0x2b56494c in __pthread_cond_wait (cond=cond@entry=0x3500028, mutex=mutex@entry=0x3500010) at pthread_cond_wait.c:186
#1  0x005ef418 in get_buffer (wait=1, array=0x37f2be0, array_size=0x3500000, cond=0x3500028, mutex=0x3500010)
    at libavcodec/omx.c:250
#2  omx_encode_frame (avctx=avctx@entry=0x34ffba0, pkt=pkt@entry=0x37b8ae0, frame=0x38, frame@entry=0x364a410,
    got_packet=0x7, got_packet@entry=0x7eddd814) at libavcodec/omx.c:747
#3  0x004332fc in avcodec_encode_video2 (got_packet_ptr=0x7eddd814, frame=0x364a410, avpkt=0x37b8ae0, avctx=0x34ffba0)
    at libavcodec/encode.c:296
#4  do_encode (avctx=0x34ffba0, frame=0x364a410, got_packet=0x7eddd814) at libavcodec/encode.c:365
#5  0x00433a10 in avcodec_send_frame (avctx=avctx@entry=0x34ffba0, frame=frame@entry=0x364a410) at libavcodec/encode.c:414
#6  0x000b39b4 in do_video_out (of=0x34fe8b0, of@entry=0x0, ost=ost@entry=0x34ff9e0, next_picture=0x34fe6d0,
    next_picture@entry=0x364a410, sync_ipts=640.00000762939453) at fftools/ffmpeg.c:1292
#7  0x000b4a3c in reap_filters (flush=15858952, flush@entry=0) at fftools/ffmpeg.c:1510
#8  0x000b8f68 in transcode_step () at fftools/ffmpeg.c:4647
#9  transcode () at fftools/ffmpeg.c:4691
#10 0x0009713c in main (argc=<optimized out>, argv=0x7eddea94) at fftools/ffmpeg.c:4898

This may well be an ffmpeg issue, but reverting to an older rpi firmware version seems to get around it.

@popcornmix
Copy link
Contributor

This may well be an ffmpeg issue, but reverting to an older rpi firmware version seems to get around it.

Posting the date of working and non-working firmware may be useful.
Identifying the exact firmware update (using rpi-update) would be even more useful.

@evanglasgow
Copy link

Identifying the exact firmware update (using rpi-update) would be even more useful.

The rpi-update hash that first exhibits the ffmpeg h264_omx freeze/hang is ec9d84e1d2ba701fd28897809269d8116b31dbf5.

@6by9
Copy link

6by9 commented Jan 16, 2019

I'm suspecting that ec9d84e just tweaked the timing of video_encode slightly. It switched to using the ISP (hardware) to format convert the image at the front of video_encode (previously it was on the general purpose VPU).

Running vcgencmd set_logging level=0x10cc0 and then using your clip and command, shows

047137.187: video_encode:0:RIL: got FIFO header for (3069733) with 100810 bytes
047137.219: video_encode:0:RIL: copying 65536 bytes for (3069733) into output buffer (3e8ee740), allocLen 65536, FilledLen 0, available_data 100810
047137.316: video_encode:0:RIL: releasing output buffer for 3069733, nFilledLen 65536, nOffset 0, nFlags 0400
047137.329: calling processed_buffer callback for (3e8ee740)
047137.354: video_encode:0:cb:emit_output_buffer(3e8ee740,65536b,400f) RIL:1

in the logging. So the codec has produced a 98kB frame whilst the output buffer is only 64kB in size. It therefore fragments it over two buffers with OMX_BUFFERFLAG_ENDOFFRAME only set on the second frame. The fact that we don't see the second buffer being filled would imply that FFmpeg hasn't returned a buffer to fill.

As a test I tweaked the codec to say it wanted 256kB buffers, and I then see no stall.
Switch to 32kB buffers and I see

063313.788: got output buffer (3e8ee740)
063313.807: video_encode:0:RIL: got FIFO header for (900900) with 49207 bytes
063313.837: video_encode:0:RIL: copying 32768 bytes for (900900) into output buffer (3e8ee740), allocLen 32768, FilledLen 0, available_data 49207
063313.982: video_encode:0:RIL: releasing output buffer for 900900, nFilledLen 32768, nOffset 0, nFlags 0400

on frame 54 or 55 (that's probably just a UI glitch in ffmpeg - the same stream in should always give exactly the same stream out for the same parameters. It's always a 49207 byte frame being copied).

Checking on 64kB buffers again, it's not always exactly the same point. Frame 118 is the 100810byte frame I saw first, but I've now seen frame 134/135 where we have returned a buffer of 56408. Either way, video_encode is waiting on being given a buffer to copy output data into, and the output handling didn't change with that commit.

I suspect there is a race condition where buffers are getting lost, and once they are all gone then you have a stall. I couldn't say at this point whether it was in FFmpeg or the firmware/ILCS.

@6by9
Copy link

6by9 commented Jan 16, 2019

VPU debugger confirms that video_encode is just waiting for a buffer. There's only one buffer allocated for each of the input and output ports.

Minor observation. That commit does relax the INPUT port requirements of video_encode so that nSliceHeight does NOT have to be a multiple of 16 if it can process the frame with the ISP.
When running your command, we have video_decode producing 1920x1088 YUV420PackedPlanar buffers, whilst video_encode is being presented with 1920x1080. Something in FFmpeg is therefore having to copy the chroma planes around to remove those 8 lines of padding on the Y, and 4 lines of padding on the U.

You can set nSliceHeight to be the same as video_decode, which would avoid the requirement for the copy.

@andreluisos
Copy link
Author

You can set nSliceHeight to be the same as video_decode, which would avoid the requirement for the copy.

Sorry for my stupidity, but how can I do that? Google wasn't very helpful.

@6by9
Copy link

6by9 commented Jan 16, 2019

Sorry for my stupidity, but how can I do that? Google wasn't very helpful.

"You" as in the FFmpeg application.
omx.c approx line 469

    // If specific codecs need to manually override the stride/plane_size,
    // that can be done here.
    in_port_params.format.video.nStride      = s->stride;
    in_port_params.format.video.nSliceHeight = s->plane_size;
    in_port_params.format.video.nFrameWidth  = avctx->width;
    in_port_params.format.video.nFrameHeight = avctx->height;

Change nSliveHeight to

in_port_params.format.video.nSliceHeight = (s->plane_size+15)&~15;

It was more an observation than saying that was the problem.
Sadly there appears to be nearly zero logging in omx.c, so it's time to add some and see what is going on.

@andreluisos
Copy link
Author

andreluisos commented Jan 16, 2019

Oh. Before building, I suppose? I'll try that.

@6by9
Copy link

6by9 commented Jan 16, 2019

OK, I totally misread where FFmpeg was stuck. It's waiting for an INPUT buffer to be available, not for an output buffer.

The codec is blocked waiting for space to CABAC encode a frame, as the output FIFO would appear to be full.
Having added logging of nTimestamp, the output side is getting further and further behind. Logging at the point it dies:

[h264_omx @ 0x15669d0] Emptying I/P buffer 0x16b6430, nFilledLen 3133440, nTimestamp 4604600
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] O/P buffer returned, nFilledLen 50474, nFlags 0410, nTimestamp 3503500
[h264_omx @ 0x15669d0] Concatenating buffer for newsize 50538
[h264_omx @ 0x15669d0] Finished with buffer 0x17fa080 - FillThisBuffer
[h264_omx @ 0x15669d0] Got complete frame - encode done
[h264_omx @ 0x15669d0] Called get_buffer for i/p00:00:03.50 bitrate=14205.4kbits/s speed=0.751x    
[h264_omx @ 0x15669d0] I/P zero copy
[h264_omx @ 0x15669d0] I/P needing copy
[h264_omx @ 0x15669d0] Emptying I/P buffer 0x16b6430, nFilledLen 3133440, nTimestamp 4637967
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] O/P buffer returned, nFilledLen 41342, nFlags 0410, nTimestamp 3536867
[h264_omx @ 0x15669d0] Concatenating buffer for newsize 41406
[h264_omx @ 0x15669d0] Finished with buffer 0x17fa080 - FillThisBuffer
[h264_omx @ 0x15669d0] Got complete frame - encode done

Timestamps are usecs, and the frames are at 33ms increments, so the input is 1.1seconds ahead. Our FIFO is 2MB in size. 15Mbit/s = 1.875MB/s, so that would imply that we are almost bang on with rate control if we're stalling due to the FIFO being full with a 1.1sec difference (should be 1.066s).

During startup we do get get_buffer returning NULL several times, so that does provide a mechanism for the input to get a bit ahead. Get too far ahead and I don't see a mechanism for FFmpeg to ever recover that latency - as soon as it sets got_packet due to a OMX_BUFFERFLAG_ENDOFFRAME in nFlags, it quits the encode of that frame.

@6by9
Copy link

6by9 commented Jan 16, 2019

Something appears messed up in FFmpeg and it ISN'T handling OMX_BUFFERFLAG_ENDOFFRAME correctly.

[h264_omx @ 0x15669d0] Called get_buffer for i/p
[h264_omx @ 0x15669d0] Checking I/P zero copy
[h264_omx @ 0x15669d0] frame->linesize = {1920,960,960}, src_linesize = {1920,960,960}, data[] = {0x6e2e1020,0x6e75e020,0x6e6de020}, src[1-2] = {0x6e2e1020,0x6e4df020,0x6e55e820}
[h264_omx @ 0x15669d0] Can't zero copy
[h264_omx @ 0x15669d0] I/P needing copy
[h264_omx @ 0x15669d0] Emptying I/P buffer 0x16b46c0, nFilledLen 3133440, nTimestamp 2235567
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] O/P buffer returned, nFilledLen 65536, nFlags 0420, nTimestamp 1601600
[h264_omx @ 0x15669d0] Concatenating buffer for newsize 65600
[h264_omx @ 0x15669d0] Finished with buffer 0x16b4730 - FillThisBuffer
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] failed to get_buffer
[h264_omx @ 0x15669d0] Got complete frame - encode done

[h264_omx @ 0x15669d0] Called get_buffer for i/p
[h264_omx @ 0x15669d0] Checking I/P zero copy
[h264_omx @ 0x15669d0] frame->linesize = {1920,960,960}, src_linesize = {1920,960,960}, data[] = {0x71817020,0x17be7c0,0x15bf3b0}, src[1-2] = {0x71817020,0x71a15020,0x71a94820}
[h264_omx @ 0x15669d0] Can't zero copy
[h264_omx @ 0x15669d0] I/P needing copy
[h264_omx @ 0x15669d0] Emptying I/P buffer 0x16b46c0, nFilledLen 3133440, nTimestamp 2268933
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] O/P buffer returned, nFilledLen 65536, nFlags 0520, nTimestamp 1601600
[h264_omx @ 0x15669d0] Concatenating buffer for newsize 131136
[h264_omx @ 0x15669d0] Finished with buffer 0x16b4730 - FillThisBuffer
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] failed to get_buffer
[h264_omx @ 0x15669d0] Got complete frame - encode done

[h264_omx @ 0x15669d0] Called get_buffer for i/p
[h264_omx @ 0x15669d0] Checking I/P zero copy
[h264_omx @ 0x15669d0] frame->linesize = {1920,960,960}, src_linesize = {1920,960,960}, data[] = {0x6e2e1020,0x6e75e020,0x6e6de020}, src[1-2] = {0x6e2e1020,0x6e4df020,0x6e55e820}
[h264_omx @ 0x15669d0] Can't zero copy
[h264_omx @ 0x15669d0] I/P needing copy
[h264_omx @ 0x15669d0] Emptying I/P buffer 0x16b46c0, nFilledLen 3133440, nTimestamp 2302300
[h264_omx @ 0x15669d0] Calling get_buffer for O/P
[h264_omx @ 0x15669d0] O/P buffer returned, nFilledLen 12750, nFlags 0530, nTimestamp 1601600
[h264_omx @ 0x15669d0] Concatenating buffer for newsize 143886
[h264_omx @ 0x15669d0] Finished with buffer 0x16b4730 - FillThisBuffer
[h264_omx @ 0x15669d0] Got complete frame - encode done

Only that 3rd buffer is complete, but they've all been considered as full frames.
get_buffers returns NULL as there isn't a buffer waiting (we've only just returned it). It isn't waiting as frame is not NULL.

Zero copy appears to be a red herring (although I haven't checked if it used that path previously). Something is moving the chroma planes from the contiguous layout that the decoder will have generated, and therefore it isn't correctly laid out to be accepted by the encoder. A shame, but there you go.

@6by9
Copy link

6by9 commented Jan 16, 2019

Comparing the VPU utilisation, with the old code it is plainly converting from the internal format in video_decode, and then converting back to the internal format as part of video_encode, taking approx 40ms from the steps for successive frames. Each conversion is around 10ms.
Somehow in that case get_buffer is returning an output buffer on each call.

With the new code, the second conversion isn't on the VPU, and we're at 33ms between conversions. (Performance gain!). It's obviously tickled the timing though.

Several solutions:

  • FFmpeg to request more and/or larger buffers from video_encode. It uses the default sizes/number the firmware tells it, which is not optimised for performance.
  • We could tweak the defaults in the firmware, but that compromises everyone so I'm very reluctant to do that.
  • FFmpeg to wait for additional buffers should it have received one output buffer without OMX_BUFFERFLAG_ENDOFFRAME set. I have a quick mod to do that, and it works. We could apply that to Raspbian, but upstream are going to be reluctant to take it if they have the same experience as GStreamer. Having said that there is already an FFmpeg build flag for the Pi so it could be hidden behind that.
diff --git a/libavcodec/omx.c b/libavcodec/omx.c
index 466e0be..018606e 100644
--- a/libavcodec/omx.c
+++ b/libavcodec/omx.c
@@ -739,6 +739,7 @@ static int omx_encode_frame(AVCodecContext *avctx, AVPacket *pkt,
     int ret = 0;
     OMX_BUFFERHEADERTYPE* buffer;
     OMX_ERRORTYPE err;
+    int had_partial = 0;
 
     if (frame) {
         uint8_t *dst[4];
@@ -830,7 +844,7 @@ static int omx_encode_frame(AVCodecContext *avctx, AVPacket *pkt,
         // packet, or get EOS.
         buffer = get_buffer(&s->output_mutex, &s->output_cond,
                             &s->num_done_out_buffers, s->done_out_buffers,
-                            !frame);
+                            !frame || had_partial);
         if (!buffer)
             break;
 @@ -865,6 +880,7 @@ static int omx_encode_frame(AVCodecContext *avctx, AVPacket *pkt,
                     s->output_buf = NULL;
                     s->output_buf_size = 0;
                 }
+                had_partial = 1;
             } else {
                 // End of frame, and the caller provided a preallocated frame
                 if ((ret = ff_alloc_packet2(avctx, pkt, s->output_buf_size + buffer->nFilledLen, 0)) < 0) {

@6by9
Copy link

6by9 commented Jan 16, 2019

@andreluisos Sorry, I've been debugging @evanglasgow 's issue as he provided an easily reproducable test case and found the firmware change where his test case failed. Looking at your original post I suspect that your issue is something different.

You're running at a couple of frames a second, so the input side of the encoder will be far slower than the output. You're also at a much lower bitrate so very unlikely to fill the codec's output FIFO.

It would be worth doing an sudo rpi-update 5315c7a to roll your firmware back to before the change to using the ISP, but I doubt it will make a difference.

Running the video side of your command with my USB webcam (Logitech C270) and everything looks fine. You could try starting your command ffmpeg -v trace to the enable logging, as the mkv mux does print

[matroska @ 0x1d1c1b0] Writing block at offset 75434, size 14119, pts 44500, dts 44500, duration 500, keyframe 0
[matroska @ 0x1d1c1b0] Writing block at offset 89560, size 9804, pts 45000, dts 45000, duration 500, keyframe 0
[matroska @ 0x1d1c1b0] Writing block at offset 99371, size 19014, pts 45500, dts 45500, duration 500, keyframe 0

Should any of those size parameters hit 64kB then you may be seeing the same issue, but otherwise I doubt it.

@andreluisos
Copy link
Author

andreluisos commented Jan 16, 2019

Have you tried removing option until the problem goes away to see if you can narrow down exactly where the problem is?

We don't have any cameras like that in the office, and all this code is someone elses, so unlikely we would be able to help much here. Might be worth posting on the forums as it will get more viewers who might be able to help.

@JamesH65 Yes, Mr. Hughes, I have.

I'm using ffmpeg -f v4l2 -video_size 1920x1080 -r 2 -re -i /dev/video0 -f alsa -i hw:1,0 -c:v h264_omx -c:a libvorbis -b:v 1400k -b:a 380k output.mkv. It still freezes. The only easy solution I tried so far was the one given by evengasglow (downgrading the firmware), which worked.

I've noticed what I believe to be a similar issue with ffmpeg h264_omx lockup. I haven't had a chance to debug it further, but a workaround I've used is revert to an older firmware version 4.14.52 with the command sudo rpi-update 5315c7a2f806c123e9e4ee26980f0019c43b9f69. That advice is from this issue (#1051).

@evanglasgow
Copy link

@6by9 Thanks for the analysis and deep-dive into ffmpeg! Darn race conditions... I sort of suspected that's where this would end up and it (rightfully) seemed a bit daunting. I really appreciate the expertise. I'll try your quick patch and have it churn through some longer clips just to verify all is well there. I'm on ffmpeg git master and it doesn't look like the diff quite matches what's there, but I think I got the key bit - just that it won't be a perfect test.

@andreluisos Sorry for hijacking the issue!

@jasaw
Copy link

jasaw commented Jan 17, 2019

I'm experiencing ffmpeg freezing problem as well, which did not happen on older version of rpi firmware. It encodes for about a minute, and freezes.

I'm running motion software version 4.1.1, ffmpeg 3.4.4, and motion encodes 1600x1200 resolution video via ffmpeg API. I applied the ffmpeg OMX_BUFFERFLAG_ENDOFFRAME patch that @6by9 suggested in the above post, and seems to have fixed the problem. I'll do more testing to confirm that it has really been fixed.

@6by9
Copy link

6by9 commented Jan 17, 2019

@andreluisos Sorry, if there isn't a reproducable test case, then there is very little we can do to help.
I did ask if you would try enabling tracing with ffmpeg -v trace at the start of your command and reporting the buffer sizes - did you try that and confirm the buffer sizes you were seeing?
I've run your command (tweaked to 1280x960 @ 5fps as that's the max my webcam supports) and it's run all night (265485 frames).

@evanglasgow That sounds positive. The diff was copied from git diff rather than made from a patch, and I had some extra logging lines in there, so that probably explains why it doesn't quite line up. Sorry about that.

@jasaw It sounds highly plausible that you're seeing the same problem.

TBH I'm amazed that this broken behaviour in FFmpeg hasn't tripped things up before.
There is a near identical issue in mainline GStreamer, and both are application issues rather than anything wrong in the IL implementation.

I'll try to make a clean patch that can be applied to the Raspbian build of ffmpeg fairly quickly, and will then look at getting it upstreamed into mainline FFmpeg.

@andreluisos
Copy link
Author

andreluisos commented Jan 17, 2019

@andreluisos Sorry, if there isn't a reproducable test case, then there is very little we can do to help.
I did ask if you would try enabling tracing with ffmpeg -v trace at the start of your command and reporting the buffer sizes - did you try that and confirm the buffer sizes you were seeing?
I've run your command (tweaked to 1280x960 @ 5fps as that's the max my webcam supports) and it's run all night (265485 frames).

Oh! I didn't see that. Been a tough week and I didn't have much time. I don't know if it's still important, but here's the result with the command ffmpeg -f v4l2 -video_size 1920x1080 -r 2 -re -i /dev/video0 -f alsa -i hw:1,0 -c:v h264_omx -c:a libvorbis -b:v 1400k -b:a 380k test.mkv:

image

It hangs in there (little bit more than a minute of recording, I think) with the latest rpi firmware.

Also, the comments became too technical for me to understand much.

@evanglasgow Thank you for joining in.

@andreluisos
Copy link
Author

Accidently closed the issue. ehehheheh

Don't hate, me guys. :(

@6by9
Copy link

6by9 commented Jan 17, 2019

From your screenshot I see

Writing block at offset 2856, size 54434, pts 47004, dts 47004, duration=500, keyframe=0
...
Writing block at offset 78729, size 54914, pts 47504, dts 47504, duration=500, keyframe=0

in that log.
You still have audio in there for all those duration=32, keyframe=1 packets - James had asked you to simplify the command line, and dropping audio would count as a simplification :)

If you're asking for 1400kbit/s and 2fps, then each frame should be ~87kB. I would therefore expect almost all buffers to be split and therefore trigger the FFmpeg bug, moreso for I-frames as they are generally allocated more bits in the stream.

@andreluisos
Copy link
Author

From your screenshot I see

Writing block at offset 2856, size 54434, pts 47004, dts 47004, duration=500, keyframe=0
...
Writing block at offset 78729, size 54914, pts 47504, dts 47504, duration=500, keyframe=0

in that log.
You still have audio in there for all those duration=32, keyframe=1 packets - James had asked you to simplify the command line, and dropping audio would count as a simplification :)

If you're asking for 1400kbit/s and 2fps, then each frame should be ~87kB. I would therefore expect almost all buffers to be split and therefore trigger the FFmpeg bug, moreso for I-frames as they are generally allocated more bits in the stream.

image
There we go. The command used was ffmpeg -v trace -f video4linux2 -re -r 5 -input_format yuv420p -i /dev/video0 -c:v h264_omx -b:v 1000k test.mkv

@6by9
Copy link

6by9 commented Jan 17, 2019

There we go. The command used was ffmpeg -v trace -f video4linux2 -re -r 5 -input_format yuv420p -i /dev/video0 -c:v h264_omx -b:v 1000k test.mkv

Did that stall?

Your new command hasn't specified the resolution (V4L2 will generally remember the last request mode), but has increased the frame rate to 5fps and dropped the bitrate. The upshot is that the buffer sizes will have all come down to an average of 25kB per frame, and I'd expect the system to keep going significantly longer.
Your log snippet certainly shows the buffer sizes have come down, but neither of the two frames were I-frames, so they will be smaller.

@andreluisos
Copy link
Author

andreluisos commented Jan 17, 2019

There we go. The command used was ffmpeg -v trace -f video4linux2 -re -r 5 -input_format yuv420p -i /dev/video0 -c:v h264_omx -b:v 1000k test.mkv

Did that stall?

Your new command hasn't specified the resolution (V4L2 will generally remember the last request mode), but has increased the frame rate to 5fps and dropped the bitrate. The upshot is that the buffer sizes will have all come down to an average of 25kB per frame, and I'd expect the system to keep going significantly longer.
Your log snippet certainly shows the buffer sizes have come down, but neither of the two frames were I-frames, so they will be smaller.

It did stall.

I did set the resolution through v4l2. I was testing the pixelformats (YUVY and MJPEG available). The manufacturer says the webcam sends the video already encoded with h264. Using copy (as output codec), however, gave me huge video sizes (probably because of the high bitrate it's set by default, which I don't think I can change). I know it's not about the topic, which comes down to h264_omx, but just wanted to let you guys know that I don't think this webcam encodes anything on its own.

@6by9
Copy link

6by9 commented Jan 17, 2019

Issue opened on FFmpeg's issue tracker https://trac.ffmpeg.org/ticket/7687

Seeing as jasaw's issue on there hasn't been touched for 17 months I'm not expecting any real input, so I may just throw a patch at ffmpeg-devel.

@6by9
Copy link

6by9 commented Jan 17, 2019

I did set the resolution through v4l2. I was testing the pixelformats (YUVY and MJPEG available). The manufacturer says the webcam sends the video already encoded with h264. Using copy (as output codec), however, gave me huge video sizes (probably because of the high bitrate it's set by default, which I don't think I can change).

v4l2-ctl --set-ctrl=video_bitrate=500000 to request 500kbit/s from the webcam. v4l2-ctl --list-ctrls to list all the controls the device has.

I know it's not about the topic, which comes down to h264_omx, but just wanted to let you guys know that I don't think this webcam encodes anything on its own.

v4l2-ctl -V will confirm the resolution and format that was last requested from the webcam.

AFAICT you need to either build ffmpeg for yourself, or be patient for a patched version to be released.
If you don't want to build it yourself, then I'm creating a patch for Raspbian based on @jasaw and @evanglasgow 's reports that it appears to solve their issues. Once that propagates out you will get the fix. There's no easy way to speed that up.

@andreluisos
Copy link
Author

andreluisos commented Jan 17, 2019

v4l2-ctl -V will confirm the resolution and format that was last requested from the webcam.

AFAICT you need to either build ffmpeg for yourself, or be patient for a patched version to be released.
If you don't want to build it yourself, then I'm creating a patch for Raspbian based on @jasaw and @evanglasgow 's reports that it appears to solve their issues. Once that propagates out you will get the fix. There's no easy way to speed that up.

That's no problem! Thank you so much for the help. Meanwhile, I'll be using a previous RPI firmware. About v4l2-ctl --set-ctrl=video_bitrate=500000, it returns unknown control 'video_bitrate'.

@6by9
Copy link

6by9 commented Jan 18, 2019

FFmpeg patch sorted and a patched build should hopefully be in the Raspbian repos within the next hour.

Version should be 7:3.2.10-1~deb9u1+rpt3 (vanilla Debian version is 7:3.2.10-1~deb9u1)

@andreluisos
Copy link
Author

andreluisos commented Jan 18, 2019

I think it's up. Setting up ffmpeg (7:3.2.10-1~deb9u1+rpt3) ...

I'll be testing.

@andreluisos
Copy link
Author

andreluisos commented Jan 18, 2019

So far, so good.

Latest firmware;
Latest ffmpeg for raspbian.

ffmpeg -f alsa -thread_queue_size 1024 -i hw:1,0 -f v4l2 -re -video_size 1280x720 -thread_queue_size 1024 -i /dev/video0 -c:v h264_omx -c:a libvorbis -b:v 3000k -b:a 350k
image

ffmpeg -f alsa -thread_queue_size 2048 -i hw:1,0 -f v4l2 -re -video_size 1920x1080 -thread_queue_size 2048 -i /dev/video0 -c:v h264_omx -c:a libvorbis -4000k -b:a 380k test.mkv
image

Thank you all for dianosing and fixing the issue. I'll let you know if it stalls again.

As it's not a RPI firmware issue, should I close this?

@Exscotticus
Copy link

Whatever you did here, it fixed a freezing bug I've been experiencing for some time. Thank you!

@6by9
Copy link

6by9 commented Jan 22, 2019

As it's not a RPI firmware issue, should I close this?

Either way, if this is now resolved then it should be closed.

@andreluisos
Copy link
Author

Issue fixed! Thank you all involved in detecting and fixing this.

@devalexqt
Copy link

Bug still present!
ffmpeg version 3.2.14-1~deb9u1+rpt1 and latest rpi firmware
And ffmpeg freeze after couple of seconds:
I try to push raw yuv data from raspivid to ffmpeg for encoding (and filtering that not included in example run command)

raspivid -w 1920 -h 1080 -b 6000000 -t 0 -n -r -|ffmpeg -f rawvideo -pix_fmt yuv420p -s 1920x1088 -i - -c:v h264_omx -pix_fmt yuv420p -b:v 6M -loglevel trace -y out.mp4
raspivid -w 1920 -h 1080 -b 6000000 -t 0 -n -r -|ffmpeg -f rawvideo -pix_fmt yuv420p -s 1920x1088 -i - -c:v h264_omx -pix_fmt yuv420p -b:v 6M -loglevel trace -y out.mp4
ffmpeg version 3.2.14-1~deb9u1+rpt1 Copyright (c) 2000-2019 the FFmpeg developers
  built with gcc 6.3.0 (Raspbian 6.3.0-18+rpi1+deb9u1) 20170516
  configuration: --prefix=/usr --extra-version='1~deb9u1+rpt1' --toolchain=hardened --libdir=/usr/lib/arm-linux-gnueabihf --incdir=/usr/include/arm-linux-gnueabihf --enable-gpl --disable-stripping --enable-avresample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libebur128 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libmp3lame --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-omx --enable-omx-rpi --enable-mmal --enable-openal --enable-opengl --enable-sdl2 --enable-libdc1394 --enable-libiec61883 --arch=armhf --enable-chromaprint --enable-frei0r --enable-libopencv --enable-libx264 --enable-shared
  libavutil      55. 34.101 / 55. 34.101
  libavcodec     57. 64.101 / 57. 64.101
  libavformat    57. 56.101 / 57. 56.101
  libavdevice    57.  1.100 / 57.  1.100
  libavfilter     6. 65.100 /  6. 65.100
  libavresample   3.  1.  0 /  3.  1.  0
  libswscale      4.  2.100 /  4.  2.100
  libswresample   2.  3.100 /  2.  3.100
  libpostproc    54.  1.100 / 54.  1.100
Splitting the commandline.
Reading option '-f' ... matched as option 'f' (force format) with argument 'rawvideo'.
Reading option '-pix_fmt' ... matched as option 'pix_fmt' (set pixel format) with argument 'yuv420p'.
Reading option '-s' ... matched as option 's' (set frame size (WxH or abbreviation)) with argument '1920x1088'.
Reading option '-i' ... matched as input url with argument '-'.
Reading option '-c:v' ... matched as option 'c' (codec name) with argument 'h264_omx'.
Reading option '-pix_fmt' ... matched as option 'pix_fmt' (set pixel format) with argument 'yuv420p'.
Reading option '-b:v' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '6M'.
Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument 'trace'.
Reading option '-y' ... matched as option 'y' (overwrite output files) with argument '1'.
Reading option 'out.mp4' ... matched as output url.
Finished splitting the commandline.
Parsing a group of options: global .
Applying option loglevel (set logging level) with argument trace.
Applying option y (overwrite output files) with argument 1.
Successfully parsed a group of options.
Parsing a group of options: input url -.
Applying option f (force format) with argument rawvideo.
Applying option pix_fmt (set pixel format) with argument yuv420p.
Applying option s (set frame size (WxH or abbreviation)) with argument 1920x1088.
Successfully parsed a group of options.
Opening an input file: -.
[rawvideo @ 0xe9d630] Opening 'pipe:' for reading
[pipe @ 0xe9dd80] Setting default whitelist 'crypto'
[rawvideo @ 0xe9d630] Before avformat_find_stream_info() pos: 0 bytes read:32768 seeks:0 nb_streams:1
[rawvideo @ 0xe9d630] All info found
[rawvideo @ 0xe9d630] stream 0: start_time: 0.000 duration: -368934881474191040.000
[rawvideo @ 0xe9d630] format: start_time: 0.000 duration: -9223372036854.775 bitrate=626688 kb/s
[rawvideo @ 0xe9d630] After avformat_find_stream_info() pos: 3133440 bytes read:3133440 seeks:0 frames:1
Input #0, rawvideo, from 'pipe:':
  Duration: N/A, start: 0.000000, bitrate: 626688 kb/s
    Stream #0:0, 1, 1/25: Video: rawvideo, 1 reference frame (I420 / 0x30323449), yuv420p, 1920x1088, 0/1, 626688 kb/s, 25 tbr, 25 tbn, 25 tbc
Successfully opened the file.
Parsing a group of options: output url out.mp4.
Applying option c:v (codec name) with argument h264_omx.
Applying option pix_fmt (set pixel format) with argument yuv420p.
Applying option b:v (video bitrate (please use -b:v)) with argument 6M.
Successfully parsed a group of options.
Opening an output file: out.mp4.
[file @ 0xea9220] Setting default whitelist 'file,crypto'
Successfully opened the file.
detected 4 logical cores
[graph 0 input from stream 0:0 @ 0xea9280] Setting 'video_size' to value '1920x1088'
[graph 0 input from stream 0:0 @ 0xea9280] Setting 'pix_fmt' to value '0'
[graph 0 input from stream 0:0 @ 0xea9280] Setting 'time_base' to value '1/25'
[graph 0 input from stream 0:0 @ 0xea9280] Setting 'pixel_aspect' to value '0/1'
[graph 0 input from stream 0:0 @ 0xea9280] Setting 'sws_param' to value 'flags=2'
[graph 0 input from stream 0:0 @ 0xea9280] Setting 'frame_rate' to value '25/1'
[graph 0 input from stream 0:0 @ 0xea9280] w:1920 h:1088 pixfmt:yuv420p tb:1/25 fr:25/1 sar:0/1 sws_param:flags=2
[format @ 0xeb20e0] compat: called with args=[yuv420p]
[format @ 0xeb20e0] Setting 'pix_fmts' to value 'yuv420p'
[AVFilterGraph @ 0xeb14f0] query_formats: 4 queried, 3 merged, 0 already done, 0 delayed
[h264_omx @ 0xea87a0] Using OMX.broadcom.video_encode
[h264_omx @ 0xea87a0] OMX state changed to 2
[h264_omx @ 0xea87a0] OMX state changed to 3
[h264_omx @ 0xea87a0] OMX port 201 settings changed
Output #0, mp4, to 'out.mp4':
  Metadata:
    encoder         : Lavf57.56.101
    Stream #0:0, 0, 1/12800: Video: h264 (h264_omx), 1 reference frame ([33][0][0][0] / 0x0021), yuv420p, 1920x1088, 0/1, q=2-31, 6000 kb/s, 25 fps, 12800 tbn, 25 tbc
    Metadata:
      encoder         : Lavc57.64.101 h264_omx
Stream mapping:
  Stream #0:0 -> #0:0 (rawvideo (native) -> h264 (h264_omx))
cur_dts is invalid (this is harmless if it occurs once at the start per stream)
[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
Clipping frame in rate conversion by 0.000008
cur_dts is invalid (this is harmless if it occurs once at the start per stream)
[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 10 times
frame=   12 fps=0.0 q=-0.0 size=     149kB time=00:00:00.36 bitrate=3390.8kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 10 times
frame=   23 fps= 21 q=-0.0 size=     551kB time=00:00:00.80 bitrate=5639.3kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 9 times
frame=   33 fps= 21 q=-0.0 size=     902kB time=00:00:01.20 bitrate=6160.1kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 9 times
frame=   43 fps= 20 q=-0.0 size=    1369kB time=00:00:01.60 bitrate=7007.1kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 9 times
frame=   53 fps= 20 q=-0.0 size=    1641kB time=00:00:02.00 bitrate=6721.7kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 9 times
frame=   63 fps= 20 q=-0.0 size=    1802kB time=00:00:02.40 bitrate=6149.7kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
    Last message repeated 9 times
frame=   73 fps= 20 q=-0.0 size=    2074kB time=00:00:02.80 bitrate=6068.9kbits/[rawvideo @ 0xea6e20] PACKET SIZE: 3133440, STRIDE: 2880
^Cmmal: Aborting programd 1 times

    Last message repeated 1 times
frame=   75 fps= 10 q=-0.0 Lsize=    2226kB time=00:00:02.96 bitrate=6159.5kbits/s speed=0.406x    
video:2225kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.050573%
Input file #0 (pipe:):
  Input stream #0:0 (video): 75 packets read (235008000 bytes); 75 frames decoded; 
  Total: 75 packets (235008000 bytes) demuxed
Output file #0 (out.mp4):
  Output stream #0:0 (video): 75 frames encoded; 75 packets muxed (2277909 bytes); 
  Total: 75 packets (2277909 bytes) muxed
75 frames successfully decoded, 0 decoding errors
[AVIOContext @ 0xeb1360] Statistics: 34 seeks, 130 writeouts
[h264_omx @ 0xea87a0] OMX state changed to 2
[h264_omx @ 0xea87a0] OMX state changed to 1
[AVIOContext @ 0xea5f10] Statistics: 235008000 bytes read, 0 seeks
Exiting normally, received signal 2.

Also, I try next command but it freeze too (~1h of encode): This is command for encode and generate image from video feed every second.

ffmpeg -f video4linux2 -pixel_format yuv420p -input_format yuv420p -video_size 1920x1080 -framerate 30 -i /dev/video0 -threads 4 -filter_complex '[0:V]split=2[video][s2];[s2]fps=1,scale=1920:1080[img]' -map [video] -c:v h264_omx  -an -b:v 6M  -y webcam.mp4 -map [img] -f image2 -y img/output_%03d.jpg

@6by9
Copy link

6by9 commented Jul 10, 2019

The original bug is still present in upstream FFmpeg as they haven't responded to their bug tracker - https://trac.ffmpeg.org/ticket/7687. It should be fixed in the Raspbian repos as we have an additional patch.

If you think you have a different lockup, then please create a new issue with as much detail as possible.

I'd also suggest you describe what you're trying to achieve

raspivid -w 1920 -h 1080 -b 6000000 -t 0 -n -r -|ffmpeg -f rawvideo -pix_fmt yuv420p -s 1920x1088 -i - -c:v h264_omx -pix_fmt yuv420p -b:v 6M -loglevel trace -y out.mp4

raspivid will produce H264 encoded video, and option -o - will send it to stdout.
You're then telling ffmpeg to expect rawvideo yuv420p from stdin, and feeding that into h264_omx for H264 encoding. It'll most likely look like noise, and is a nonsensical setup. It's also likely to get very confused as to how big the input buffers to the video encoder are, so the expectation within FFmpeg of 1-in, 1-out from the codec is likely to be broken.

@devalexqt
Copy link

My configuration:
Raspberry Pi 3 B v1.2 (with latest firmware) + Raspberry Pi Camera v1.3

uname -a
Linux raspberrypi 4.19.57-v7+ #1244 SMP Thu Jul 4 18:45:25 BST 2019 armv7l GNU/Linux

First I try to build latest version of ffmpeg from git but it freeze as this thread say then I try to install latest version of ffmpeg from raspbian repository via "sudo apt-get install ffmpeg" and it installs ffmpeg version 3.2.14-1~deb9u1+rpt1 and it still freeze.

I know that I can get h264 from raspivid, but run command with raw video in yuv420p format from raspivid stdout is likely for quick reproduce of the bug because encoder was freeze on 2 seconds.

In my case I need two output files from pi camera, one is video in mp4 container and second output must be series of jpeg images for every seconds of video for analysis in other software, like motion detection. So, my real command is below:

ffmpeg -f video4linux2 -pixel_format yuv420p -input_format yuv420p -video_size 1920x1080 -framerate 30 -i /dev/video0 -threads 4 -filter_complex '[0:V]split=2[video][s2];[s2]fps=1,scale=1920:1080[img]' -map [video] -c:v h264_omx  -an -b:v 6M  -y webcam.mp4 -map [img] -f image2 -y img/output_%03d.jpg

But it still freeze at random run time, for example: 1 minute, 24 minutes or 1 h, etc. I try different run commands for ffmpeg but result it stay the same => freeze and in same cases it may cause OS to freeze too.
I think it a same bug.

@6by9
Copy link

6by9 commented Jul 11, 2019

I think it a same bug.

I took my car to the garage as the engine warning light was on (symptom). They replaced the spark plugs (diagnosis).
The engine warning light came back on (symptom). I have no evidence, but it must be the spark plugs.

If you think you have a different lockup, then please create a new issue

I've done it for you #1185

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants