FFMpeg ignores -shortest and goes on forever filling all the RAM available in a system (Avisynth input)

[Francesco Bucciantini]

Summary of the bug:

Hi there,
I faced a pretty big issue in production when indexing a .thm image.

Source:

General 
Complete name : GX010047.THM 
Format : JPEG 
File size : 8.48 KiB 

Image 
Format : JPEG 
Width : 160 pixels 
Height : 120 pixels 
Color space : YUV 
Chroma subsampling : 4:2:0 
Bit depth : 8 bits 
Compression mode : Lossy 
Stream size : 8.48 KiB (100%)

Such an image is decoded automatically into an H.264 lossless file muxed in .mkv

General
Unique ID : 6999799334518796533026371963913070697 (0x5441CC0A15B8899800EED4347C56869)
Complete name : 20230330-1055-1159-3e30-adfd0282de64\1-24-24~177276031~14840~20170208-151013-452-316F559DBA2D~dec_avmedia_v1.mkv
Format : Matroska
Format version : Version 4
File size : 9.30 KiB
Duration : 40 ms
Overall bit rate : 1 904 kb/s
Frame rate : 25.000 FPS
Writing application : Lavf59.29.100
Writing library : Lavf59.29.100
ErrorDetectionType : Per level 1

Video
ID : 1
Format : AVC
Format/Info : Advanced Video Codec
Format profile : High 4:4:4 Intra@L1.1
Format settings, CABAC : No
Codec ID : V_MPEG4/ISO/AVC
Duration : 40 ms
Width : 160 pixels
Height : 120 pixels
Display aspect ratio : 4:3
Frame rate mode : Constant
Frame rate : 25.000 FPS
Color space : YUV
Chroma subsampling : 4:2:0
Bit depth : 8 bits
Scan type : Progressive
Writing library : x264 core 164 r3095 baee400
Encoding settings : cabac=0 / ref=1 / deblock=0:0:0 / analyse=0:0 / me=dia / subme=0 / psy=0 / mixed_ref=0 / me_range=16 / chroma_me=1 / trellis=0 / 8x8dct=0 / cqm=0 / deadzone=21,11 / fast_pskip=0 / chroma_qp_offset=0 / threads=4 / lookahead_threads=1 / sliced_threads=0 / nr=0 / decimate=1 / interlaced=0 / bluray_compat=0 / constrained_intra=0 / bframes=0 / weightp=0 / keyint=1 / keyint_min=1 / scenecut=0 / intra_refresh=0 / rc=cqp / mbtree=0 / qp=0
Default : No
Forced : No
Color range : Full
Matrix coefficients : BT.470 System B/G

then a logic creates the following script automatically as part of a workflow:

_ffas_video = "\\Media Ingest\Avisynth_Server1\Node2\Avisynth_in\D3 GOPRO\GOMMONE\GX010047.THM"
_ffas_audio = "\\Media Ingest\Avisynth_Server1\Node2\Avisynth_in\D3 GOPRO\GOMMONE\GX010047.THM"
_ffas_width = 160
_ffas_height = 120
_ffas_work_fdr = "\\avisynth\TempFiles\20200505-1441-4178-0e32-00746ba87035\20230330-1055-1159-3e30-adfd0282de64"
Import("\\avisynth\processors\AVS_plugins\avsi\mtmodes.avsi")
LoadPlugin("\\avisynth\processors\AVS_plugins\ffms2\x64\ffms2.dll")
LoadPlugin("\\avisynth\processors\AVS_plugins\ffms2\x64\BestAudioSource.dll")
LoadPlugin("\\avisynth\processors\AVS_plugins\JPSDR\x64\Release_W7\plugins_JPSDR.dll")
FFIndex("\\avisynth\TempFiles\20200505-1441-4178-0e32-00746ba87035\20230330-1055-1159-3e30-adfd0282de64\1-24-24~177276031~14840~20170208-151013-452-316F559DBA2D~dec_avmedia_v1.mkv", cachefile = "\\avisynth\TempFiles\20200505-1441-4178-0e32-00746ba87035\20230330-1055-1159-3e30-adfd0282de64\1-24-24~230330105708426~14840~20170208-151013-452-316F559DBA2D~dec_avmedia~ffindex.dat")
video = FFVideoSource("\\avisynth\TempFiles\20200505-1441-4178-0e32-00746ba87035\20230330-1055-1159-3e30-adfd0282de64\1-24-24~177276031~14840~20170208-151013-452-316F559DBA2D~dec_avmedia_v1.mkv", 0, cachefile = "\\avisynth\TempFiles\20200505-1441-4178-0e32-00746ba87035\20230330-1055-1159-3e30-adfd0282de64\1-24-24~230330105708426~14840~20170208-151013-452-316F559DBA2D~dec_avmedia~ffindex.dat", fpsnum=25000, fpsden=1000, seekmode = 1)
audio_null = BlankClip(length=0, width=160, height=120, color=$000000, channels=1, audio_rate=48000, fps=25)
audio = audio_null
Global m_clip = AudioDub(video, audio)
m_clip = ConvertToYUV422(m_clip)
m_clip = ConvertBits(m_clip, 10)
m_clip = AssumeFieldBased(m_clip)
m_clip = propClearAll(m_clip)
#node_name:ChannelMapper, id:20180910-180019-976-6b94d948b31c
audio_null = GetChannel(m_clip, 1).Amplify(0)
m_clip = MergeChannels(m_clip, audio_null)
m_clip = GetChannel(m_clip, 1,1,1,1,1,1,1,1)

#node_name:Loudness Correction, id:20180910-180715-507-dc0f7fbfc53f
# Variables:
#
# m_clip = The last returned AviSynth media
#
# Do NOT change any of the following variables!!!
# _ffas_video = <original video>
# _ffas_audio = <original audio>
# _ffas_height = <source height>
# _ffas_width = <source width>
# _m_clip_a_channels = <total channels>
# _ffas_work_fdr = Working folder for the workflow
#

r=ResampleAudio(m_clip, 48000)
n=Normalize(r, 0.22)
m_clip=ConvertAudioTo24bit(n)

# The following MUST be the last line of your script
#node_name:Safe Color Limiter, id:20180701-081456-730-68c5351dabf5
Import("\\avisynth\processors\AVS_plugins\avsi\SafeColorLimiter.avsi")
m_clip = SafeColorLimiter(m_clip)
Return m_clip

When I index the original image with

ImageSource("A:\MEDIA\temp\GX010047.THM")

everything is fine.
Same goes when I index the .mkv decoded file with FFVideoSource() in AVSPmod mod.

VirtualDub is also working just fine, BUT not FFMpeg...

Running this command in FFMpeg:

ffmpeg.exe -stats_period 1.2 -hide_banner -i "1-24-24~230330134143483~4044~20211117-1743-5495-7a75-f1d9f457e51c~enc_av_xdcamhd.avs" -f lavfi -i "aevalsrc=0" -f lavfi -i "color=color=black:size=1920x1080" -shortest -map_metadata -1 -map 0:0 -filter_complex "[0:1]pan=1|c0=c0[a1],[0:1]pan=1|c0=c1[a2],[0:1]pan=1|c0=c2[a3],[0:1]pan=1|c0=c3[a4],[0:1]pan=1|c0=c4[a5],[0:1]pan=1|c0=c5[a6],[0:1]pan=1|c0=c6[a7],[0:1]pan=1|c0=c7[a8],[a1]amerge=1,apad[astr1],[a2]amerge=1,apad[astr2],[a3]amerge=1,apad[astr3],[a4]amerge=1,apad[astr4],[a5]amerge=1,apad[astr5],[a6]amerge=1,apad[astr6],[a7]amerge=1,apad[astr7],[a8]amerge=1,apad[astr8]" -map "[astr1]" -c:a:0 pcm_s24le -ar:a:0 48000 -map "[astr2]" -c:a:1 pcm_s24le -ar:a:1 48000 -map "[astr3]" -c:a:2 pcm_s24le -ar:a:2 48000 -map "[astr4]" -c:a:3 pcm_s24le -ar:a:3 48000 -map "[astr5]" -c:a:4 pcm_s24le -ar:a:4 48000 -map "[astr6]" -c:a:5 pcm_s24le -ar:a:5 48000 -map "[astr7]" -c:a:6 pcm_s24le -ar:a:6 48000 -map "[astr8]" -c:a:7 pcm_s24le -ar:a:7 48000 -vf "sidedata=delete,metadata=delete,colorspace=fast=1:ispace=bt470bg:itrc=bt709:iprimaries=bt709:all=bt709:format=yuv422p:irange=pc:range=pc,scale=w=1440:h=1080:flags=lanczos:sws_dither=ed:in_color_matrix=bt709ut_color_matrix=bt709:in_range=pcut_range=pc,pad=w=1920:h=1080:x=240:y=0,setfield=tff,setdar=16/9,setsar=1" -timecode 00:00:00:00 -c:v mpeg2video -r 25 -pix_fmt yuv422p -aspect 16:9 -b:v 50000000 -minrate 50000000 -maxrate 50000000 -intra_vlc 1 -dc 8 -g 12 -bf 2 -mpv_flags +strict_gop -qmin 5 -qmax 28 -qsquish 99 -color_primaries bt709 -color_trc bt709 -colorspace bt709 -color_range tv -seq_disp_ext 1 -video_format component -chroma_sample_location topleft -signal_standard 4 -field_order tt -top 1 -alternate_scan 1 -flags +ildct+ilme+cgop -sc_threshold 1000000000 -intra_matrix 8,10,22,27,29,37,37,40,9,12,14,28,29,37,39,40,9,14,27,31,34,37,40,48,12,22,27,29,34,37,40,58,26,27,29,34,37,38,48,58,26,27,29,36,38,38,48,69,18,27,34,36,38,38,48,69,26,26,34,34,38,40,58,79 -inter_matrix 16,20,22,26,28,32,32,36,18,20,22,28,28,32,34,36,18,22,26,30,30,32,36,38,20,22,26,28,30,32,36,42,24,26,28,30,32,34,38,40,24,26,28,32,34,34,38,42,24,26,30,32,34,34,38,42,24,24,30,30,34,36,40,44 -non_linear_quant 1 -f mxf -max_muxing_queue_size 700 -map_metadata -1 -metadata "creation_time=now" -y "test.mxf"

pause

generates the issue, in fact FFMpeg keeps going and going and going forever, filling up the whole RAM and then the whole paging files until Windows itself crashes:

you can see from the screenshot that although it's not producing any frames in output, it's already filling and filling and filling the RAM as it reached 3 hours already and it would keep going.

This is what happened on a server:

As you can see, it filled the whole 128 GB of RAM first and then it started filling the whole 545 GB of paging files on the SSD before making Windows itself crash (literally, Windows rebooted itself automatically after crashing, badly).

Here's a package with the whole thing: ​https://we.tl/t-N6uwUeBWZc

(link available for 7 days only)

and here's an extract of the output of FFMpeg: ​https://pastebin.com/5FanUB6E

This has been tested and verified with both Avisynth 3.7.2 stable and Avisynth 3.7.3 Beta 9, x64 of course.
For the sake of debugging, commenting out SafeColorLimiter() which is my own function changes nothing.

Anyway, given that AVSPmod mod plays nicely

and that VirtualDub also plays nicely:

and it can output a file just fine:

The discriminant here appears to be FFMpeg...

To double check this, I tried with x264 (but given that it can't read 10bit planar, I changed ConvertBits from 10 to 16):

Surprise surprise, x264 using Jean Philippe Scotto di Rinaldi's build worked and encoded just that one frame.

So... in a nutshell, it looks like it's an FFMpeg bug after all...

Given that the source is 4 frames and that -shortest is there, FFMpeg should read it and use the SHORTEST source available, instead, it goes on forever and ever.

For more info: ​https://forum.doom9.org/showthread.php?p=1985231

[Francesco Bucciantini]

Found the culprit. It's the mute audio that makes it going on and on forever. Basically BlankClip() generates a mute audio, but length=0 makes it go on forever. Now, this shouldn't really matter 'cause

1) The video is 2 frames long anyway (frame 0 and frame 1)
2) Once it goes through AudioDub() it should really follow the video and NOT keep going forever and ever
3) The container is .mxf for which audio and video must always be of the same length, so ffmpeg shouldn't really be doing what it's doing

[Francesco Bucciantini]

What I've actually done in production is check whether the source is an image and has therefore only 1 frame (namely frame 0) and basically force length=1 in BlankClip(), otherwise, if it's not 0, it means that it's a video without audio and therefore I'll grab the video frames and fps and populate length and fps accordingly in BlankClip().
This way it will work and indeed it did:

[Francesco Bucciantini]

Uhmmmm AVSPmod mod is also affected. I'm debugging a bit to understand whether it's ffmpeg at fault or if we (the Avisynth community) are the ones not playing nicely.
Please put the bug on pause, I'll get back to you, 'cause this:

doesn't really look promising, even though in VirtualDub it works...

Investigating further, please wait.

[Francesco Bucciantini]

Issue confirmed on Avisynth side, version 3.7.2 stable.
Will be fixed in 3.7.3 Beta 10.

To quote Stephen (qyot):

FFmpeg reads video and audio packets separately, and if either reaches EOF, it attempts to read the other one before exiting, because it is easily possible - and not a bug - that either video or audio might be longer than the other, and it shouldn't be truncated.
The error is that length=0 is treated by BlankClip as somehow valid when it isn't, and ends up creating an audio stream of infinite length, which FFmpeg then attempts to read/output.

So, in other words, BlankClip(length=0) should really throw an error from our side and it will be addressed 'cause currently it makes FFMpeg attempt to write an ever-increasing number of audio samples, until the process crashes or is killed.

Closing the ticket now.

Cheers,
Frank

[Francesco Bucciantini]

Fixed in Avisynth 3.7.3 Beta 10 by Stephen:

​https://github.com/AviSynth/AviSynthPlus/commit/9c79d295b6917741d99a26bb28eee829223d1d54

Cheers,
Frank