[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