#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 _______________________________________________ FFmpeg-trac mailing list FFmpeg-trac@avcodec.org https://ffmpeg.org/mailman/listinfo/ffmpeg-trac To unsubscribe, visit link above, or email ffmpeg-trac-requ...@ffmpeg.org with subject "unsubscribe".