Opened 3 years ago
Closed 3 years 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:2 by , 3 years 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 , 3 years 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 , 3 years ago
Ran Gyan's test case with -v verbose and -debug_ts added. Now we can go through the steps that happen:
- 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 - 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
- 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))
- 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
- 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
- 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
- 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
- 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)
- 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
- 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
- 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.
- 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".
- And finally, as you ctrl+C the process, the following things occur:
- 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
- The decoder is flushed, we receive one frame from each video decoder (or at least that is what's logged).
- 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 - 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 , 3 years 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 , 3 years 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 , 3 years 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 , 3 years 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 , 3 years 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 , 3 years 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.
comment:11 by , 3 years 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.
comment:12 by , 3 years 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 , 3 years 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:
- The values seem correct enough.
- get_input_packet returns AVERROR(EAGAIN) exactly once, and then seemingly no packets are read at all.
comment:14 by , 3 years ago
Alright, so I seem to have isolated where it goes loop-de-loop.
transcode_stepfirst of all doeschoose_output.- Since the stream is not yet initialized, it gets returned.
transcode_steponly sleeps and resets the "I need to sleep now for a bit" flag thing if it did not receive any stream fromchoose_output.- 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 , 3 years ago
| Analyzed by developer: | set |
|---|---|
| Reproduced by developer: | set |
| Resolution: | → fixed |
| Status: | new → closed |
Should now be fixed by:
- ec20b8130269260f3ae1e4642da26ba556814f84 in master
- 70405dd7e31cd436e9ffa252124537df253a5dc3 in release/4.4
Note:
See TracTickets
for help on using tickets.
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.