Progress reporting regression for content with large frame gaps

[Zac]

Summary of the bug:
I noticed that the "progress" update in the console output no longer refreshes as of ver 4.3.x (I tested in 4.2.0 to confirm the regression) for certain content.

For reference the "status update" I am talking about is this bit of the console output:

frame= 1106 fps=157 q=26.0 size= 1024kB time=00:00:35.06 bitrate= 239.2kbits/s speed=4.97x

The input content has large periods with no frames. The command I am using fixes this my forcing the output framerate to 30. When I do this in v4.2.1 (and prior) the "speed" and "frame" values written to the console continue to update even though the location in the source is not moving forward (during the large gaps). In 4.3.1, it looks like the progress update only occurs when the source location has changed.

Why does this matter? My app does "hang detection" and this triggers a false positive hang. I can always bump my hang detection timer so it is not a huge deal for me but no matter what I can always encounter content which has longer and longer time between frames (think of a slide presentation where an 8 hour long video may have 10 frames).

FWIW I tried on windows and linux builds and got the same result.

How to reproduce:

c:\ffmpegs\ffmpeg-4.2.1-win64-static\ffmpeg-4.2.1-win64-static>ffmpeg -i input.mp4 -an -map 0:v:0  -vf fps=fps=30,scale=1656:1246,yadif=deint=1  -colorspace bt709 -color_primaries bt709 -color_trc bt709  -pix_fmt yuv420p  -c:v libx264 -profile:v main -level:v 4.2 -preset medium -crf 20  -x264-params bframes=0:scenecut=0:aud=1:cabac=0:colormatrix=bt709 -force_key_frames expr:gte(t,n_forced*3)  -b:v 2560000 -maxrate:v 3840000 -bufsize 11520000 -max_muxing_queue_size 9999  d8ba422f4-cbf7-4986-a2b2-acbc004ba739.m4v
ffmpeg version 4.3.1 Copyright (c) 2000-2020 the FFmpeg developers
  built with gcc 10.2.1 (GCC) 20200726
  configuration: --enable-gpl --enable-version3 --enable-sdl2 --enable-fontconfig --enable-gnutls --enable-iconv --enable-libass --enable-libdav1d --enable-libbluray --enable-libfreetype --enable-libmp3lame --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libopenjpeg --enable-libopus --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libsrt --enable-libtheora --enable-libtwolame --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxml2 --enable-libzimg --enable-lzma --enable-zlib --enable-gmp --enable-libvidstab --enable-libvmaf --enable-libvorbis --enable-libvo-amrwbenc --enable-libmysofa --enable-libspeex --enable-libxvid --enable-libaom --enable-libgsm --enable-librav1e --disable-w32threads --enable-libmfx --enable-ffnvcodec --enable-cuda-llvm --enable-cuvid --enable-d3d11va --enable-nvenc --enable-nvdec --enable-dxva2 --enable-avisynth --enable-libopenmpt --enable-amf
  libavutil      56. 51.100 / 56. 51.100
  libavcodec     58. 91.100 / 58. 91.100
  libavformat    58. 45.100 / 58. 45.100
  libavdevice    58. 10.100 / 58. 10.100
  libavfilter     7. 85.100 /  7. 85.100
  libswscale      5.  7.100 /  5.  7.100
  libswresample   3.  7.100 /  3.  7.100
  libpostproc    55.  7.100 / 55.  7.100
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'input.mp4':
  Metadata:
    major_brand     : mp42
    minor_version   : 1
    compatible_brands: isommp41mp42
    creation_time   : 2021-01-20T16:18:49.000000Z
  Duration: 00:27:44.94, start: 0.000000, bitrate: 419 kb/s
    Stream #0:0(und): Audio: aac (LC) (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 247 kb/s (default)
    Metadata:
      creation_time   : 2021-01-20T16:18:49.000000Z
      handler_name    : Core Media Audio
    Stream #0:1(und): Video: h264 (High) (avc1 / 0x31637661), yuvj420p(pc, bt709/bt709/iec61966-2-1), 1440x1920, 169 kb/s, 6.99 fps, 60 tbr, 600 tbn, 1200 tbc (default)
    Metadata:
      rotate          : 270
      creation_time   : 2021-01-20T16:18:49.000000Z
      handler_name    : Core Media Video
    Side data:
      displaymatrix: rotation of 90.00 degrees
Stream mapping:
  Stream #0:1 -> #0:0 (h264 (native) -> h264 (libx264))
Press [q] to stop, [?] for help
[swscaler @ 00000203a4821a00] deprecated pixel format used, make sure you did set range correctly
[libx264 @ 00000203a0601340] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 BMI2 AVX2
[libx264 @ 00000203a0601340] profile Main, level 4.2, 4:2:0, 8-bit
[libx264 @ 00000203a0601340] 264 - core 161 - H.264/MPEG-4 AVC codec - Copyleft 2003-2020 - http://www.videolan.org/x264.html - options: cabac=0 ref=3 deblock=1:0:0 analyse=0x1:0x111 me=hex subme=7 psy=1 psy_rd=1.00:0.00 mixed_ref=1 me_range=16 chroma_me=1 trellis=1 8x8dct=0 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=-2 threads=12 lookahead_threads=2 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=0 weightp=2 keyint=250 keyint_min=25 scenecut=0 intra_refresh=0 rc_lookahead=40 rc=crf mbtree=1 crf=20.0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 vbv_maxrate=3840 vbv_bufsize=11520 crf_max=0.0 nal_hrd=none filler=0 ip_ratio=1.40 aq=1:1.00
Output #0, ipod, to 'd8ba422f4-cbf7-4986-a2b2-acbc004ba739.m4v':
  Metadata:
    major_brand     : mp42
    minor_version   : 1
    compatible_brands: isommp41mp42
    encoder         : Lavf58.45.100
    Stream #0:0(und): Video: h264 (libx264) (avc1 / 0x31637661), yuv420p(bt709), 1656x1246, q=-1--1, 2560 kb/s, 30 fps, 15360 tbn, 30 tbc (default)
    Metadata:
      encoder         : Lavc58.91.100 libx264
      creation_time   : 2021-01-20T16:18:49.000000Z
      handler_name    : Core Media Video
    Side data:
      cpb: bitrate max/min/avg: 3840000/0/2560000 buffer size: 11520000 vbv_delay: N/A
      displaymatrix: rotation of -0.00 degrees
[out_0_0 @ 00000203a471f1c0] 100 buffers queued in out_0_0, something may be wrong.peed=2.47x
frame=  290 fps=113 q=26.0 size=       0kB time=00:00:07.86 bitrate=   0.0kbits/s speed=3.06x

Notes:
I used this version
​https://github.com/BtbN/FFmpeg-Builds/releases/tag/autobuild-2021-01-26-12-37 (I tried many prior 4.3.1 vernos too)

I would submit my input.mp4 file which repros it but it has customer content so I cannot. I have probably two dozen other files (all with large gaps between the video frames) but I have not got approval to share externally.

[Zac]

ffmpeg -i input.mp4 -an -map 0:v:0 -vf fps=fps=30,scale=1656:1246,yadif=deint=1 -colorspace bt709 -color_primaries bt709 -color_trc bt709 -pix_fmt yuv420p -c:v libx264 -profile:v main -level:v 4.2 -preset medium -crf 20 -x264-params bframes=0:scenecut=0:aud=1:cabac=0:colormatrix=bt709 -force_key_frames expr:gte(t,n_forced*3) -b:v 2560000 -maxrate:v 3840000 -bufsize 11520000 -max_muxing_queue_size 9999 d8ba422f4-cbf7-4986-a2b2-acbc004ba739.m4v -v 9 -loglevel 99

[Carl Eugen Hoyos]

Is the issue you see reproducible with current FFmpeg gut head, the only version supported on this bug tracker?
If you cannot provide an input file that allows to reproduce the issue, please run git bisect to find the change introducing the regression.

[Zac]

io stats

[Zac]

cehoyos, thanks for looking at this quickly

Yes. This reproduces with master. I used the 20210127 build from ​https://johnvansickle.com/ffmpeg/builds/ffmpeg-git-amd64-static.tar.xz.

I am still getting approval from our customer to share the actual file that reproduces the issue. I *hope* to be able to send it.

I found something else which points to what may be an actual root of the issue. I noticed that if I execute the repro command (See bottom of this post for command) from an ec2 instance, the machine goes unresponsive. It all ssh connections are "hung" and no new ones are even collected. Host level metrics fortunately continue to populate which allows me to see that as of 4.3.1.20200831, the read IO is off the charts! See the attached image. There are almost a million readops per minute and 40GB of reads per minute! Note: CPU and write are all nominal so those are not the bottleneck. Last note: The input file is 83MB.

My guess is that we are doing crazy seeking behavior to try to handle this content!

repro command
:./ffmpeg -y -hide_banner -i /root/veros/repro.mp4 -vn -map 0:a:0 -ac 2 -c:a aac -profile:a aac_low -b:a 248750 -maxrate:a 373125 -max_muxing_queue_size 9999 /host/panopto/scratch/1/ec9533d8-13fb-40f1-aa2b-acc2002563fe.m4a -an -map 0:v:0 -vf fps=fps=30,scale=1656:1246,yadif=deint=1 -colorspace bt709 -color_primaries bt709 -color_trc bt709 -pix_fmt yuv420p -c:v libx264 -profile:v main -level:v 4.2 -preset medium -crf 20 -x264-params bframes=0:scenecut=0:aud=1:cabac=0:colormatrix=bt709 -b:v 2560000 -maxrate:v 3840000 -bufsize 11520000 -max_muxing_queue_size 9999 /host/panopto/scratch/1/cb704e72-a038-4eb6-8e5f-acc200256400.m4v)

[Zac]

@cehoyos

I received word back from the person who has been creating the "repro content." Before they provide their permission to share the content here they wanted the following Qs answered:
-- How long will the repro file be retained by ffmpeg? Is there a period when it will be deleted (I can manage content lifecycle on the storage server if need be)
-- Who will have access to the repro content? Can we restrict to a specific developer or set of developers? If need be, I can work with specific developers and hand them expiring URLs.

Thanks!
-Zac

[Carl Eugen Hoyos]

Forever / everybody

[Carl Eugen Hoyos]

Please run git bisect to find the change introducing the issue you see.

[Zac]

Good news! I found a customer who let me share the file! That is presumably far more useful.
Sadly, the upload.ffmpeg.org ftp server keeps timing out so I can't repro it. Instead, I plopped the files up on my own s3 bucket for folks to access:

--​http://cdn-devtest.d.panopto.com/zacesq/ticket/9081/dd_ticket9081.mp4

• ​http://cdn-devtest.d.panopto.com/zacesq/ticket/9081/ticket9081.mp4
• ​http://cdn-devtest.d.panopto.com/zacesq/ticket/9081/ticket9081.rm

Enjoy!

[Carl Eugen Hoyos]

Probably a regression since b794df43f3a521985f27d40974316db40b64cc88

I tested with a simplified command line, and the issue I see is not (primarily) a problem with the status line but that my system goes oom:

$ ffmpeg -i ticket9081.mp4 -vf fps=30 -qscale 2 -an out.avi
ffmpeg version N-101060-gbd50e715a9 Copyright (c) 2000-2021 the FFmpeg developers
  built with gcc 10 (SUSE Linux)
  configuration: --enable-gpl
  libavutil      56. 65.100 / 56. 65.100
  libavcodec     58.122.100 / 58.122.100
  libavformat    58. 67.100 / 58. 67.100
  libavdevice    58. 11.103 / 58. 11.103
  libavfilter     7.105.100 /  7.105.100
  libswscale      5.  8.100 /  5.  8.100
  libswresample   3.  8.100 /  3.  8.100
  libpostproc    55.  8.100 / 55.  8.100
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'ticket9081.mp4':
  Metadata:
    major_brand     : mp42
    minor_version   : 1
    compatible_brands: isommp41mp42
    creation_time   : 2021-02-02T23:52:38.000000Z
  Duration: 00:12:45.87, start: 0.000000, bitrate: 458 kb/s
  Stream #0:0(und): Audio: aac (LC) (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 217 kb/s (default)
    Metadata:
      creation_time   : 2021-02-02T23:52:38.000000Z
      handler_name    : Core Media Audio
      vendor_id       : [0][0][0][0]
  Stream #0:1(und): Video: h264 (High) (avc1 / 0x31637661), yuvj420p(pc, bt709/bt709/iec61966-2-1), 1440x1920, 239 kb/s, 1.95 fps, 60 tbr, 600 tbn, 1200 tbc (default)
    Metadata:
      rotate          : 270
      creation_time   : 2021-02-02T23:52:38.000000Z
      handler_name    : Core Media Video
      vendor_id       : [0][0][0][0]
    Side data:
      displaymatrix: rotation of 90.00 degrees
Please use -q:a or -q:v, -qscale is ambiguous
Stream mapping:
  Stream #0:1 -> #0:0 (h264 (native) -> mpeg4 (native))
Press [q] to stop, [?] for help
[swscaler @ 0x413a5c0] deprecated pixel format used, make sure you did set range correctly
Output #0, avi, to 'out.avi':
  Metadata:
    major_brand     : mp42
    minor_version   : 1
    compatible_brands: isommp41mp42
    ISFT            : Lavf58.67.100
  Stream #0:0(und): Video: mpeg4 (FMP4 / 0x34504D46), yuv420p(tv, bt709/bt709/iec61966-2-1, progressive), 1920x1440, q=2-31, 200 kb/s, 30 fps, 30 tbn (default)
    Metadata:
      encoder         : Lavc58.122.100 mpeg4
      creation_time   : 2021-02-02T23:52:38.000000Z
      handler_name    : Core Media Video
      vendor_id       : [0][0][0][0]
    Side data:
      cpb: bitrate max/min/avg: 0/0/200000 buffer size: 0 vbv_delay: N/A
      displaymatrix: rotation of -0.00 degrees
[out_0_0 @ 0x376bdc0] 100 buffers queued in out_0_0, something may be wrong.ts/s speed= 3.3x       
[out_0_0 @ 0x376bdc0] 1000 buffers queued in out_0_0, something may be wrong.s/s speed=3.31x    
Killed

[David Ing]

This is still a problem with ffmpeg 4.4.1, tested on Windows x64, via the static build from BtbN (​https://github.com/BtbN/FFmpeg-Builds).

The links provided by the OP are no longer valid. I obtained the media file from the OP and I have placed them in a gfolder here:

​https://drive.google.com/drive/folders/18myjTOQ7zbH7EZBp87sf7rYistXEvx56?usp=sharing

[David Ing]

Ffmpeg is seriously broken. When I execute the command, ffmpeg consumes 23.5 GB (giga) of memory:

ffmpeg -i repro.mp4 -vf fps=30 -qscale 2 -an out.avi

[Elon Musk]

Fixed in 01440e258827f77990d918bfeb77cb613bc3733a

[David Ing]

I just cherry-picked the commit ...

​https://github.com/FFmpeg/FFmpeg/commit/01440e258827f77990d918bfeb77cb613bc3733a

... into my local 4.4.1 branch and the problem was not resolved.

I still see 24.5 GB (gigabytes) of RAM consumed, and I still see messages like the following.

[out_0_0 @ 0x55945bb40f40] 100 buffers queued in out_0_0, something may be wrong.speed=4.28x
[out_0_0 @ 0x55945bb40f40] 1000 buffers queued in out_0_0, something may be wrong.peed=5.02x

Next I will try building straight from master.

[David Ing]

The problem is fixed in master, so I will leave this bug closed.

[Elon Musk]

You need also commit before that one, but dunno why it does not work, 4.4.1 avfilter code is different a lot.

[David Ing]

The following fixes 4.4.1. Thanks!

git cherry-pick 531d09fb2d6bddb968dbef1fbb8b351aed85cbfa
git cherry-pick 01440e258827f77990d918bfeb77cb613bc3733a