Extremely long buffering when opening live video stream

[Fanfwe]

Hello,
I am working on a VLCKit based Apple TV app which opens a live video stream over HTTP (not HLS). I am however posting here in libVLC category as I don't think this is specifically about VLCKit but more related to libVLC, in fact.
In most cases, I start the app, it opens the HTTP stream, and few seconds later, playback starts and it just works as expected.
But there are also a few cases where I start the app, it opens the HTTP stream, but I get a black screen for over 30 seconds, and only then playback starts, but, as you can imagine, with a long delay compared to other players running on the same live stream.
Looking at wireshark capture during that time shows that there is indeed a TS stream being sent to the Player app during this time.
So it looks like for some reason, sometimes, VLC buffers for 30+ seconds the stream when opening it.

I have enabled verbose logs and when I can reproduce this behavior, it seems to be related to the fact that there is a TS discontinuity during the initial buffering phase :

Code: Select all

2020-11-19 11:49:41.907724+0100 Player[319:145826] Buffering 0% 2020-11-19 11:49:41.908088+0100 Player[319:145826] Buffering 3% 2020-11-19 11:49:41.908274+0100 Player[319:145826] Buffering 6% 2020-11-19 11:49:41.909091+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:49:41.909281+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:49:41.909451+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:49:41.994021+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:49:41.996595+0100 Player[319:145826] Buffering 9% 2020-11-19 11:49:41.998550+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:49:41.998930+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:49:42.003816+0100 Player[319:145826] libdvbpsi error (PSI decoder): TS discontinuity (received 1, expected 15) for PID 0 2020-11-19 11:49:42.004289+0100 Player[319:145826] PATCallBack called 2020-11-19 11:49:42.007757+0100 Player[319:145826] libdvbpsi error (PSI decoder): TS discontinuity (received 1, expected 15) for PID 1240 2020-11-19 11:49:42.008244+0100 Player[319:145826] PMTCallBack called for program 1 2020-11-19 11:49:42.008685+0100 Player[319:145826] Stream buffering done (37634 ms in 100 ms) 2020-11-19 11:49:42.009000+0100 Player[319:145826] 2020-11-19 11:49:42.010104+0100 Player[319:145826] buffer deadlock prevented 2020-11-19 11:49:42.010500+0100 Player[319:145826] Decoder wait done in 1 ms 2020-11-19 11:50:18.559569+0100 Player[319:145857] AAC channels: 2 samplerate: 48000 2020-11-19 11:50:18.560222+0100 Player[319:145857] restarting module due to input format change 2020-11-19 11:50:18.561117+0100 Player[319:145857] removing module "avcodec" 2020-11-19 11:50:18.561661+0100 Player[319:145857] looking for audio decoder module matching "any": 13 candidates 2020-11-19 11:50:18.562008+0100 Player[319:145857] using ffmpeg Lavc58.6.103 2020-11-19 11:50:18.562325+0100 Player[319:145857] option quiet does not exist 2020-11-19 11:50:18.562625+0100 Player[319:145857] CPU flags: 0x00000068 2020-11-19 11:50:18.564876+0100 Player[319:145857] codec (aac) started 2020-11-19 11:50:18.565258+0100 Player[319:145857] using audio decoder module "avcodec" 2020-11-19 11:50:18.566400+0100 Player[319:145857] creating audio output 2020-11-19 11:50:18.566875+0100 Player[319:145857] looking for audio output module matching "any": 3 candidates 2020-11-19 11:50:18.567448+0100 Player[319:145857] option audiounit_ios-gain does not exist 2020-11-19 11:50:18.567974+0100 Player[319:145857] using audio output module "audiounit_ios" 2020-11-19 11:50:18.569328+0100 Player[319:145857] VLC is looking for: 'f32l' 48000 Hz Stereo frame=1 samples/8 bytes 2020-11-19 11:50:18.590189+0100 Player[319:145856] Waiting for VPS/SPS/PPS 2020-11-19 11:50:18.599678+0100 Player[319:145857] Output on HDMI, channel count: 2

Looking at the logs above, we can see that it starts buffering, up to 9%, then gets a TS discontinuity, and then immediately declares that buffering is done, with some interesting timing values: 37634 ms in 100 ms. And looking at the logs timestamps, we can see that shortly after those messages, nothing happens for about 37 seconds, then logs start to appear again, and this is about when the playback actually starts, but it plays everything about 37 seconds "late", so VLC has been buffering everything during that time.

When I don't see the issue, in the logs I can see buffering going straight up to 100%, and the Stream buffering done message gives me time values that are more or less: (1000ms in 1000ms), and then playback starts right away.

I have not instantiated the VLCMediaPlayer with any options (other than "-vvv").

Can somebody enlighten me on why this is happening, and if there would be a way to avoid this huge buffering ?

Best regards

[InTheWings]

Stream buffering done (X ms in 100 ms)
TS sends PCR (clock) timing. There's a huge gap.

create a dump file from stream to reproduce

[Fanfwe]

Hello,
I don't think I can dump the stream from the app on Apple TV, but I made this tcpdump capture of the HTTP session, available here: http://dl.free.fr/vCApLr1Fx
Let me know if this works for you, or if I need to proceed in a different way for the dump.
Associated logs from libVLC are available here: https://pastiebin.com/5fbf7a56a31fe
This time it was a 44 seconds delay.

I had another VLC playing this same stream through another HTTP session that was open long before the session shown in this log, and there was no issue with the video on that other player while the other one was trying to open it.

[Fanfwe]

Hello,
I've been able to reproduce this once again, and this time I was capturing the stream with snaplen set to 0, which allowed me to properly reconstruct the TS dump from my pcap capture.

The TS dump is available here: http://dl.free.fr/iuJqWV4ng
The associated logs are visible here: https://pastebin.com/NkGEh8Qf

This time I got this message:
2020-11-30 09:52:51.957726+0100 Player[1870:1953895] Stream buffering done (45916 ms in 35 ms)
After that, nothing happens for about 45 seconds, and then playback starts but with a 45 seconds delay compared to another player that plays the same live stream in parallel, and that was started earlier (and which didn't show this issue when it got started).

Also, this time, there is no message about a TS discontinuity right before the Stream buffering done.

When trying to replay the dumped TS stream on a desktop VLC, it exhibits a similar behavior. No video is visible after starting playback, and for about 45 seconds, and then after, video plays fine.

Is there something wrong with the TS stream during those first 45 seconds ?

[InTheWings]

As expected, there's a 40s gap.


Core is waiting, as implicitly told.
Fix the source.

[baowuwolf]

I also encountered this problem, I found that libvlc 3.0.11 version does not have this problem, but the 3.0.12 and newer versions have this problem.
3.0.11 version play so fast with buffered 6 seconde,but 3.0.11 and newer versions buffer 30 seconds with the same play options.

[ssbmaccom]

What is the source of your MPEG TS stream?
I use TVVLCKit in a similar way with streams, gstreamer is forwarding from a DVB receiver and I haven't seen this huge delay (in local network). From instantiating the player instance to playback start there is a maximum of 3 to 4 seconds.

For dumping such a stream I simply used a brief python script that is actually dumping an HTTP connection into a file, which then simply is the "pure" MPEG TS stream. And I use the Python script mostly to construct the URL from info queried from the receiver - curl would work as well.