VLC hanging pauses since Yosemite upgrade

[videojim]

Figured I'd start a new thread since other threads have suggested posting log files trying to track down this problem with VLC pausing/freezing under Yosemite that seems to be affecting some users.

Downloaded the newest nightly build of 2.2 (have seen this with 3.0 nightly builds as well). vlc-2.2.0-x86_64-20141104-0312

Enabled logging in the preferences and also enabled logging via the command line -v command. I put lines starting with ">>>Opened" to indicate when I opened two videos. Please note the two videos I tried open and play fine in MPlayer OSX Extended, Quicktime Player, and Mac Media Player.


First the VLC-log.txt:

-- logger module started --
core: Running vlc with the default interface. Use 'cvlc' to use vlc without interface.
mp4 warning: elst box found
mp4 warning: STTS table of 1 entries
mp4 warning: CTTS table of 65702 entries
mp4 warning: elst box found
mp4 warning: STTS table of 1 entries
faad warning: decoded zero sample

>>>Opened first video (1-2 minute delay)

core warning: picture is too late to be displayed (missing 20 ms)
core warning: picture is too late to be displayed (missing 45 ms)
core warning: picture is too late to be displayed (missing 168 ms)
core warning: picture is too late to be displayed (missing 128 ms)
core warning: picture is too late to be displayed (missing 88 ms)
core warning: picture is too late to be displayed (missing 48 ms)
core warning: picture is too late to be displayed (missing 163 ms)
core warning: picture is too late to be displayed (missing 124 ms)
core warning: picture is too late to be displayed (missing 84 ms)
core warning: picture is too late to be displayed (missing 44 ms)
core warning: picture is too late to be displayed (missing 29 ms)
core warning: picture is too late to be displayed (missing 22 ms)
core warning: picture is too late to be displayed (missing 66 ms)
core warning: picture is too late to be displayed (missing 26 ms)
core warning: picture is too late to be displayed (missing 64 ms)
core warning: picture is too late to be displayed (missing 24 ms)
core warning: picture is too late to be displayed (missing 28 ms)
core warning: picture is too late to be displayed (missing 184 ms)
core warning: picture is too late to be displayed (missing 144 ms)
core warning: picture is too late to be displayed (missing 104 ms)
core warning: picture is too late to be displayed (missing 64 ms)
core warning: picture is too late to be displayed (missing 24 ms)
core warning: picture is too late to be displayed (missing 29 ms)
core warning: picture is too late to be displayed (missing 57 ms)
core warning: playback too early (-48742): down-sampling
core warning: picture is too late to be displayed (missing 26 ms)
core warning: picture is too late to be displayed (missing 89 ms)
core warning: picture is too late to be displayed (missing 49 ms)
core warning: picture is too late to be displayed (missing 40 ms)
core warning: picture is too late to be displayed (missing 23 ms)
core warning: picture is too late to be displayed (missing 154 ms)
core warning: picture is too late to be displayed (missing 114 ms)
core warning: picture is too late to be displayed (missing 75 ms)
core warning: picture is too late to be displayed (missing 35 ms)
core warning: picture is too late to be displayed (missing 30 ms)
core warning: picture is too late to be displayed (missing 33 ms)
core warning: can't get output picture
avcodec warning: disabling direct rendering
mkv warning: MKV/Ebml Parser: m_el[mi_level] == NULL

mkv warning: MKV/Ebml Parser: Up cannot escape itself
macosx warning: variable stereo-mode doesn't exist or isn't handled
faad warning: decoded zero sample

>>>Opened second video (1-2 minute delay)

freetype error: Breaking unbreakable line
core warning: early picture skipped
core warning: early picture skipped
core warning: can't get output picture
avcodec warning: disabling direct rendering
-- logger module stopped --

Then the command line output:


Last login: Sun Nov 2 18:57:02 on ttys000
Ethereal-Horizon:~ master$ /Applications/VLC.app/Contents/MacOS/VLC -v
VLC media player 2.2.0-rc1 Weatherwax (revision 2.2.0-rc1-1-g57c046c)
[0000000104f000b8] core libvlc warning: cannot read /Applications/VLC.app/Contents/MacOS/plugins/plugins.dat: No such file or directory
[0000000104f17278] core interface error: no suitable interface module
[0000000104f000b8] core libvlc error: interface "(null),none" initialization failed
[0000000104f17278] logger interface: using logger.
[0000000104f17278] logger interface warning: no log filename provided, using `/Users/master/Library/Logs/vlc-log.txt'
TagLib: MP4: Invalid atom size
TagLib: MP4: Invalid atom size

>>>Opened first video (1-2 minute delay)

2014-11-03 19:05:06.639 VLC[98637:11005704] Can't find app with identifier com.spotify.client
2014-11-03 19:07:06.682 VLC[98637:11005704] Can't find app with identifier com.spotify.client
shader program 1: WARNING: Output of vertex shader 'TexCoord1' not read by fragment shader
WARNING: Output of vertex shader 'TexCoord2' not read by fragment shader

Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: conn 0xf5df token 0x3ffffffffffd0a0
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: Backtrace (at 1.30589e+06):
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 0 CoreGraphics 0x00007fff8a8cd3d6 CGSBacktraceCreate + 112
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 1 CoreGraphics 0x00007fff8a8eb820 _ZN16CGSUpdateManager14disable_updateEv + 86
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 2 AppKit 0x00007fff94774f35 -[NSWindow disableScreenUpdatesUntilFlush] + 127
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 3 libvout_macosx_plugin.dylib 0x00000001179cecc5 -[VLCOpenGLVideoView renewGState] + 69
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 4 AppKit 0x00007fff946d0961 -[NSView _invalidateFocus] + 437
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 5 AppKit 0x00007fff946cd7ac -[NSView addSubview:] + 504
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 6 Foundation 0x00007fff8c93ff4c __NSThreadPerformPerform + 293
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 7 CoreFoundation 0x00007fff8d3e4661 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 8 CoreFoundation 0x00007fff8d3d67ed __CFRunLoopDoSources0 + 269
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 9 CoreFoundation 0x00007fff8d3d5e1f __CFRunLoopRun + 927
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 10 CoreFoundation 0x00007fff8d3d5838 CFRunLoopRunSpecific + 296
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 11 HIToolbox 0x00007fff91d1043f RunCurrentEventLoopInMode + 235
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 12 HIToolbox 0x00007fff91d101ba ReceiveNextEventCommon + 431
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 13 HIToolbox 0x00007fff91d0fffb _BlockUntilNextEventMatchingListInModeWithFilter + 71
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 14 AppKit 0x00007fff946b8821 _DPSNextEvent + 964
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 15 AppKit 0x00007fff946b7fd0 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 194
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 16 AppKit 0x00007fff946abf73 -[NSApplication run] + 594
Nov 3 19:07:06 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: 17 libmacosx_plugin.dylib 0x00000001058066ef OpenIntf + 287
2014-11-03 19:10:02.402 VLC[98637:11005704] Can't find app with identifier com.spotify.client

>>>Opened second video (1-2 minute delay)

2014-11-03 19:12:58.387 VLC[98637:11005704] Can't find app with identifier com.spotify.client
2014-11-03 19:14:58.431 VLC[98637:11005704] Can't find app with identifier com.spotify.client
shader program 1: WARNING: Output of vertex shader 'TexCoord1' not read by fragment shader
WARNING: Output of vertex shader 'TexCoord2' not read by fragment shader

Nov 3 19:14:58 Ethereal-Horizon.local VLC[98637] <Warning>: void CGSUpdateManager::log() const: conn 0xf5df: spurious update.
Ethereal-Horizon:~ master$



Any ideas?

And why is VLC trying to find spottily? I did try installing Spotify after seeing this error, but it didn't make any difference.

[videojim]

I think I found the cause...

After thinking about the Spotify references in the logs, I combed through all the preferences and found the 'Control external music players' setting was set to 'Pause iTunes /Spotify'. Eureka!

Now I didn't have Spotify installed until I tried installing it after seeing the errors in the log, so I doubt that was the problem. So I turned this setting to 'Do Nothing' and POOF! My hanging pauses stopped happening. If I turn it back to 'Pause iTunes /Spotify' and close iTunes, the problem doesn't occur.

So maybe VLC has an issue with pausing iTunes 12.0.1? Had 11.4 before the Yosemite upgrade.

I'll leave it off and add this to my bug report. Still may be a bug in VLC in regards to it pausing iTunes somewhere.

Glad I finally found this solution, since VLC was the only problematic app with Yosemite that I use.

[dfuhrmann]

Hi,

Thanks a lot for your analysis.

Now I didn't have Spotify installed until I tried installing it after seeing the errors in the log, so I doubt that was the problem. So I turned this setting to 'Do Nothing' and POOF! My hanging pauses stopped happening. If I turn it back to 'Pause iTunes /Spotify' and close iTunes, the problem doesn't occur.

Just to understand it right: Did the hang stopped because 1) you installed spotify, or 2) you closed iTunes? Maybe you can delete Spotify again to ensure that this is a sole problem with iTunes? Maybe its also only a problem with both of them...

Additional question: if you have actually music playing in iTunes: What is the behaviour? Is the music paused at the beginning or the end of the VLC hang?

[videojim]

No, installing Spotify didn't change anything.

Basically the hanging pauses stopped when I either:
Had the setting on ''Pause iTunes /Spotify' and had iTunes closed.
Had the setting on 'Do Nothing' and had iTunes open or closed.

So i think it's definitely VLC trying to pause iTunes 12.0.1 that is causing it.

And having the setting at ''Pause iTunes /Spotify' and iTunes 12.0.1 playing a song doesn't pause iTunes when i start playing a video.

[dfuhrmann]

I just tested it on Yosemite and for me it works totally fine, strangely. I have no concrete idea yet what is the exact issue. I assume you have a "normal iTunes" installation?

[videojim]

Yeah, normal iTunes

It's not the end of the world. I didn't even know that VLC would pause iTunes when I started playing videos, so leaving the setting off is fine for me.

[typenut]

I'm not as techie as you guys, but to me it simply looks like it's leaking memory, I work in a visual Enviroment and this reminds me of an issue we had couple years ago with a mkv standalone, but I do not have my Notebooks from back than any longer.

[dfuhrmann]

Sorry, but this bug pattern really looks like it has nothing to do with leaked memory. In this case you would not necessarily see hangs, but increased RAM consumption instead.