Opened 7 months ago

Closed 5 months ago

#9160 closed defect (fixed)

ffmpeg stuck at initialization

Reported by: Gyan Owned by:
Priority: important Component: ffmpeg
Version: git-master Keywords: regression
Cc: Blocked By:
Blocking: Reproduced by developer: yes
Analyzed by developer: yes

Description

ffmpeg gets stuck at initialization with the following command, with a CPU core running steady near 100%:

cat video.ts | ffmpeg -i - -f image2 -loop 1 -re -i image.png -filter_complex "[0:v]scale=iw:ih[in];[1][in]scale2ref[img][in1];[in1][img]overlay[out]" -map "[out]" -map 0:a -f null -

The sufficient and necessary conditions appear to be that the first input be non-seekable, and the image input have the -re flag applied. Removing either of these conditions and the issue disappears.

Based on the nature I suspected that one or more commits made to ffmpeg.c in Oct 2020 might be the culprit. And indeed, the issue doesn't occur with my 2020-10-28 build but does occur with my 2020-10-31 build. The commits I suspect are 67be1ce0c6 and 7369595c55.

How to generate inputs:

ffmpeg -f lavfi -i testsrc2 -f lavfi -i sine -t 5 video.ts

ffmpeg -f lavfi -i mandelbrot -vframes 1 image.png

Change History (15)

comment:1 by Gregory Beauregard, 7 months ago

Keywords: regression added

I've been having a similar problem where I get initialization freezes for a few months where 1 CPU gets stuck at 100% when I'm using -re as part of an ffmpeg encode to send live over SRT. Yesterday I bisected it to a regression since 67be1ce0c6de330b1c10d1d121819d8a74a7b1f5 (what op suspects). However, I can trigger it in a number of other situations (-re plus a subtitles track overlay...sometimes, -re plus a pre-input -ss time seek, often) and I can sometimes fix it with bizarre workarounds like inserting a noop vulkan hwupload/hwdownload.

Last edited 7 months ago by Gregory Beauregard (previous) (diff)

comment:2 by jeeb, 7 months ago

For the record, I will attempt to look into what is exactly going wrong where soon - I am just currently a bit burnt-out with $dayjob and OSS stuff. Hopefully I will feel better soon.

comment:3 by Gregory Beauregard, 6 months ago

Here's a reproducer that works consistently for me: https://stream.gably.net/images/initfreeze.mkv (4.5 MB)

Command to reproduce freeze: ffmpeg -ss 00:00:30 -re -i initfreeze.mkv -c:v libx264 -preset superfast -b:v 500k -c:a libopus -channel_layout stereo -b:a 60k -map 0:a -map 0:v -map_metadata -1 -y initfreeze2.mkv

comment:4 by jeeb, 6 months ago

Ran Gyan's test case with -v verbose and -debug_ts added. Now we can go through the steps that happen:

  1. Inputs get probed
    Input #0, mpegts, from 'pipe:':
      Duration: N/A, start: 1.429089, bitrate: N/A
      Program 1
        Metadata:
          service_name    : Service01
          service_provider: FFmpeg
      Stream #0:0[0x100]: Video: mpeg2video (Main), 1 reference frame ([2][0][0][0] / 0x0002), yuv420p(tv, progressive, left), 320x240 [SAR 1:1 DAR 4:3], 25 fps, 25 tbr, 90k tbn, 50 tbc
        Side data:
          cpb: bitrate max/min/avg: 0/0/0 buffer size: 49152 vbv_delay: N/A
      Stream #0:1[0x101]: Audio: mp2 ([3][0][0][0] / 0x0003), 44100 Hz, mono, fltp, 384 kb/s
    Input #1, image2, from 'image.png':
      Duration: 00:00:00.04, start: 0.000000, bitrate: N/A
      Stream #1:0: Video: png, 1 reference frame, rgb24(pc), 640x480 [SAR 1:1 DAR 4:3], 25 fps, 25 tbr, 25 tbn, 25 tbc
    
  2. Filters get their initial configuration
    [Parsed_scale_0 @ 0x326e780] w:iw h:ih flags:'bilinear' interl:0
    [Parsed_scale2ref_1 @ 0x326b140] w:iw h:ih flags:'bilinear' interl:0
    
  3. Streams are mapped
    Stream mapping:
      Stream #0:0 (mpeg2video) -> scale (graph 0)
      Stream #1:0 (png) -> scale2ref:default (graph 0)
      overlay (graph 0) -> Stream #0:0 (wrapped_avframe)
      Stream #0:1 -> #0:1 (mp2 (native) -> pcm_s16le (native))
    
  1. First video packet from input #0 is read in, it is fed to decoder but nothing is received yet. No further initialization is done yet, as we need the metadata from the decoded+filtered AVFrame for better initialization. The throwing of the packet into the decoder is not yet logged, but that should happen at this point.
    demuxer -> ist_index:0 type:video next_dts:NOPTS next_dts_time:NOPTS next_pts:NOPTS next_pts_time:NOPTS pkt_pts:129600 pkt_pts_time:1.44 pkt_dts:126000 pkt_dts_time:1.4 off:-1429089 off_time:-1.42909
    demuxer+ffmpeg -> ist_index:0 type:video pkt_pts:982 pkt_pts_time:0.0109111 pkt_dts:-2618 pkt_dts_time:-0.0290889 off:-1429089 off_time:-1.42909
    
  1. First audio packet from input #0 is read, fed into decoder and received. Then fed and received from the filter chain and fed and received through the raw audio "encoder".
    demuxer -> ist_index:1 type:audio next_dts:NOPTS next_dts_time:NOPTS next_pts:NOPTS next_pts_time:NOPTS pkt_pts:128618 pkt_pts_time:1.42909 pkt_dts:128618 pkt_dts_time:1.42909 off:-1429089 off_time:-1.42909
    [mpegts @ 0x3233e00] Thread message queue blocking; consider raising the thread_queue_size option (current value: 8)
    demuxer+ffmpeg -> ist_index:1 type:audio pkt_pts:0 pkt_pts_time:0 pkt_dts:0 pkt_dts_time:0 off:-1429089 off_time:-1.42909
    [graph_1_in_0_1 @ 0x3241cc0] tb:1/44100 samplefmt:s16p samplerate:44100 chlayout:0x4
    [format_out_0_1 @ 0x354eb80] auto-inserting filter 'auto_resampler_0' between the filter 'Parsed_anull_0' and the filter 'format_out_0_1'
    [auto_resampler_0 @ 0x354fd80] ch:1 chl:mono fmt:s16p r:44100Hz -> ch:1 chl:mono fmt:s16 r:44100Hz
    filter -> pts:0 pts_time:0 exact:-0.000008 time_base:1/44100
    
    encoder <- type:audio frame_pts:0 frame_pts_time:0 time_base:1/44100
    encoder -> type:audio pkt_pts:0 pkt_pts_time:0 pkt_dts:0 pkt_dts_time:0
    
  2. Another audio packet is churned through from input #0
    demuxer -> ist_index:1 type:audio next_dts:26122 next_dts_time:0.026122 next_pts:26122 next_pts_time:0.026122 pkt_pts:130969 pkt_pts_time:1.45521 pkt_dts:130969 pkt_dts_time:1.45521 off:-1429089 off_time:-1.42909
    demuxer+ffmpeg -> ist_index:1 type:audio pkt_pts:2351 pkt_pts_time:0.0261222 pkt_dts:2351 pkt_dts_time:0.0261222 off:-1429089 off_time:-1.42909
    filter -> pts:1152 pts_time:0.0261224 exact:1152.000008 time_base:1/44100
    encoder <- type:audio frame_pts:1152 frame_pts_time:0.0261224 time_base:1/44100
    encoder -> type:audio pkt_pts:1152 pkt_pts_time:0.0261224 pkt_dts:1152 pkt_dts_time:0.0261224
    
  3. A video packet is read from input #0, and we finally get our first decoded video frame for this input.
    demuxer -> ist_index:0 type:video next_dts:10911 next_dts_time:0.010911 next_pts:0 next_pts_time:0 pkt_pts:133200 pkt_pts_time:1.48 pkt_dts:129600 pkt_dts_time:1.44 off:-1429089 off_time:-1.42909
    demuxer+ffmpeg -> ist_index:0 type:video pkt_pts:4582 pkt_pts_time:0.0509111 pkt_dts:982 pkt_dts_time:0.0109111 off:-1429089 off_time:-1.42909
    decoder -> ist_index:0 type:video frame_pts:982 frame_pts_time:0.0109111 best_effort_ts:982 best_effort_ts_time:0.0109111 keyframe:1 frame_type:1 time_base:1/90000
    
  4. ffmpeg.c has moved on to input #1, the image2 PNGs. We receive our first read packets (which as far as I can tell, are actually being pushed to decoding as we will see logging that follows)
    demuxer -> ist_index:2 type:video next_dts:NOPTS next_dts_time:NOPTS next_pts:NOPTS next_pts_time:NOPTS pkt_pts:0 pkt_pts_time:0 pkt_dts:0 pkt_dts_time:0 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:0 pkt_pts_time:0 pkt_dts:0 pkt_dts_time:0 off:0 off_time:0
    demuxer -> ist_index:2 type:video next_dts:40000 next_dts_time:0.04 next_pts:0 next_pts_time:0 pkt_pts:1 pkt_pts_time:0.04 pkt_dts:1 pkt_dts_time:0.04 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:1 pkt_pts_time:0.04 pkt_dts:1 pkt_dts_time:0.04 off:0 off_time:0
    [image2 @ 0x3243540] Thread message queue blocking; consider raising the thread_queue_size option (current value: 8)
    
  5. X number of further PNG packets follow
    demuxer -> ist_index:2 type:video next_dts:80000 next_dts_time:0.08 next_pts:0 next_pts_time:0 pkt_pts:2 pkt_pts_time:0.08 pkt_dts:2 pkt_dts_time:0.08 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:2 pkt_pts_time:0.08 pkt_dts:2 pkt_dts_time:0.08 off:0 off_time:0
    
    demuxer -> ist_index:2 type:video next_dts:120000 next_dts_time:0.12 next_pts:0 next_pts_time:0 pkt_pts:3 pkt_pts_time:0.12 pkt_dts:3 pkt_dts_time:0.12 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:3 pkt_pts_time:0.12 pkt_dts:3 pkt_dts_time:0.12 off:0 off_time:0
    
    demuxer -> ist_index:2 type:video next_dts:160000 next_dts_time:0.16 next_pts:0 next_pts_time:0 pkt_pts:4 pkt_pts_time:0.16 pkt_dts:4 pkt_dts_time:0.16 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:4 pkt_pts_time:0.16 pkt_dts:4 pkt_dts_time:0.16 off:0 off_time:0
    
    demuxer -> ist_index:2 type:video next_dts:200000 next_dts_time:0.2 next_pts:0 next_pts_time:0 pkt_pts:5 pkt_pts_time:0.2 pkt_dts:5 pkt_dts_time:0.2 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:5 pkt_pts_time:0.2 pkt_dts:5 pkt_dts_time:0.2 off:0 off_time:0
    
    demuxer -> ist_index:2 type:video next_dts:240000 next_dts_time:0.24 next_pts:0 next_pts_time:0 pkt_pts:6 pkt_pts_time:0.24 pkt_dts:6 pkt_dts_time:0.24 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:6 pkt_pts_time:0.24 pkt_dts:6 pkt_dts_time:0.24 off:0 off_time:0
    
    demuxer -> ist_index:2 type:video next_dts:280000 next_dts_time:0.28 next_pts:0 next_pts_time:0 pkt_pts:7 pkt_pts_time:0.28 pkt_dts:7 pkt_dts_time:0.28 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:7 pkt_pts_time:0.28 pkt_dts:7 pkt_dts_time:0.28 off:0 off_time:0
    
    demuxer -> ist_index:2 type:video next_dts:320000 next_dts_time:0.32 next_pts:0 next_pts_time:0 pkt_pts:8 pkt_pts_time:0.32 pkt_dts:8 pkt_dts_time:0.32 off:0 off_time:0
    demuxer+ffmpeg -> ist_index:2 type:video pkt_pts:8 pkt_pts_time:0.32 pkt_dts:8 pkt_dts_time:0.32 off:0 off_time:0
    
  6. We finally get our first decoded frame, and we are now finally getting to pushing AVFrames into all bits of the video filtering
    decoder -> ist_index:0 type:video frame_pts:0 frame_pts_time:0 best_effort_ts:0 best_effort_ts_time:0 keyframe:1 frame_type:1 time_base:1/25
    
    [Parsed_scale_0 @ 0x32745c0] w:iw h:ih flags:'bilinear' interl:0
    [Parsed_scale2ref_1 @ 0x3274b40] w:iw h:ih flags:'bilinear' interl:0
    [graph 0 input from stream 0:0 @ 0x358efc0] w:320 h:240 pixfmt:yuv420p tb:1/90000 fr:25/1 sar:1/1
    [graph 0 input from stream 1:0 @ 0x358f780] w:640 h:480 pixfmt:rgb24 tb:1/25 fr:25/1 sar:1/1
    [Parsed_scale_0 @ 0x32745c0] w:320 h:240 fmt:yuv420p sar:1/1 -> w:320 h:240 fmt:yuv420p sar:1/1 flags:0x2
    [Parsed_scale2ref_1 @ 0x3274b40] w:320 h:240 fmt:yuv420p sar:1/1 -> w:320 h:240 fmt:yuva420p sar:1/1 flags:0x2
    [Parsed_overlay_2 @ 0x358e6c0] main w:320 h:240 fmt:yuv420p overlay w:320 h:240 fmt:yuva420p
    [Parsed_overlay_2 @ 0x358e6c0] [framesync @ 0x358e7e8] Selected 1/90000 time base
    [Parsed_overlay_2 @ 0x358e6c0] [framesync @ 0x358e7e8] Sync level 2
    
  7. This is then where ffmpeg.c seems to now get stuck. We know that video encoders only initialize after the filter chain first returns something. We can also see this by the fact that we only had two audio related "filter ->" outputs in the log. Nothing regarding video.
  8. That log is made in "adjust_frame_pts_to_encoder_tb" which for video is being called from "do_video_out". Lack of seeing that means that the logic within "reap_filters" is not receiving anything from "av_buffersink_get_frame_flags".
  9. And finally, as you ctrl+C the process, the following things occur:
    1. The decoder is flushed, we receive one frame from each video decoder (or at least that is what's logged).
      decoder -> ist_index:0 type:video frame_pts:4582 frame_pts_time:0.0509111 best_effort_ts:4582 best_effort_ts_time:0.0509111 keyframe:0 frame_type:2 time_base:1/90000
      decoder -> ist_index:0 type:video frame_pts:1 frame_pts_time:0.04 best_effort_ts:1 best_effort_ts_time:0.04 keyframe:1 frame_type:1 time_base:1/25
      
  10. General encoding stats are written.
    Finishing stream 0:0 without any data written to it.
    Output #0, null, to 'pipe:':
      Metadata:
        encoder         : Lavf58.78.100
      Stream #0:0: Video: wrapped_avframe, 1 reference frame, yuv420p, 320x240 (0x0) [SAR 1:1 DAR 4:3], q=2-31, 200 kb/s, 25 fps, 25 tbn (default)
        Metadata:
          encoder         : Lavc58.136.101 wrapped_avframe
      Stream #0:1: Audio: pcm_s16le, 44100 Hz, mono, s16, 705 kb/s
        Metadata:
          encoder         : Lavc58.136.101 pcm_s16le
    muxer <- type:audio pkt_pts:0 pkt_pts_time:0 pkt_dts:0 pkt_dts_time:0 size:2304
    muxer <- type:audio pkt_pts:1152 pkt_pts_time:0.0261224 pkt_dts:1152 pkt_dts_time:0.0261224 size:2304
    frame=    0 fps=0.0 q=0.0 Lsize=N/A time=00:00:00.05 bitrate=N/A speed=0.00443x    
    video:0kB audio:4kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
    
  11. General stats are written
    Input file #0 (pipe:):
      Input stream #0:0 (video): 2 packets read (19867 bytes); 2 frames decoded; 
      Input stream #0:1 (audio): 2 packets read (2507 bytes); 2 frames decoded (2304 samples); 
      Total: 4 packets (22374 bytes) demuxed
    Input file #1 (image.png):
      Input stream #1:0 (video): 9 packets read (2097270 bytes); 2 frames decoded; 
      Total: 9 packets (2097270 bytes) demuxed
    Output file #0 (pipe:):
      Output stream #0:0 (video): 0 frames encoded; 0 packets muxed (0 bytes); 
      Output stream #0:1 (audio): 2 frames encoded (2304 samples); 2 packets muxed (4608 bytes); 
      Total: 2 packets (4608 bytes) muxed
    [AVIOContext @ 0x3244f00] Statistics: 507412 bytes read, 0 seeks
    Exiting normally, received signal 2.
    

comment:5 by jeeb, 6 months ago

The thread queue size messages for AVPacket handling initially seem like a red herring, since by setting the thread queue for both inputs hilariously high (10k) has no other effect than the image2 input doing a *lot* more reading on the AVIO level.

comment:6 by jeeb, 6 months ago

Used gdb with gdb --pid="$(pgrep ffmpeg)", and just the first point where I find it located is in trying to pick which output stream to process:

#2  av_log (avcl=avcl@entry=0x0, level=<optimized out>, level@entry=48, 
    fmt=0x1431fee "cur_dts is invalid st:%d (%d) [init:%d i_done:%d finish:%d] (this is harmless if it occurs once at the start per stream)\n")
    at src/libavutil/log.c:411
        vl = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7ffc9694a940, reg_save_area = 0x7ffc9694a880}}
#3  0x00000000004aab21 in choose_output () at src/fftools/ffmpeg.c:3956
        ost = 0x3942f00
        opts = <optimized out>
        opts_min = 9223372036854775807
        ost_min = 0x0
        i = 0
        ost = <optimized out>
        opts = <optimized out>
#4  transcode_step () at src/fftools/ffmpeg.c:4686
        ist = 0x0
        ost = <optimized out>
        ret = <optimized out>
        i = <optimized out>
        ifilter = <optimized out>
#5  transcode () at src/fftools/ffmpeg.c:4808
        cur_time = <optimized out>
        total_packets_written = 0
        ret = <optimized out>
        timer_start = <optimized out>
        i = <optimized out>
        ist = <optimized out>
        os = <optimized out>
        ost = <optimized out>
#6  0x00000000004a9425 in main (argc=<optimized out>, argv=<optimized out>) at src/fftools/ffmpeg.c:5013
        ret = <optimized out>
        i = <optimized out>
        ti = {real_usec = 195896914413, user_usec = 6420, sys_usec = 6391}

comment:7 by jeeb, 6 months ago

Then when I hit ctrl+C it ends up at:

Thread 1 "ffmpeg" received signal SIGINT, Interrupt.
0x00000000004e1f4e in ff_filter_graph_run_once (graph=<optimized out>) at src/libavfilter/avfiltergraph.c:1398
1398	    for (i = 1; i < graph->nb_filters; i++)
(gdb) bt full
#0  0x00000000004e1f4e in ff_filter_graph_run_once (graph=<optimized out>) at src/libavfilter/avfiltergraph.c:1398
        i = <optimized out>
        filter = 0x39acd80
#1  0x00000000004e28b2 in get_frame_internal (ctx=0x3a21500, frame=frame@entry=0x0, flags=flags@entry=1, samples=<optimized out>)
    at src/libavfilter/buffersink.c:131
        inlink = 0x3c80940
        buf = 0x39ea3c0
        cur_frame = 0x0
        ret = <optimized out>
        pts = -9223372036854775808
        status = 0
#2  0x00000000004e272f in av_buffersink_get_frame_flags (ctx=0x39acd80, frame=0x5, frame@entry=0x0, flags=60476800, flags@entry=1)
    at src/libavfilter/buffersink.c:142
No locals.
#3  0x00000000004e1ae5 in avfilter_graph_request_oldest (graph=0x3a11e40) at src/libavfilter/avfiltergraph.c:1356
        oldest = 0x3c80940
        r = <optimized out>
        frame_count = <optimized out>
#4  0x00000000004aabfe in transcode_from_filter (graph=0x3929d80, best_ist=<optimized out>) at src/fftools/ffmpeg.c:4642
        nb_requests_max = 0
        ret = <optimized out>
        i = <optimized out>
        ist = <optimized out>
        ifilter = <optimized out>
        nb_requests = <optimized out>
#5  transcode_step () at src/fftools/ffmpeg.c:4732
        ist = 0x0
        ost = <optimized out>
        ret = <optimized out>
        i = <optimized out>
        ifilter = <optimized out>
#6  transcode () at src/fftools/ffmpeg.c:4808
        cur_time = <optimized out>
        total_packets_written = 0
        ret = <optimized out>
        timer_start = <optimized out>
        i = <optimized out>
        ist = <optimized out>
        os = <optimized out>
        ost = <optimized out>
#7  0x00000000004a9425 in main (argc=<optimized out>, argv=<optimized out>) at src/fftools/ffmpeg.c:5013
        ret = <optimized out>
        i = <optimized out>
        ti = {real_usec = 195896914413, user_usec = 6420, sys_usec = 6391}

comment:8 by jeeb, 6 months ago

Making that specific timestamp message verbose instead of debug, you get this during various points of the process, including when you seem to get stuck:

cur_dts is invalid st:0 (0) [init:0 i_done:0 finish:0] (this is harmless if it occurs once at the start per stream)
    Last message repeated 4263554 timeses

comment:9 by jeeb, 6 months ago

That message does make sense since init is done in init_output_stream_wrapper, which is called from do_video_out, which is not being called in reap_filters as there is no video frame yet available in the filter chain...

Time to check where the video frames are fed to the filter chain :) .

comment:10 by Gregory Beauregard, 6 months ago

For other people who run into encodes that won't work because of this bug I've found a few workarounds you can try in rough order of preference/difficulty:

  • Downgrade to the 4.3 branch (at least until the circumstances of the bug are understood so you know when -re is safe to use). For my streaming wrapper where I need to use -re a lot I've forked ffmpeg 4.3 and I selectively backport fixes.
  • In some cases I've found inserting a noop vulkan hwupload/hwdownload can allow you to do your encode again, but make sure you don't use an actual noop vulkan filter because (unrelated) bugs can lead to frame reordering and video corruption. I've found this often works when I have this freeze on a video with a subtitle overlay.
  • You might try piping ffmpeg into itself to try to put the line with the -re in a separate instance. For example, do all your video filters/seeking/etc in one ffmpeg.c instance (without -re) and send it to a nut rawvideo format, then pipe that into an ffmpeg.c instance with -re to do your actual encode. The idea is that if the freeze is related to any filters/seeking/overlays you can do that in an ffmpeg.c instance separate from the one that has -re on it.
Last edited 6 months ago by Gregory Beauregard (previous) (diff)

comment:11 by Gregory Beauregard, 6 months ago

As for when the bug occurs, there's a few situations I know of that aren't obviously related except they all involve using -re:

  • the double -i input case reported by Gyan
  • every time a -ss seek is followed by a -re input (e.g. my sample from above) (I've not found any cases where this doesn't cause the freeze yet, but I thought I had some from the months prior when I discovered it that don't freeze. I'll upload a sample if I ever find one again.)
  • occasionally when I put a HDMV subtitle overlay on a video. I have a couple samples of this, but I'm not sure how easy it will be to cut down to upload as a sample. I'll do it later if needed.

I'm interested if anyone else can reproduce the -ss freeze because I haven't heard back on that yet.

Last edited 6 months ago by Gregory Beauregard (previous) (diff)

comment:12 by Gregory Beauregard, 6 months ago

Here's a reproducer that doesn't require a download of the "seek" kind:

Generate test input:

ffmpeg -report -f lavfi -i testsrc=duration=60:size=1920x1080:rate=30,format=yuv420p -f lavfi -i sine=frequency=440:duration=60:sample_rate=44100:b=4 -pix_fmt yuv420p -c:v libx264 -b:v 1000k -profile:v high -preset veryfast -c:a libopus -b:a 128k -y "freezeinput.mkv"

Encode that freezes:

ffmpeg -ss 00:00:30 -re -i freezeinput.mkv -c:v libx264 -preset superfast -b:v 500k -c:a copy -y initfreeze2.mkv

comment:13 by jeeb, 6 months ago

Looking at the rate emulation handling, adding some logging to one of the obvious places seems to show that the variables seem to be more or less initialized, but that this place only gets called once.

diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c
index 3ad11452da..7f7cb515e4 100644
--- a/fftools/ffmpeg.c
+++ b/fftools/ffmpeg.c
@@ -4221,8 +4221,13 @@ static int get_input_packet(InputFile *f, AVPacket **pkt)
             InputStream *ist = input_streams[f->ist_index + i];
             int64_t pts = av_rescale(ist->dts, 1000000, AV_TIME_BASE);
             int64_t now = av_gettime_relative() - ist->start;
-            if (pts > now)
+            if (pts > now) {
+                av_log(NULL, AV_LOG_VERBOSE,
+                       "Stream time: %"PRId64", ist->start: %"PRId64", "
+                       "relative time from start: %"PRId64"... Waiting\n",
+                       pts, ist->start, now);
                 return AVERROR(EAGAIN);
+            }
         }
     }
 

Output from a simplified command that reproduces the issue:

ffmpeg -v verbose -debug_ts -ss 00:00:01 -re -i ~/Videos/ffmpeg_trac_9160/initfreeze.mkv -c:v rawvideo -map 0:v -f null -

Thus stops at:

Stream time: 14000, ist->start: 269070008287, relative time from start: 9009... Waiting

Which means that:

  1. The values seem correct enough.
  2. get_input_packet returns AVERROR(EAGAIN) exactly once, and then seemingly no packets are read at all.

comment:14 by jeeb, 6 months ago

Alright, so I seem to have isolated where it goes loop-de-loop.

  1. transcode_step first of all does choose_output.
  2. Since the stream is not yet initialized, it gets returned.
  3. transcode_step only sleeps and resets the "I need to sleep now for a bit" flag thing if it did not receive any stream from choose_output.
  4. Thus, the thing doesn't progress.

I will have to see how this logic will look in the end, but for now a diff that seems to improve the situation:

--- a/fftools/ffmpeg.c
+++ b/fftools/ffmpeg.c
@@ -3957,8 +3957,10 @@ static OutputStream *choose_output(void)
                 "cur_dts is invalid st:%d (%d) [init:%d i_done:%d finish:%d] (this is harmless if it occurs once at the start per stream)\n",
                 ost->st->index, ost->st->id, ost->initialized, ost->inputs_done, ost->finished);
 
-        if (!ost->initialized && !ost->inputs_done)
-            return ost;
+        if (!ost->initialized && !ost->inputs_done) {
+            av_log(NULL, AV_LOG_VERBOSE, "Noope, not initialized yet!\n");
+            return ost->unavailable ? NULL : ost;
+        }
 
         if (!ost->finished && opts < opts_min) {
             opts_min = opts;

comment:15 by jeeb, 5 months ago

Analyzed by developer: set
Reproduced by developer: set
Resolution: fixed
Status: newclosed
Note: See TracTickets for help on using tickets.