underruns ingesting hls stream with `input.ffmpeg`

[mcfiredrill]

Describe the bug I'm trying to input an HLS stream with input.ffmpeg and output another HLS stream. I plan on muxing audio etc later, this is just the simplest possible test case.

Even though the HLS input stream is running on my local machine, I'm still seeing constant underruns and the resulting stream playback is choppy.

To Reproduce

#!/usr/local/bin/liquidsoap
set("log.level",3)

s = input.ffmpeg(max_buffer=60.0, "http://localhost:8080/hls/datafruits.m3u8")

aac_lofi = %ffmpeg(format="mpegts",
    %audio(codec="aac", channels=2, ar=44100),
                    %video(
                      codec="libx264",
                      b="5M"
                    )
    )
aac_midfi = %ffmpeg(format="mpegts",
    %audio(codec="aac", channels=2, ar=44100, b="96k"),
                    %video(
                      codec="libx264",
                      b="5M"
                    )
    )
aac_hifi = %ffmpeg(format="mpegts",
    %audio(codec="aac", channels=2, ar=44100, b="192k"),
                    %video(
                      codec="libx264",
                      b="5M"
                    )
    )

streams = [("aac_lofi", aac_lofi ),
        ("aac_midfi", aac_midfi),
        ("aac_hifi", aac_hifi )]

def segment_name(~position, ~extname, stream_name) =
  timestamp = int_of_float(time())
  "#{stream_name}_#{timestamp}_#{position}.#{extname}"
end

output.file.hls(playlist = "live.m3u8",
  segment_duration = 2.,
  segments = 10,
  segments_overhead = 5,
  segment_name = segment_name,
  persist_at = "state.config",
  "/tmp/hls",
  streams,
  mksafe(s))

The input HLS stream is coming from an ngnix-rtmp server that I'm running locally in Docker. I'm streaming content to it with OBS locally.

Liquidsoap's HLS output is sent to /tmp/hls where I test it with ffplay -i live.m3u8. The resulting playback is smooth for a few seconds then becomes quite choppy.

You can also see constant underruns in the logs.

liquidsoap radio.liq                                                           
[libx264 @ 0x564568a07a40] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 BMI2 AVX2
[libx264 @ 0x564568a07a40] profile High, level 3.1, 4:2:0, 8-bit
[libx264 @ 0x564568d61f00] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 BMI2 AVX2
[libx264 @ 0x564568d61f00] profile High, level 3.1, 4:2:0, 8-bit
[libx264 @ 0x5645690653c0] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 BMI2 AVX2
[libx264 @ 0x5645690653c0] profile High, level 3.1, 4:2:0, 8-bit
2022/02/08 13:09:43 >>> LOG START                                                            
2022/02/08 13:09:41 [main:3] Liquidsoap 2.0.2                                                
2022/02/08 13:09:41 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.5.0 sedlex=2.5 menhirLib=20211128 curl=0.9.2 dtools=0.4.4 duppy=0.9.2 cry=0.6.6 mm=0.7.4 ogg=0.7.0 
ogg.decoder=0.7.0 vorbis=0.8.0 vorbis.decoder=0.8.0 mad=0.5.2 dynlink=[distributed with Ocaml] lame=0.3.5 gstreamer=0.3.1 ffmpeg=1.1.1 samplerate=0.1.6 taglib=0.3.8 camomile=1.0.2
2022/02/08 13:09:41 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.
2022/02/08 13:09:41 [gstreamer.loader:3] Loaded GStreamer 1.18.5 0
2022/02/08 13:09:41 [clock:3] Using builtin (low-precision) implementation for latency control
2022/02/08 13:09:43 [lang:2] WARNING: "set" is deprecated and will be removed in future version. Please use `settings.path.to.key.set(value)`
2022/02/08 13:09:43 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2022/02/08 13:09:43 [frame:3] Video frame size set to: 1280x720  
2022/02/08 13:09:43 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2022/02/08 13:09:43 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2022/02/08 13:09:43 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2022/02/08 13:09:43 [sandbox:3] Sandboxing disabled              
2022/02/08 13:09:43 [video.converter:3] Using preferred video converter: ffmpeg.
2022/02/08 13:09:43 [audio.converter:3] Using samplerate converter: ffmpeg.
2022/02/08 13:09:43 [clock.main:3] Streaming loop starts in auto-sync mode
2022/02/08 13:09:43 [clock.main:3] Delegating synchronisation to CPU clock
2022/02/08 13:09:43 [mksafe:3] Switch to safe_blank.
2022/02/08 13:09:43 [mksafe:3] Switch to input.ffmpeg_0 with transition.
[mpegts @ 0x564568a03880] Packets poorly interleaved, failed to avoid negative timestamp -5110 in stream 1.
Try -max_interleave_delta 0 as a possible workaround.                                                                                                                                      
[mpegts @ 0x564568d2a200] Packets poorly interleaved, failed to avoid negative timestamp -5110 in stream 1.                                                                                
Try -max_interleave_delta 0 as a possible workaround.                                                                                                                                      
[mpegts @ 0x56456902dc40] Packets poorly interleaved, failed to avoid negative timestamp -5110 in stream 1.                                                                                
Try -max_interleave_delta 0 as a possible workaround.                                                                                                                                      
[mpegts @ 0x564568a03880] Packets poorly interleaved, failed to avoid negative timestamp -1510 in stream 1.                                                                                
Try -max_interleave_delta 0 as a possible workaround.                                                                                                                                      
[mpegts @ 0x564568d2a200] Packets poorly interleaved, failed to avoid negative timestamp -1510 in stream 1.                                                                                
Try -max_interleave_delta 0 as a possible workaround.                                                                                                                                      
[mpegts @ 0x56456902dc40] Packets poorly interleaved, failed to avoid negative timestamp -1510 in stream 1.                                                                                
Try -max_interleave_delta 0 as a possible workaround.
2022/02/08 13:09:47 [clock.main:2] We must catchup 1.05 seconds!
2022/02/08 13:09:48 [clock.main:2] We must catchup 1.52 seconds!
2022/02/08 13:09:49 [clock.main:2] We must catchup 2.00 seconds!
2022/02/08 13:09:50 [clock.main:2] We must catchup 2.61 seconds!
2022/02/08 13:09:51 [clock.main:2] We must catchup 3.44 seconds!
2022/02/08 13:09:52 [clock.main:2] We must catchup 4.26 seconds!
2022/02/08 13:09:54 [clock.main:2] We must catchup 5.01 seconds!
2022/02/08 13:09:55 [clock.main:2] We must catchup 5.82 seconds!
2022/02/08 13:09:56 [clock.main:2] We must catchup 6.65 seconds!
2022/02/08 13:09:57 [clock.main:2] We must catchup 7.42 seconds!
2022/02/08 13:09:58 [clock.main:2] We must catchup 8.36 seconds!
2022/02/08 13:09:59 [clock.main:2] We must catchup 9.16 seconds!
2022/02/08 13:10:01 [clock.main:2] We must catchup 9.72 seconds!
2022/02/08 13:10:02 [clock.main:2] We must catchup 10.47 seconds!
2022/02/08 13:10:03 [clock.main:2] We must catchup 11.13 seconds!
2022/02/08 13:10:04 [clock.main:2] We must catchup 11.73 seconds!
2022/02/08 13:10:05 [clock.main:2] We must catchup 12.28 seconds!
2022/02/08 13:10:06 [clock.main:2] We must catchup 12.82 seconds!
2022/02/08 13:10:07 [clock.main:2] We must catchup 13.44 seconds!
2022/02/08 13:10:08 [clock.main:2] We must catchup 14.07 seconds!
2022/02/08 13:10:09 [clock.main:2] We must catchup 14.82 seconds!
2022/02/08 13:10:10 [clock.main:2] We must catchup 15.55 seconds!
2022/02/08 13:10:11 [clock.main:2] We must catchup 15.93 seconds!
2022/02/08 13:10:12 [clock.main:2] We must catchup 16.52 seconds!
2022/02/08 13:10:13 [clock.main:2] We must catchup 17.03 seconds!

Expected behavior Since the input HLS stream is all coming from the same machine, I wouldn't expect any underruns to occur. I'd expect smooth playback just like if I do ffplay -i http://localhost:8080/hls/datafruits.m3u8.

Version details

• OS:arch linux
• Version 2.0.2

Install method opam install gavl ffmpeg taglib mad lame ogg vorbis cry samplerate ocurl liquidsoap -y

[mcfiredrill]

Recorded a short video just now , maybe this helps?

https://user-images.githubusercontent.com/66243/153077843-4841766e-4302-4f75-a41e-f265816fba74.mp4

At the end I said "maybe input.ffmpeg is too slow" but who knows, could be issue with my nginx-rtmp config or output.file.hls settings... Thanks as always for making liquidsoap!

[mcfiredrill]

I'm thinking this issue has to do with ffmpeg, or perhaps the output.file.hls settings I have here.

I get the same results (lots of underruns) using a single video single('single.mp4').

I can create a very stable stream using testsrc. s = mux_audio(video.testsrc(), audio=noise())

[toots]

Thanks for reporting this one. I've had similar issues, will investigate.

[toots]

Pretty sure it's coming from input.ffmpeg, I've had the same issue just doing input.ffmpeg to a sound card output.

[toots]

So, a little investigation reveals what's going on here I believe.

You can set settings.ffmpeg.log.verbosity.set("info") in the script to see more details.

First, I tested with https://stream.radiofrance.fr/fip/fip.m3u8, which is a top-level m3u8 playlist. With this one, it was clear that input.ffmpeg was lagging each time ffmpeg was reloading the playlist to fetch the next segments leading to hicups in the playback.

Then, using https://stream.radiofrance.fr/fip/fip_hifi.m3u8, which points to a specific sub-stream of the top-level playlist. With this, the input was processing the new segments fast enough and no hicups were observed.

Next, I tested with https://stream.radiofrance.fr/fip/fip.m3u8 but this time, wrapping the input.ffmpeg into a buffer to force it into its own clock and this seemed to also remove the hicups.

What this points out to is that the ffmpeg hls demuxer is not processing new segments fast enough when using a full hls playlist with all streams. Also, for some reason, our current use of its API returns the lowest quality stream when using the top-level playlist. We'll have to investigate wether this is an issue on our side or on the ffmpeg side.

I'd suggest to either or both:

• Points directly to the specific sub-stream you want to be using.
• Wrap the input in a buffer.

Let us know if that helps!

[toots]

I've been meaning to test this again after the recent optimizations pushed to v2.0.4-preview and I'm happy to report that this isn't happening again. Seems like the optimizations also took care of whatever was dragging the ffmpeg processing!