[FFmpeg-trac] #9160(ffmpeg:new): ffmpeg stuck at initialization
FFmpeg
trac at avcodec.org
Sun Apr 11 22:38:44 EEST 2021
#9160: ffmpeg stuck at initialization
------------------------------------+----------------------------------
Reporter: Gyan | Owner:
Type: defect | Status: new
Priority: important | Component: ffmpeg
Version: git-master | Resolution:
Keywords: regression | Blocked By:
Blocking: | Reproduced by developer: 0
Analyzed by developer: 0 |
------------------------------------+----------------------------------
Comment (by JEEB):
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))
}}}
4. 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
}}}
5. 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
}}}
6. 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
}}}
7. 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
}}}
8. 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)
}}}
9. 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
}}}
10. 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
}}}
11. 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.
12. 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".
13. And finally, as you ctrl+C the process, the following things occur:
I. 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
}}}
II. 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
}}}
III. 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.
}}}
--
Ticket URL: <https://trac.ffmpeg.org/ticket/9160#comment:4>
FFmpeg <https://ffmpeg.org>
FFmpeg issue tracker
More information about the FFmpeg-trac
mailing list