2.2.1 missing first seconds of audio files

[Thinkcat]

Hello

This is a Mid 2011 Mac Mini running El Capitan. My problem is that every time I start playing a file, the audio starts only after a 1 to 2 second delay, missing as much from the begninng of the file. If I have something already playing, then the next file starts from the actual beginning.

I have a Focusrite Scarlett (USB) sound module. This problem started either when I upgraded from Yosemite to El Capitan or when I updated VLC. I will go and try different combinations and report back here.

I play files both from a network drive and from a local drive. There is no difference.

[Thinkcat]

Funny. I have had this problem for a month at least, but now, immediately after I complained about it, I cannot reproduce it anymore. Don't hold your breath, though. Will keep on trying different combinations.

Edit: After relaunching VLC the problem came back.

Edit: It's not the Focusrite. The internal speaker comes along no faster.

Edit: The problem does not appear with VLC 2.0.0. Now trying to find the version that introduced it.

Edit: The problem is not in 2.0.9 but it is in 2.1.0. I did not try 2.0.10 because there is no 64-bit version of it.

[gcortes]

I'm having the same problem on 2.2.1 on a Mac Mini runnig OS X 10.11.3. I found it only does it if it has been idle more then 30 seconds from the last time it played. Also, if I play a sound effect from Preferences/Sound/Sound Effects and then play a file in VLC within 30 seconds, it plays the whole thing. It's as if the audio service shuts down after 30 seconds and takes a second to reactivate. Perhaps VLC is not waiting for it to reactivate.

Update

I tried 2.0.9. It didn't have the HTTP LUA interface I needed. I'm using VLC via VLC Thing on SmartThings.

[Jean-Baptiste Kempf]

We need logs.

[wig.flowers]

Here si the log taken when the first file in an album finished and the second file commenced playing, with some of the Audio chopped off. Before you read through the whole thing, prominent error messages include:

-core warning: playback way too late (305574): flushing buffers,
-core warning: playback too late (122855): up-sampling,
-core warning: playback way too early (-208000): playing silence,
-macosx warning: variable stereo-mode doesn't exist or isn't handled,
-core error: unsafe option "recursive" has been ignored for security reasons.

core debug: EOF reached
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: waiting decoder fifos to empty
core debug: finished input
core debug: removing module "flac"
core debug: killing decoder fourcc `flac', 0 PES in FIFO
core debug: removing module "ugly_resampler"
core debug: removing module "audio_format"
core debug: removing module "scaletempo"
auhal debug: Stopping the auhal module
macosx debug: releasing sleep blocker (4506)
core debug: removing module "float_mixer"
core debug: keeping audio output
core debug: removing module "flacsys"
core debug: removing module "packetizer_flac"
core debug: removing module "record"
core debug: removing module "filesystem"
core debug: Program doesn't contain anymore ES
core debug: dead input
core debug: changing item without a request (current 0/7)
core debug: using item 1
core debug: starting playback of the new playlist item
core debug: resyncing on Aja
core debug: Aja is at 1
core debug: creating new input thread
core debug: Creating an input for 'Aja'
core error: unsafe option "recursive" has been ignored for security reasons
core debug: requesting art for Aja
core debug: using timeshift granularity of 50 MiB, in path '/tmp'
core debug: `file:///Users/William/Music/Music/Steely%20Dan%20-%20Aja/02%20-%20Steely%20Dan%20-%20Aja.flac' gives access `file' demux `' path `/Users/William/Music/Music/Steely%20Dan%20-%20Aja/02%20-%20Steely%20Dan%20-%20Aja.flac'
core debug: looking for meta fetcher module matching "any": 1 candidates
core debug: specified demux `any'
lua debug: Trying Lua scripts in /Users/William/Library/Application Support/org.videolan.vlc/lua/meta/fetcher
core debug: creating demux: access='file' demux='any' location='/Users/William/Music/Music/Steely%20Dan%20-%20Aja/02%20-%20Steely%20Dan%20-%20Aja.flac' file='/Users/William/Music/Music/Steely Dan - Aja/02 - Steely Dan - Aja.flac'
lua debug: Trying Lua scripts in /Applications/VLC.app/Contents/MacOS/share/lua/meta/fetcher
core debug: looking for access_demux module matching "file": 14 candidates
lua debug: Trying Lua playlist script /Applications/VLC.app/Contents/MacOS/share/lua/meta/fetcher/tvrage.luac
lua debug: skipping script (unmatched scope) /Applications/VLC.app/Contents/MacOS/share/lua/meta/fetcher/tvrage.luac
lua debug: Trying Lua scripts in /Applications/VLC.app/Contents/MacOS/share/share/lua/meta/fetcher
core debug: no meta fetcher modules matched
core debug: found art for Aja in cache
core debug: no access_demux modules matched
core debug: creating access 'file' location='/Users/William/Music/Music/Steely%20Dan%20-%20Aja/02%20-%20Steely%20Dan%20-%20Aja.flac', path='/Users/William/Music/Music/Steely Dan - Aja/02 - Steely Dan - Aja.flac'
core debug: looking for access module matching "file": 19 candidates
filesystem debug: opening file `/Users/William/Music/Music/Steely Dan - Aja/02 - Steely Dan - Aja.flac'
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 - 3067 KiB/s
core debug: looking for stream_filter module matching "any": 9 candidates
core debug: no stream_filter modules matched
core debug: looking for stream_filter module matching "record": 9 candidates
core debug: using stream_filter module "record"
core debug: creating demux: access='file' demux='any' location='/Users/William/Music/Music/Steely%20Dan%20-%20Aja/02%20-%20Steely%20Dan%20-%20Aja.flac' file='/Users/William/Music/Music/Steely Dan - Aja/02 - Steely Dan - Aja.flac'
core debug: looking for demux module matching "flac": 66 candidates
core debug: looking for packetizer module matching "any": 23 candidates
core debug: using packetizer module "packetizer_flac"
core debug: using demux module "flacsys"
core debug: looking for a subtitle file in /Users/William/Music/Music/Steely Dan - Aja/
core debug: looking for meta reader module matching "any": 2 candidates
core debug: using meta reader module "taglib"
core debug: removing module "taglib"
core debug: `file:///Users/William/Music/Music/Steely%20Dan%20-%20Aja/02%20-%20Steely%20Dan%20-%20Aja.flac' successfully opened
macosx warning: variable stereo-mode doesn't exist or isn't handled
core debug: selecting program id=0
core debug: looking for decoder module matching "any": 40 candidates
core debug: using decoder module "flac"
core debug: Buffering 0%
core debug: Buffering 9%
flac debug: decode STREAMINFO
core debug: Buffering 18%
flac debug: channels:2 samplerate:44100 bitspersamples:16
flac debug: STREAMINFO decoded
core debug: Buffering 27%
core debug: reusing audio output
core debug: VLC is looking for: 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
auhal debug: attempting to use device 0
core debug: Buffering 37%
auhal debug: using default audio device 60
auhal debug: found 2 stream formats for stream id 61
auhal debug: Audio device supports PCM mode only
auhal debug: Current device has a latency of 82 frames (0.001859 sec)
core debug: Buffering 46%
core debug: Buffering 55%
core debug: Buffering 65%
core debug: Buffering 74%
core debug: Buffering 83%
core debug: Buffering 92%
core debug: Stream buffering done (1021 ms in 3 ms)
auhal debug: current format is: [44100.000000][mcpl][9][8][1][8][2][32]
auhal debug: layout of AUHAL has 2 channels
auhal debug: selected 2 physical channels for device output
auhal debug: VLC will output: Stereo
auhal debug: we set the AU format: [44100.000000][mcpl][9][8][1][8][2][32]
auhal debug: the actual set AU format is [44100.000000][mcpl][9][8][1][8][2][32]
auhal debug: analog output successfully opened
core debug: output 'f32l' 44100 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 's32l' 44100 Hz Stereo frame=1 samples/8 bytes
core debug: looking for audio filter module matching "scaletempo": 14 candidates
scaletempo debug: format: 44100 rate, 2 nch, 4 bps, fl32
scaletempo debug: params: 30 stride, 0.200 overlap, 14 search
scaletempo debug: 1.000 scale, 1323.000 stride_in, 1323 stride_out, 1059 standing, 264 overlap, 617 search, 2204 queue, fl32 mode
core debug: using audio filter module "scaletempo"
core debug: conversion: 's32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
core debug: looking for audio converter module matching "any": 11 candidates
audio_format debug: s32l->f32l, bits per sample: 32->32
core debug: using audio converter module "audio_format"
core debug: conversion pipeline complete
core debug: conversion: 'f32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
core debug: conversion pipeline complete
core debug: looking for audio resampler module matching "any": 2 candidates
core debug: using audio resampler module "ugly_resampler"
core debug: End of audio preroll
core debug: Decoder wait done in 5 ms
core warning: playback way too early (-208000): playing silence
core debug: inserting 9172 zeroes
macosx debug: releasing old sleep blocker (4506)
macosx debug: prevented sleep through IOKit (4511)
core warning: playback too late (122855): up-sampling
core warning: playback way too late (305574): flushing buffers
core debug: inserting 61228 zeroes

[dfuhrmann]

Thanks for your help. But it looks like your log was cut off. Please provide a complete log, by using a pastebin service like http://pastebin.com/, and giving the link here.

[Thinkcat]

I did a bug report about this, with logs, but forgot to link it.

Here: https://trac.videolan.org/vlc/ticket/16546

[ajmas]

Could you test with the latest 2.x nightly for MacOS X, and see if it is still an issue?

[Thinkcat]

I downloaded http://nightlies.videolan.org/build/mac ... 9-0310.zip (says version 2.2.3). The problem persists.

This is not simply "a bug" but some kind of regression or side effect brought with the 2.1.0 "new audio core".

[archjeb]

Hello all.

I'm noticing the same issue with a Mac Book Pro running Sierra.

What's interesting is, I do NOT see the issue with the built-in 1/8" audio output. I only see it with the USB audio adapter (Landing Zone Dock station). I do not have this issue when using QuickTime or iTunes to play the mp3 files. Its only with VLC or using the vlclib with python.

******
USB PnP Sound Device:

Default Output Device: Yes
Default System Output Device: Yes
Input Channels: 1
Manufacturer: C-Media Electronics Inc.
Output Channels: 2
Current SampleRate: 44100
Transport: USB
•••••••


Any thoughts of what to try?


Thanks,

-AJ