VLC Playback Very Slow to Start

[ExaltedVanguard]

Fresh install of VLC 2.2.4

My media files are held on a USB HDD connected to my router (Archer c7), which hosts the files on a SMB/CIFS share as well as on a private ftp server. My network also contains a raspberry pi (running ubuntu server), which I'm using to host an openvpn server that's bridged to my ethernet. These clients are managed by DHCP from the router and simply seen as other computers on the network.

I will be referring to clients that are physically part of the network (like my desktop or laptop at home) as on-site clients. Clients connected via openvpn and bridged in (like my laptop while I'm at a hotel) will be referred to as off-site clients.

The purpose of this setup is to allow me to connect via vpn and let me access my smb share/ftp as an off-site client. Then I can watch my home movies from anywhere in the world without having to lug around the hard drive containing them or worrying about copying them to my laptop ahead of time.

All on-site clients are able to access and play files via both SMB and ftp. Everything works as perfectly. Double-click and file and it plays.

Off-site clients are able to access and play files via ftp and everything works as expected. SMB is not working well. After double-clicking a file VLC will open and the file name will populate in the title bar, but no playback will occur (screen is blank) for a lengthy period of time (1-3 minutes). After this waiting period, the video will start playback normally. Things behave as expected, just with a very long, annoying delay.

This is clearly not an issue with the files themselves, since there's no problems while I'm on-site.

My first thought was that it was a bandwidth issue (especially since I've been testing this using my phone as a wifi hotspot). This doesn't appear to be the case, since accessing the files using FTP works flawlessly, and after the delay on SMB, playback will continue normally without freezing. In fact, opening windows performance monitor shows that practically no data is being transferred during the pause (like 10Kb/s). This drastically increases when playback starts, of course.

So my next thought was that perhaps there's some issue with the vpn'ed SMB connection. That doesn't seem to be the case either. If I (as an off-site client) copy the file off the network and paste it to my desktop, the transfer begins immediately. No delay is seen.

The problem appears to be restricted to VLC.

Here is my VLC log prior to the freeze:

Code: Select all

core debug: adding item `video - file.mkv' ( file://192.168.1.1/Downloads/video%20-%20file.mkv ) core debug: processing request item: video - file.mkv, node: null, skip: 0 core debug: rebuilding array of current - root Playlist core debug: rebuild done - 1 items, index 0 core debug: starting playback of the new playlist item core debug: resyncing on video - file.mkv core debug: video - file.mkv is at 0 core debug: creating new input thread core debug: Creating an input for 'video - file.mkv' core debug: Creating an input for 'video - file.mkv' core debug: requesting art for video - file.mkv core debug: using timeshift granularity of 50 MiB, in path 'C:\Users\username\AppData\Local\Temp' core debug: `file://192.168.1.1/Downloads/video%20-%20file.mkv' gives access `file' demux `' path `192.168.1.1/Downloads/video%20-%20file.mkv' core debug: specified demux `any' core debug: creating demux: access='file' demux='any' location='192.168.1.1/Downloads/video%20-%20file.mkv' file='\\192.168.1.1\Downloads\video - file.mkv' core debug: looking for access_demux module matching "file": 12 candidates core debug: looking for meta fetcher module matching "any": 1 candidates lua debug: Trying Lua scripts in C:\Users\username\AppData\Roaming\vlc\lua\meta\fetcher lua debug: Trying Lua scripts in C:\Program Files (x86)\VLC\lua\meta\fetcher lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\fetcher\tvrage.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\fetcher\tvrage.luac core debug: no meta fetcher modules matched core debug: searching art for video - file.mkv core debug: looking for art finder module matching "any": 2 candidates core debug: no access_demux modules matched core debug: creating access 'file' location='192.168.1.1/Downloads/video%20-%20file.mkv', path='\\192.168.1.1\Downloads\video - file.mkv' core debug: looking for access module matching "file": 21 candidates filesystem debug: opening file `\\192.168.1.1\Downloads\video - file.mkv' core debug: using access module "filesystem" core debug: Using stream method for AStream* core debug: starting pre-buffering core debug: received first data after 0 ms core debug: pre-buffering done 1024 bytes in 0s - 1000000 KiB/s core debug: looking for stream_filter module matching "any": 6 candidates core debug: no stream_filter modules matched core debug: looking for stream_filter module matching "record": 6 candidates core debug: using stream_filter module "record" core debug: creating demux: access='file' demux='any' location='192.168.1.1/Downloads/video%20-%20file.mkv' file='\\192.168.1.1\Downloads\video - file.mkv' core debug: looking for demux module matching "mkv": 66 candidates mkv debug: | + Seek head mkv debug: | | + Seek mkv debug: | - info at 4151 mkv debug: | + Information mkv debug: | | + TimecodeScale=1000000 mkv debug: | | + Muxing Application=libebml v1.3.3 + libmatroska v1.4.4 mkv debug: | | + Writing Application=mkvmerge v8.9.0 ('Father Daughter') 64bit mkv debug: | | + Duration=2735004 mkv debug: | | + Date=Tue Mar 15 05:53:07 2016 mkv debug: | | + Title=original title was here mkv debug: | | + UID=923415968 mkv debug: | | + Seek mkv debug: | - tracks at 4351 mkv debug: | + Tracks mkv debug: | | + Track Entry mkv debug: | | | + Track Number=1 mkv debug: | | | + Track UID=1 mkv debug: | | | + Track Type=video mkv debug: | | | + Track Lacing=0 mkv debug: | | | + Track MinCache=1 mkv debug: | | | + Track CodecId=V_MPEGH/ISO/HEVC mkv debug: | | | + Track CodecPrivate size=114 mkv debug: | | | + Track Default Duration=41708333 mkv debug: | | | + Track Language=`und' mkv debug: | | | + Track Video mkv debug: | | | | + width=1280 mkv debug: | | | | + height=720 mkv debug: | | | | + display width=1280 mkv debug: | | | | + display height=720 mkv debug: | | + Track Entry mkv debug: | | | + Track Number=2 mkv debug: | | | + Track UID=2 mkv debug: | | | + Track Type=audio mkv debug: | | | + Track CodecId=A_AAC mkv debug: | | | + Track CodecPrivate size=4 mkv debug: | | | + Track Default Duration=42666666 mkv debug: | | | + Track Language=`und' mkv debug: | | | + Track Name=Stereo mkv debug: | | | + Track Audio mkv debug: | | | | + afreq=24000 mkv debug: | | | | + achan=2 mkv debug: | | | | + aoutfreq=48000 mkv debug: | | + Track Entry mkv debug: | | | + Track Number=3 mkv debug: | | | + Track UID=470035099 mkv debug: | | | + Track Type=subtitle mkv debug: | | | + Track Lacing=0 mkv debug: | | | + Track CodecId=S_TEXT/UTF8 mkv debug: | | | + Track Language=`und' mkv debug: | | + Seek mkv debug: | - cues at 174317686 mkv debug: | + Cues qt4 debug: IM: Setting an input lua debug: Trying Lua scripts in C:\Users\username\AppData\Roaming\vlc\lua\meta\art lua debug: Trying Lua scripts in C:\Program Files (x86)\VLC\lua\meta\art lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\00_musicbrainz.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\00_musicbrainz.luac lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\01_googleimage.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\01_googleimage.luac lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\02_frenchtv.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\02_frenchtv.luac lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\03_lastfm.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\03_lastfm.luac core debug: no art finder modules matched core debug: art not found for video - file.mkv

And where it picks back up a minute or two later:

Code: Select all

mkv debug: | - loading cues done. mkv debug: | | + Seek mkv debug: | | + Unknown (N7libebml8EbmlVoidE) mkv debug: | - tags at 174327490 mkv debug: | + Tags mkv debug: + Tag mkv debug: | + Targets mkv debug: | | + TargetTypeValue: 50 mkv debug: | | + TrackUID: 1 mkv debug: | + Simple Tag mkv debug: | | + Meta BPS: 449239 mkv debug: | + Simple Tag mkv debug: | | + Meta DURATION: 00:45:34.899000000 mkv debug: | + Simple Tag mkv debug: | | + Meta NUMBER_OF_FRAMES: 65572 mkv debug: | + Simple Tag mkv debug: | | + Meta NUMBER_OF_BYTES: 153578145 mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_WRITING_APP: mkvmerge v8.9.0 ('Father Daughter') 64bit mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_WRITING_DATE_UTC: 2016-03-15 05:53:07 mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_TAGS: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES mkv debug: + Tag mkv debug: | + Targets mkv debug: | | + TargetTypeValue: 50 mkv debug: | | + TrackUID: 2 mkv debug: | + Simple Tag mkv debug: | | + Meta BPS: 58884 mkv debug: | + Simple Tag mkv debug: | | + Meta DURATION: 00:45:34.848000000 mkv debug: | + Simple Tag mkv debug: | | + Meta NUMBER_OF_FRAMES: 64098 mkv debug: | + Simple Tag mkv debug: | | + Meta NUMBER_OF_BYTES: 20129954 mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_WRITING_APP: mkvmerge v8.9.0 ('Father Daughter') 64bit mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_WRITING_DATE_UTC: 2016-03-15 05:53:07 mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_TAGS: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES mkv debug: + Tag mkv debug: | + Targets mkv debug: | | + TargetTypeValue: 50 mkv debug: | | + TrackUID: 1841560253326699163 mkv debug: | + Simple Tag mkv debug: | | + Meta BPS: 65 mkv debug: | + Simple Tag mkv debug: | | + Meta DURATION: 00:00:05.000000000 mkv debug: | + Simple Tag mkv debug: | | + Meta NUMBER_OF_FRAMES: 1 mkv debug: | + Simple Tag mkv debug: | | + Meta NUMBER_OF_BYTES: 41 mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_WRITING_APP: mkvmerge v8.9.0 ('Father Daughter') 64bit mkv debug: | + Simple Tag mkv debug: | | + Meta _STATISTICS_WRITING_DATE_UTC: 2016-03-15 05:53:07 mkv debug: | + Simple Tag mkv warning: MKV/Ebml Parser: m_el[mi_level] == NULL mkv debug: | | + Meta _STATISTICS_TAGS: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES mkv warning: MKV/Ebml Parser: m_el[mi_level] == NULL mkv warning: MKV/Ebml Parser: Up cannot escape itself mkv debug: loading tags done. mkv debug: | + Void mkv debug: | + Information mkv debug: | + Tracks mkv debug: | + Void mkv debug: | + Cluster mkv debug: found 3 es core debug: selecting program id=0 core debug: Buffering 0% mkv debug: Starting the UI Hook core debug: using demux module "mkv" core debug: looking for a subtitle file in \\192.168.1.1\Downloads\ core debug: looking for decoder module matching "any": 43 candidates avcodec debug: CPU flags: 0x010053db avcodec debug: trying to use direct rendering avcodec debug: allowing 4 thread(s) for decoding avcodec debug: avcodec codec (MPEG-H Part2/HEVC (H.265)) started avcodec debug: using frame thread mode with 4 threads core debug: using decoder module "avcodec" core debug: looking for decoder module matching "any": 43 candidates core debug: using decoder module "faad" core debug: looking for decoder module matching "any": 43 candidates avcodec debug: CPU flags: 0x010053db avcodec warning: refusing to decode non validated subtitle codec subsdec debug: trying demuxer-specified character encoding: UTF-8 core debug: using decoder module "subsdec" core debug: looking for meta reader module matching "any": 2 candidates lua debug: Trying Lua scripts in C:\Users\username\AppData\Roaming\vlc\lua\meta\reader lua debug: Trying Lua scripts in C:\Program Files (x86)\VLC\lua\meta\reader lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\reader\filename.luac core debug: no meta reader modules matched core debug: `file://192.168.1.1/Downloads/video%20-%20file.mkv' successfully opened core debug: Buffering 0% avcodec debug: available software decoder output format 0 (yuv420p) core debug: Buffering 35% core debug: looking for text renderer module matching "any": 2 candidates core debug: Buffering 68% core debug: Stream buffering done (1023 ms in 1179 ms) freetype debug: Using Arial as font from file C:\WINDOWS\Fonts\arial.ttf freetype debug: Using Courier New as mono-font from file C:\WINDOWS\Fonts\cour.ttf faad warning: decoded zero sample freetype debug: using fontsize: 2 core debug: using text renderer module "freetype" core debug: looking for video filter2 module matching "any": 58 candidates faad debug: AAC SBR (channels: 2, samplerate: 48000) core debug: reusing audio output directsound debug: Opening DirectSound Audio Output swscale debug: 32x32 (32x32) chroma: YUVA -> 16x16 (16x16) chroma: RGBA with scaling using Bicubic (good quality) core debug: using video filter2 module "swscale" core debug: looking for video filter2 module matching "any": 58 candidates yuvp debug: YUVP to YUVA converter core debug: using video filter2 module "yuvp" core debug: Deinterlacing available core debug: deinterlace 0, mode blend, is_needed 0 core debug: Opening vout display wrapper core debug: looking for vout display module matching "any": 11 candidates directsound debug: Windows speaker config: Stereo and stream has 2 channels, using 2 channels core debug: output 'f32l' 48000 Hz Stereo frame=1 samples/8 bytes core debug: looking for audio volume module matching "any": 2 candidates core debug: using audio volume module "float_mixer" core debug: input 'f32l' 48000 Hz Stereo frame=1 samples/8 bytes core debug: looking for audio filter module matching "scaletempo": 14 candidates scaletempo debug: format: 48000 rate, 2 nch, 4 bps, fl32 scaletempo debug: params: 30 stride, 0.200 overlap, 14 search scaletempo debug: 1.000 scale, 1440.000 stride_in, 1440 stride_out, 1152 standing, 288 overlap, 672 search, 2400 queue, fl32 mode core debug: using audio filter module "scaletempo" core debug: conversion: 'f32l'->'f32l' 48000 Hz->48000 Hz Stereo->Stereo core debug: conversion pipeline complete core debug: conversion: 'f32l'->'f32l' 48000 Hz->48000 Hz Stereo->Stereo core debug: conversion pipeline complete core debug: looking for audio resampler module matching "any": 3 candidates direct3d debug: creating Vout EventThread core debug: using audio resampler module "samplerate" core debug: End of audio preroll direct3d debug: Win32VoutCreateWindow core debug: looking for vout window hwnd module matching "qt4,any": 3 candidates qt4 debug: requesting video window... qt4 debug: Video was requested 0, 0 core debug: using vout window hwnd module "qt4" direct3d debug: created video sub-window direct3d debug: Vout EventThread running direct3d debug: disabling screen saver direct3d debug: Direct3d Device: Intel(R) HD Graphics 4000 32902 358 9 core debug: VoutDisplayEvent 'resize' 1296x759 window direct3d warning: trying surface pixel format: YV12 direct3d debug: selected surface pixel format is YV12 direct3d debug: Using D3DTEXF_LINEAR for minification direct3d debug: Using D3DTEXF_LINEAR for magnification direct3d debug: Direct3D scene created successfully direct3d debug: Direct3D device adapter successfully initialized core debug: using vout display module "direct3d" core debug: original format sz 1280x736, of (0,0), vsz 1280x720, 4cc I420, sar 1:1, msk r0x0 g0x0 b0x0 core debug: removing module "freetype" core debug: looking for text renderer module matching "any": 2 candidates core debug: VoutDisplayEvent 'resize' 1920x954 window freetype debug: Using Arial as font from file C:\WINDOWS\Fonts\arial.ttf freetype debug: Using Courier New as mono-font from file C:\WINDOWS\Fonts\cour.ttf freetype debug: using fontsize: 2 core debug: using text renderer module "freetype" avcodec warning: plane 0 not aligned avcodec warning: disabling direct rendering core debug: End of video preroll core debug: Received first picture freetype debug: Breaking line core debug: Decoder wait done in 175 ms core debug: meta ok for original title here, need to fetch art core debug: looking for meta fetcher module matching "any": 1 candidates lua debug: Trying Lua scripts in C:\Users\username\AppData\Roaming\vlc\lua\meta\fetcher lua debug: Trying Lua scripts in C:\Program Files (x86)\VLC\lua\meta\fetcher lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\fetcher\tvrage.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\fetcher\tvrage.luac core debug: no meta fetcher modules matched core debug: searching art for original title here core debug: looking for art finder module matching "any": 2 candidates core debug: looking for xml reader module matching "any": 1 candidates core debug: using xml reader module "xml" core debug: auto hiding mouse cursor lua debug: Trying Lua scripts in C:\Users\username\AppData\Roaming\vlc\lua\meta\art lua debug: Trying Lua scripts in C:\Program Files (x86)\VLC\lua\meta\art lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\00_musicbrainz.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\00_musicbrainz.luac lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\01_googleimage.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\01_googleimage.luac lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\02_frenchtv.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\02_frenchtv.luac lua debug: Trying Lua playlist script C:\Program Files (x86)\VLC\lua\meta\art\03_lastfm.luac lua debug: skipping script (unmatched scope) C:\Program Files (x86)\VLC\lua\meta\art\03_lastfm.luac core debug: no art finder modules matched core debug: art not found for original title here core debug: auto hiding mouse cursor core debug: auto hiding mouse cursor

While I can certainly use ftp as a workaround, trying to explain the process to a (not-so-tech-savvy) family member would be a nightmare compared to the point-and-click process that is SMB.

[ExaltedVanguard]

Any advice on how to fix this, or what I can do to provide more information? My best guess (talking out my ass and knowing nothing about the code of VLC) is that reading mkv tags results in a very large number of file reads as VLC loads each individual part of the header, rather than loading the entire header at once.

This massive number of file-access requests would have little impact on a local network where pings are less than 1ms, but over the internet you would see a significant slow down.

[Jean-Baptiste Kempf]

Try 3.0 nightly build

[ExaltedVanguard]

Same issue with the latest nightly (20160716).

Since DLNA is "fixed" in 3.0, I can also confirm that streaming from DLNA works fine (just like ftp). The issue remains confined to VLC opening files over SMB.

[Jean-Baptiste Kempf]

Same issue with the latest nightly (20160716).

Since DLNA is "fixed" in 3.0, I can also confirm that streaming from DLNA works fine (just like ftp).

Cool.

The issue remains confined to VLC opening files over SMB.

Windows version?

[ExaltedVanguard]

Sorry for the very delayed reply.

Windows 10.

FWIW I've redone my network and my VPN server is now hosted directly on my router (instead of a raspberry pi attached to it), so minor topographical change in the network, but nothing meaningful for this issue (aside from ruling out hardware as a source of the issue).

Exact same issue is still present. FTP and DLNA still work 100% as expected. SMB playback continues to take >90 seconds to start (and continues to be fine after this extensive initial delay). All symptoms remain as described above.

I've also tested with the latest nightly (20161009) and the issue persists.

[balley8780]

Did you ever get this resolved. I've had this problem ever since Win10 came out. Have not found a solution. But your description is pretty exact. Mine occurs when I am using VLC to play HD videos from a media server that uses SMB for playback.