ffmpeg-git: Slow Start Transcode vs ffmpeg-2.8.7: Fast Start Transcode

[barhom]

The Problem:

In ffmpeg 2.8.7 we have noticed that there are a couple of videos that start up really quickly whilst when we tried 3.0.2, 3.1.2 and git the startup time for the transcode is incredibly slow.

Try the command below to understand the issue in ffmpeg 2.8.7 and >3.0.2 or git.

This command:

ffmpeg -analyzeduration 1000000 -i http://www.netsat.se/channel.ts \
-map 0:0 -map 0:1 -c:v libx264 -preset superfast -g 25 -b:v 900k \
-maxrate 900k -bufsize 2000k -filter:v yadif -c:a libfdk_aac -b:a 64k \
-f mpegts -metadata chan_id=300 -metadata timeshift=0 \
"udp://239.240.127.64:3301?buffer_size=1316&pkt_size=1316" -loglevel 48

In FFmpeg-git this transcode-command starts in about 5 seconds.
In FFmpeg-2.8.7 this transcode-command starts in about 1 second.

Logs:

ffmpeg-git (5s start time because of all the "probing stream 1 pp:")

ffmpeg -analyzeduration 1000000 -i http://www.netsat.se/channel.ts -map 0:0 -map 0:1 -c:v libx264 -preset superfast -g 25 -b:v 900k -maxrate 900k -bufsize 2000k -filter:v yadif -c:a libfdk_aac -b:a 64k -f mpegts -metadata chan_id=300 -metadata timeshift=0 "udp://239.240.127.64:3301?buffer_size=1316&pkt_size=1316" -loglevel 48
ffmpeg version N-80789-gc5566f0 Copyright (c) 2000-2016 the FFmpeg developers
  built with gcc 4.9.2 (Debian 4.9.2-10)
  configuration: --prefix=/home/company/company_packages/ffmpeg_build --pkg-config-flags=--static --extra-cflags=-I/home/company/company_packages/ffmpeg_build/include --extra-ldflags=-L/home/company/company_packages/ffmpeg_build/lib --bindir=/home/company/company_packages/bin --enable-gpl --enable-libass --enable-libfdk-aac --enable-libfreetype --enable-libmp3lame --enable-libtheora --enable-libvorbis --enable-libx264 --enable-libx265 --enable-nonfree --enable-libzvbi
  libavutil      55. 27.100 / 55. 27.100
  libavcodec     57. 48.101 / 57. 48.101
  libavformat    57. 40.101 / 57. 40.101
  libavdevice    57.  0.102 / 57.  0.102
  libavfilter     6. 46.102 /  6. 46.102
  libswscale      4.  1.100 /  4.  1.100
  libswresample   2.  1.100 /  2.  1.100
  libpostproc    54.  0.100 / 54.  0.100
Splitting the commandline.
Reading option '-analyzeduration' ... matched as AVOption 'analyzeduration' with argument '1000000'.
Reading option '-i' ... matched as input file with argument 'http://www.netsat.se/channel.ts'.
Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:0'.
Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:1'.
Reading option '-c:v' ... matched as option 'c' (codec name) with argument 'libx264'.
Reading option '-preset' ... matched as AVOption 'preset' with argument 'superfast'.
Reading option '-g' ... matched as AVOption 'g' with argument '25'.
Reading option '-b:v' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '900k'.
Reading option '-maxrate' ... matched as AVOption 'maxrate' with argument '900k'.
Reading option '-bufsize' ... matched as AVOption 'bufsize' with argument '2000k'.
Reading option '-filter:v' ... matched as option 'filter' (set stream filtergraph) with argument 'yadif'.
Reading option '-c:a' ... matched as option 'c' (codec name) with argument 'libfdk_aac'.
Reading option '-b:a' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '64k'.
Reading option '-f' ... matched as option 'f' (force format) with argument 'mpegts'.
Reading option '-metadata' ... matched as option 'metadata' (add metadata) with argument 'chan_id=300'.
Reading option '-metadata' ... matched as option 'metadata' (add metadata) with argument 'timeshift=0'.
Reading option 'udp://239.240.127.64:3301?buffer_size=1316&pkt_size=1316' ... matched as output file.
Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument '48'.
Finished splitting the commandline.
Parsing a group of options: global .
Applying option loglevel (set logging level) with argument 48.
Successfully parsed a group of options.
Parsing a group of options: input file http://www.netsat.se/channel.ts.
Successfully parsed a group of options.
Opening an input file: http://www.netsat.se/channel.ts.
[http @ 0x3f2ce60] Setting default whitelist 'http,https,tls,rtp,tcp,udp,crypto,httpproxy'
[http @ 0x3f2ce60] request: GET /channel.ts HTTP/1.1
User-Agent: Lavf/57.40.101
Accept: */*
Range: bytes=0-
Connection: close
Host: www.netsat.se
Icy-MetaData: 1


[mpegts @ 0x3f2c7a0] Format mpegts probed with size=2048 and score=50
[mpegts @ 0x3f2c7a0] stream=0 stream_type=2 pid=83f prog_reg_desc=
[mpegts @ 0x3f2c7a0] stream=1 stream_type=4 pid=8a3 prog_reg_desc=
[mpegts @ 0x3f2c7a0] Before avformat_find_stream_info() pos: 0 bytes read:49026 seeks:0 nb_streams:2
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2500
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2499
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2498
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2497
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2496
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2495
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2494
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2493
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2492
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2491
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2490
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2489
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2488
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2487
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2486
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2485
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2484
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2483
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2482
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2481
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2480
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2479
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2478
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2477
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2476
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2475
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2474
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2473
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2472
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2471
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2470
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2469
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2468
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2467
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2466
[mpegts @ 0x3f2c7a0] probing stream 1 pp:2465
[mpegts @ 0x3f2c7a0] Probe with size=102480, packets=2500 detected mp3 with score=50
[mpegts @ 0x3f2c7a0] probed stream 1
[mp2 @ 0x3f3d9e0] Header missing
[mpegts @ 0x3f2c7a0] max_analyze_duration 1000000 reached at 1008000 microseconds st:1
[mpegts @ 0x3f2c7a0] After avformat_find_stream_info() pos: 2787288 bytes read:2789244 seeks:0 frames:67
Input #0, mpegts, from 'http://www.netsat.se/channel.ts':
  Duration: N/A, start: 22346.331678, bitrate: N/A
  Program 1811
    Metadata:
      service_name    : Syrian Drama TV
      service_provider: JMC
    Stream #0:0[0x83f], 23, 1/90000: Video: mpeg2video (Main), 1 reference frame ([2][0][0][0] / 0x0002), yuv420p(tv, left), 720x576 [SAR 16:15 DAR 4:3], 0/1, 25 fps, 25 tbr, 90k tbn, 50 tbc
    Stream #0:1[0x8a3](ara), 44, 1/90000: Audio: mp2 ([4][0][0][0] / 0x0004), 48000 Hz, stereo, s16p, 160 kb/s

vs

ffmpeg-2.8.7 (1s start time - I dont see any "probing stream 1 pp:")

ffmpeg -analyzeduration 1000000 -i http://www.netsat.se/channel.ts -map 0:0 -map 0:1 -c:v libx264 -preset superfast -g 25 -b:v 900k -maxrate 900k -bufsize 2000k -filter:v yadif -c:a libfdk_aac -b:a 64k -f mpegts -metadata chan_id=300 -metadata timeshift=0 "udp://239.240.127.64:3301?buffer_size=1316&pkt_size=1316" -loglevel 48
ffmpeg version 2.8.7 Copyright (c) 2000-2016 the FFmpeg developers
  built with gcc 4.9.2 (Debian 4.9.2-10)
  configuration: --prefix=/home/company/company_packages/ffmpeg_build --pkg-config-flags=--static --extra-cflags=-I/home/company/company_packages/ffmpeg_build/include --extra-ldflags=-L/home/company/company_packages/ffmpeg_build/lib --bindir=/home/company/company_packages/bin --enable-gpl --enable-libass --enable-libfdk-aac --enable-libfreetype --enable-libmp3lame --enable-libtheora --enable-libvorbis --enable-libx264 --enable-libx265 --enable-nonfree --enable-libzvbi
  libavutil      54. 31.100 / 54. 31.100
  libavcodec     56. 60.100 / 56. 60.100
  libavformat    56. 40.101 / 56. 40.101
  libavdevice    56.  4.100 / 56.  4.100
  libavfilter     5. 40.101 /  5. 40.101
  libswscale      3.  1.101 /  3.  1.101
  libswresample   1.  2.101 /  1.  2.101
  libpostproc    53.  3.100 / 53.  3.100
Splitting the commandline.
Reading option '-analyzeduration' ... matched as AVOption 'analyzeduration' with argument '1000000'.
Reading option '-i' ... matched as input file with argument 'http://www.netsat.se/channel.ts'.
Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:0'.
Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:1'.
Reading option '-c:v' ... matched as option 'c' (codec name) with argument 'libx264'.
Reading option '-preset' ... matched as AVOption 'preset' with argument 'superfast'.
Reading option '-g' ... matched as AVOption 'g' with argument '25'.
Reading option '-b:v' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '900k'.
Reading option '-maxrate' ... matched as AVOption 'maxrate' with argument '900k'.
Reading option '-bufsize' ... matched as AVOption 'bufsize' with argument '2000k'.
Reading option '-filter:v' ... matched as option 'filter' (set stream filtergraph) with argument 'yadif'.
Reading option '-c:a' ... matched as option 'c' (codec name) with argument 'libfdk_aac'.
Reading option '-b:a' ... matched as option 'b' (video bitrate (please use -b:v)) with argument '64k'.
Reading option '-f' ... matched as option 'f' (force format) with argument 'mpegts'.
Reading option '-metadata' ... matched as option 'metadata' (add metadata) with argument 'chan_id=300'.
Reading option '-metadata' ... matched as option 'metadata' (add metadata) with argument 'timeshift=0'.
Reading option 'udp://239.240.127.64:3301?buffer_size=1316&pkt_size=1316' ... matched as output file.
Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument '48'.
Finished splitting the commandline.
Parsing a group of options: global .
Applying option loglevel (set logging level) with argument 48.
Successfully parsed a group of options.
Parsing a group of options: input file http://www.netsat.se/channel.ts.
Successfully parsed a group of options.
Opening an input file: http://www.netsat.se/channel.ts.
[http @ 0x3fcd0e0] request: GET /channel.ts HTTP/1.1
User-Agent: Lavf/56.40.101
Accept: */*
Range: bytes=0-
Connection: close
Host: www.netsat.se
Icy-MetaData: 1


[mpegts @ 0x3fcc7a0] Format mpegts probed with size=2048 and score=100
[mpegts @ 0x3fcc7a0] stream=0 stream_type=2 pid=83f prog_reg_desc=
[mpegts @ 0x3fcc7a0] stream=1 stream_type=4 pid=8a3 prog_reg_desc=
[mpegts @ 0x3fcc7a0] Before avformat_find_stream_info() pos: 0 bytes read:109508 seeks:0
[mp3 @ 0x3fdcb40] Header missing
[mpegts @ 0x3fcc7a0] max_analyze_duration 1000000 reached at 1008000 microseconds st:1
[mpegts @ 0x3fcc7a0] After avformat_find_stream_info() pos: 692404 bytes read:696186 seeks:0 frames:67
Input #0, mpegts, from 'http://www.netsat.se/channel.ts':
  Duration: N/A, start: 22572.219678, bitrate: N/A
  Program 1811
    Metadata:
      service_name    : Syrian Drama TV
      service_provider: JMC
    Stream #0:0[0x83f], 23, 1/90000: Video: mpeg2video (Main), 1 reference frame ([2][0][0][0] / 0x0002), yuv420p(tv, left), 720x576 [SAR 16:15 DAR 4:3], 1/50, max. 15000 kb/s, 25 fps, 25 tbr, 90k tbn, 50 tbc
    Stream #0:1[0x8a3](ara), 44, 1/90000: Audio: mp2 ([4][0][0][0] / 0x0004), 48000 Hz, stereo, s16p, 160 kb/s

(Side note: I know the logs above show ffmpeg "N-80789-gc5566f0" which is not latest git - but I have tried this on latest git as well so we know the issue is there)

Does anyone know why this command is slow-starting in ffmpeg newer than 2.8.7 ?

Thanks

[Carl Eugen Hoyos]

Which commit introduced the issue you see?

[barhom]

Replying to cehoyos:

Which commit introduced the issue you see?

I am not sure, it must be somewhere between 2.8.7 (Feynman) and 3.0.2 (Einstein).
I can try to hunt it down.

[barhom]

I have found the regression.
It was introduced by the following commit:

​https://github.com/FFmpeg/FFmpeg/commit/4bec36f98c5150b09d45740f3e1c80526e85b676

Removing the lines

    if (pes->stream_type == 4)
         st->request_probe = 50;

from master fixes the problem I have with slow-starting transcodes. I suggest that if ffmpeg wants an extra probe for stream_type == 4 then it should make it optional somehow.

[Michael Niedermayer]

Fixed in c75273310cf1becffee79bab0e2bba0b1606afb7