libVLC slow start to UDP streams on first boot (Windows)

[jonwat]

Hi,

I'm using libVLC to playback a number of UDP streams and in general have had no issue (1-2 seconds to change between streams and all very stable).

When the machine boots from fresh, the first time I try to stream a channel it can take anywhere from 15 seconds to 1-2 minutes to start the stream, thereafter everything is fine and it reverts to 1-2 seconds to switch between streams. If I boot from fresh and run VLC (v2.04) instead of my application it can start any of the streams within 3 seconds.

I have completely disabled all firewalls and anti-virus at a service level. I have also read some other forum posts about an issue with cold plugin caches and slow start-up in VLC. I don't think it is anything to do with this as If I delete the plugins cache then I get a slow down around my call to initialiseVLC however if I leave the plugins cache alone it passes through this part of the code nice and quickly.

I have also tried switching from UDP streams to RTP (no change) and experimenting with the UDP Caching and Network Caching values (again no change and I'm fairly sure the defaults are fine for my setup). Also as far as I can see from a network level it does seem like the IGMP join is getting sent OK.

I have hooked onto the libVLC events in my debug code. You can see around a 55 sec delay in the stream starting below. The gap is always between that first libvlc_MediaPlayerBuffering, presumably when it is pre-buffering and the libvlc_MediaPlayerPlaying event. When it works quickly for each subsequent stream, the gap between those messages is usually an absolute maximum of 1 or 2 seconds.

18/01/2013 22:00:00 libvlc_MediaPlayerOpening
18/01/2013 22:00:00 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerPlaying
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering
18/01/2013 22:00:55 libvlc_MediaPlayerBuffering

I'd be surprised if it is a network issue as VLC can tune the stream every time on first boot without any problems. Could there be any other parameters I might need to specify to libVLC or anywhere else I could start to look for the problem?

I am using the libVLC DLL's from v2.04 but have also tested v2.05 (no difference).

Any pointers greatly appreciated.

Thanks,

Jon.

[Rémi Denis-Courmont]

It looks like you are starting the stream before the network card is initialized.

[jonwat]

Thanks for the quick reply.

I assume the network card must be initialised because I have tried using VNC (so I know it is definitely on the network) to connect to the machine and still the same behaviour, VLC works first time but libVLC gets this delay. Note this behaviour still happens even if I leave the machine 20-30 minutes after rebooting it. It seems like VLC is doing something that doesn't happen when I embed libVLC.

Any further pointers on how I might go about continuing to debug this? Thanks.

[joseAndresGomezTovar]

Did you try with VLC v2.0.5 directly?
Did you analyze the network with wireshark?

I suppose that the problem is in the network connection

[jonwat]

Yes both VLC v2.0.4 and VLC v2.0.5 work directly.

I have analysed the network with Wireshark and the strange thing is the trace shows the same thing for VLC (working) and libVLC (where there is a long delay on the first stream after reboot). That is an IGMPv2 Membership Report followed straightaway by lots of UDP packets. In both cases I receive the Program Management Table within a few hundred milliseconds. Only with libVLC the stream takes at least 15 seconds to start and often over 1 minute and with VLC (either 2.0.4 or 2.0.5) it starts within around 5 seconds maximum. I have re-run the tests numerous times and the results are the same.

It does initially seem like a network problem. however if that was the case I would expect the same behaviour from both VLC and libVLC.

Are there any settings in libVLC that could help?

[Jean-Baptiste Kempf]

You should compare the -vvv logs between the two cases.

[jonwat]

Thanks. I've done that with v2.0.5 and my program linked with the .lib and .dll's from v2.0.5.

I ran a few tests (restarting the machine in between) and saw this take as little as 2-3 seconds to start using libVLC right up to 62 seconds. So it works intermittently on first boot, thereafter once a stream has been started it is quick for any other stream you switch to. This would not normally be a problem but the machine often gets restarted for other good reasons. As I say VLC v2.0.5 works quickly every time in the same conditions on the same machine, it never has this intermittent slow down.

The trace below is from the example that took 62 seconds. If I'm reading the logs right it is stuck for around 44 seconds pre-buffering and waiting for the PMT. However if I run Wireshark I see that in every case the IGMP membership report is sent followed by the UDP traffic and a PMT very shortly after (total of 2-3 seconds), however libVLC does not always seem to receive or process this.

The thing I don't understand is if it is a network issue why does Wireshark always show the IGMP join being promptly sent and the UDP traffic being received straight after. Is there something I have missed in the logs below (I have the full logs if need be from all the tests)?

I'm using URL udp://@225.1.1.133:1234, I've edited some of the addresses in the logs so I could post them.

-- logger module started --
main debug: using interface module "logger"
main debug: TIMER module_need() : 114.738 ms - Total 114.738 ms / 1 intvls (Avg 114.738 ms)
main debug: Creating an input for 'udp:1.1.133:1234'
main debug: using timeshift granularity of 50 MiB, in path 'C:\Users\***AppData\Local\Temp'
main debug: `@1.1.133:1234' gives access `udp' demux `' path `@1.1.133:1234'
main debug: creating demux: access='udp' demux='' location='@1.1.133:1234' file='\\@1.1.133:1234'
main debug: looking for access_demux module: 0 candidates
main debug: no access_demux module matched "udp"
main debug: TIMER module_need() : 9.694 ms - Total 9.694 ms / 1 intvls (Avg 9.694 ms)
main debug: creating access 'udp' location='@1.1.133:1234', path='\\@1.1.133:1234'
main debug: looking for access module: 1 candidate
access_udp debug: opening server=:0 local=1.1.133:1234
main debug: net: opening 1.1.133 datagram port 1234
main debug: using access module "access_udp"
main debug: TIMER module_need() : 52.685 ms - Total 52.685 ms / 1 intvls (Avg 52.685 ms)
main debug: Using block method for AStream*
main debug: starting pre-buffering
main debug: received first data after 16576 ms
main debug: prebuffering done 1316 bytes in 16s - 0 KiB/s
main debug: looking for stream_filter module: 4 candidates
main debug: no stream_filter module matching "any" could be loaded
main debug: TIMER module_need() : 126.625 ms - Total 126.625 ms / 1 intvls (Avg 126.625 ms)
main debug: looking for stream_filter module: 1 candidate
main debug: using stream_filter module "stream_filter_record"
main debug: TIMER module_need() : 10.797 ms - Total 10.797 ms / 1 intvls (Avg 10.797 ms)
main debug: creating demux: access='udp' demux='' location='@1.1.133:1234' file='\\@1.1.133:1234'
main debug: looking for demux module: 55 candidates
ts debug: pid[1001] unknown
ts debug: pid[1004] unknown
ts debug: pid[1003] unknown
ts debug: PATCallBack called
ts debug: new PAT ts_id=1 version=25 current_next=1
ts debug: * number=0 pid=16
ts debug: * number=100 pid=1000
ts debug: pid[1002] unknown
ts debug: PMTCallBack called
ts debug: new PMT program number=100 version=13 pid_pcr=1001
ts debug: * es pid=1001 type=27 dr->i_tag=0x11
ts debug: * es pid=1001 type=27 fcc=h264
main debug: selecting program id=100
ts debug: * es pid=1002 type=3 dr->i_tag=0xa
ts debug: found language: hun
ts debug: * es pid=1002 type=3 fcc=mpga
ts debug: * es pid=1004 type=6 dr->i_tag=0xa
ts debug: * es pid=1004 type=6 dr->i_tag=0x5
ts debug: * es pid=1004 type=6 dr->i_tag=0x6a
ts debug: found language: hun
ts debug: * es pid=1004 type=6 fcc=a52
ts debug: * es pid=1003 type=6 dr->i_tag=0x56
ts debug: * es pid=1003 type=6 dr->i_tag=0x45
ts debug: * es pid=1003 type=6 dr->i_tag=0x56
ts debug: * ttxt type=Teletext lan=hun page=100
ts debug: * es pid=1003 type=6 fcc=telx
access_udp warning: unimplemented query in control
main debug: using demux module "ts"
main debug: TIMER module_need() : 44005.151 ms - Total 44005.151 ms / 1 intvls (Avg 44005.149 ms)

The similar section from the VLC test is:

main debug: adding item `1.1.133:1234' ( @1.1.133:1234 )
qt4 debug: Adding a new MRL to recent ones: @1.1.133:1234
main debug: rebuilding array of current - root Playlist
main debug: rebuild done - 1 items, index -1
main debug: processing request item: 1.1.133:1234, node: null, skip: 0
main debug: resyncing on 1.1.133:1234
main debug: 1.1.133:1234 is at 0
main debug: starting playback of the new playlist item
main debug: resyncing on 1.1.133:1234
main debug: 1.1.133:1234 is at 0
main debug: creating new input thread
main debug: Creating an input for '1.1.133:1234'
main debug: using timeshift granularity of 50 MiB, in path 'C:\Users\***\AppData\Local\Temp'
main debug: `@1.1.133:1234' gives access `udp' demux `' path `1.1.133:1234'
main debug: creating demux: access='udp' demux='' location='@225.1.1.133:1234' file='\\@1.1.133:1234'
main debug: looking for access_demux module: 0 candidates
main debug: no access_demux module matched "udp"
main debug: TIMER module_need() : 0.306 ms - Total 0.306 ms / 1 intvls (Avg 0.306 ms)
main debug: creating access 'udp' location='@1.1.133:1234', path='\\@1.1.133:1234'
main debug: looking for access module: 1 candidate
main debug: meta ok for (null), need to fetch art
main debug: looking for meta fetcher module: 1 candidate
lua debug: Trying Lua scripts in C:\Users\***\AppData\Roaming\vlc\lua\meta\fetcher
lua debug: Trying Lua scripts in C:\Program Files (x86)\VideoLAN\VLC\lua\meta\fetcher
qt4 debug: IM: Setting an input
lua debug: Trying Lua playlist script C:\Program Files (x86)\VideoLAN\VLC\lua\meta\fetcher\tvrage.luac
access_udp debug: opening server=:0 local=1.1.133:1234
main debug: net: opening 1.1.133 datagram port 1234
main debug: using access module "access_udp"
main debug: TIMER module_need() : 101.606 ms - Total 101.606 ms / 1 intvls (Avg 101.606 ms)
main debug: Using block method for AStream*
main debug: starting pre-buffering
main debug: using meta fetcher module "lua"
main debug: TIMER module_need() : 130.399 ms - Total 130.399 ms / 1 intvls (Avg 130.399 ms)
main debug: removing module "lua"
main debug: searching art for 1.1.133:1234
main debug: looking for art finder module: 2 candidates
main debug: received first data after 109 ms
main debug: prebuffering done 1316 bytes in 0s - 11 KiB/s
main debug: looking for stream_filter module: 4 candidates
main debug: no stream_filter module matching "any" could be loaded
main debug: TIMER module_need() : 0.318 ms - Total 0.318 ms / 1 intvls (Avg 0.318 ms)
main debug: looking for stream_filter module: 1 candidate
main debug: using stream_filter module "stream_filter_record"
main debug: TIMER module_need() : 0.214 ms - Total 0.214 ms / 1 intvls (Avg 0.214 ms)
main debug: creating demux: access='udp' demux='' location='@1.1.133:1234' file='\\1.1.133:1234'
main debug: looking for demux module: 55 candidates
lua debug: Trying Lua scripts in C:\Users\***\AppData\Roaming\vlc\lua\meta\art
lua debug: Trying Lua scripts in C:\Program Files (x86)\VideoLAN\VLC\lua\meta\art
lua debug: Trying Lua playlist script C:\Program Files (x86)\VideoLAN\VLC\lua\meta\art\00_musicbrainz.luac
lua debug: Trying Lua playlist script C:\Program Files (x86)\VideoLAN\VLC\lua\meta\art\01_googleimage.luac
lua debug: Trying Lua playlist script C:\Program Files (x86)\VideoLAN\VLC\lua\meta\art\02_frenchtv.luac
lua debug: Trying Lua playlist script C:\Program Files (x86)\VideoLAN\VLC\lua\meta\art\03_lastfm.luac
main debug: no art finder module matching "any" could be loaded
main debug: TIMER module_need() : 291.044 ms - Total 291.044 ms / 1 intvls (Avg 291.044 ms)
main debug: art not found for 1.1.133:1234
ts debug: pid[1001] unknown
ts debug: pid[1004] unknown
ts debug: pid[1003] unknown
ts debug: pid[1002] unknown
ts debug: PATCallBack called
ts debug: new PAT ts_id=1 version=25 current_next=1
ts debug: * number=0 pid=16
ts debug: * number=100 pid=1000
ts debug: PMTCallBack called
ts debug: new PMT program number=100 version=13 pid_pcr=1001
ts debug: * es pid=1001 type=27 dr->i_tag=0x11
ts debug: * es pid=1001 type=27 fcc=h264
main debug: selecting program id=100
ts debug: * es pid=1002 type=3 dr->i_tag=0xa
ts debug: found language: hun
ts debug: * es pid=1002 type=3 fcc=mpga
ts debug: * es pid=1004 type=6 dr->i_tag=0xa
ts debug: * es pid=1004 type=6 dr->i_tag=0x5
ts debug: * es pid=1004 type=6 dr->i_tag=0x6a
ts debug: found language: hun
ts debug: * es pid=1004 type=6 fcc=a52
ts debug: * es pid=1003 type=6 dr->i_tag=0x56
ts debug: * es pid=1003 type=6 dr->i_tag=0x45
ts debug: * es pid=1003 type=6 dr->i_tag=0x56
ts debug: * ttxt type=Teletext lan=hun page=100
ts debug: * es pid=1003 type=6 fcc=telx
access_udp warning: unimplemented query in control
main debug: using demux module "ts"
main debug: TIMER module_need() : 1284.306 ms - Total 1284.306 ms / 1 intvls (Avg 1284.306 ms)

[mikhalch]

Jon,
have been able to get to the bottom of this (or figure out a work-around)?
I've been dealing with a similar issue where libvlc would continuously keep buffering files on a NAS.
Standalone VLC wold play the same files just fine, no stuttering..
I've tried different version and various config settings w/out any effect..

Thanks,
Andrey