2015-01-17, 22:02
When I transition video modes -- e.g. when I change from the menus in Confluence to a new video source (play MythTV recording) -- the transition isn't smooth.
The Confluence menu 'goes away' and my Unity desktop becomes visible for 0.5 to 2.5 seconds, then the video appears (and I 'miss' the first 1.5 seconds of the video).
This started with Helix (and happened with Helix betas). But around the same time, I upgraded to Ubuntu 14.
The desktop is visible when switching to any video sources (not just MythTV) and it isn't consistent in length (sometimes it is a long time, sometimes barley noticeable).
kodi.log has a bunch of CDVDClock:
iscontinuity sync errors (see log below), but I think I've seen those before this problem appeared. Nvidia 331.113 (see below).
Anyone else see this before or now? Any suggestions:
The Confluence menu 'goes away' and my Unity desktop becomes visible for 0.5 to 2.5 seconds, then the video appears (and I 'miss' the first 1.5 seconds of the video).
This started with Helix (and happened with Helix betas). But around the same time, I upgraded to Ubuntu 14.
The desktop is visible when switching to any video sources (not just MythTV) and it isn't consistent in length (sometimes it is a long time, sometimes barley noticeable).
kodi.log has a bunch of CDVDClock:
iscontinuity sync errors (see log below), but I think I've seen those before this problem appeared. Nvidia 331.113 (see below).Anyone else see this before or now? Any suggestions:
Code:
$ X -version
X.Org X Server 1.15.1
Release Date: 2014-04-13
X Protocol Version 11, Revision 0
Build Operating System: Linux 3.2.0-70-generic x86_64 Ubuntu
Current Operating System: ubuntu-xbmc 3.13.0-44-generic #73-Ubuntu SMP Tue Dec 16 00:22:43 UTC 2014 x86_64
xorg-server 2:1.15.1-0ubuntu2.6 (For technical support please see http://www.ubuntu.com/support)
$ nvidia-smi
+------------------------------------------------------+
| NVIDIA-SMI 331.113 Driver Version: 331.113Code:
06:12:43 T:140513503001024 DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
06:12:43 T:140513503001024 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
06:12:43 T:140513503001024 INFO: AddOnLog: MythTV PVR Client: Received announcement: Player, xbmc, OnPlay
06:12:43 T:140556082251520 DEBUG: CActiveAESink::OpenSink - trying to open device PULSE:alsa_output.pci-0000_06_00.1.hdmi-stereo-extra3
06:12:43 T:140556082251520 DEBUG: PulseAudio: Context authorizing
06:12:43 T:140556082251520 DEBUG: PulseAudio: Context setting name
06:12:43 T:140556082251520 DEBUG: PulseAudio: Context ready
06:12:43 T:140556082251520 DEBUG: PULSE does not support format: AE_FMT_FLOATP - will fallback to AE_FMT_FLOAT
06:12:43 T:140555388434176 NOTICE: fps: 29.970030, pwidth: 640, pheight: 360, dwidth: 640, dheight: 360
06:12:43 T:140555388434176 DEBUG: OutputPicture - change configuration. 640x360. framerate: 29.97. format: YV12
06:12:43 T:140555388434176 NOTICE: Display resolution ADJUST : HDMI-0: 1920x1080 @ 59.94Hz (18) (weight: 0.000)
06:12:43 T:140555388434176 DEBUG: CXBMCRenderManager::Configure - 3
06:12:43 T:140513503001024 NOTICE: Using GL_TEXTURE_2D
06:12:43 T:140513503001024 DEBUG: GL: Requested render method: 0
06:12:44 T:140556082251520 DEBUG: PulseAudio: Stream ready
06:12:44 T:140556082251520 NOTICE: PulseAudio: Opened device alsa_output.pci-0000_06_00.1.hdmi-stereo-extra3 in pcm mode with Buffersize 150 ms
06:12:44 T:140556082251520 DEBUG: CActiveAESink::OpenSink - PULSE Initialized:
06:12:44 T:140556082251520 DEBUG: Output Device : GF108 High Definition Audio Controller Digital Stereo (HDMI)
06:12:44 T:140556082251520 DEBUG: Sample Rate : 48000
06:12:44 T:140556082251520 DEBUG: Sample Format : AE_FMT_FLOAT
06:12:44 T:140556082251520 DEBUG: Channel Count : 2
06:12:44 T:140556082251520 DEBUG: Channel Layout: FL,FR
06:12:44 T:140556082251520 DEBUG: Frames : 2400
06:12:44 T:140556082251520 DEBUG: Frame Samples : 4800
06:12:44 T:140556082251520 DEBUG: Frame Size : 8
06:12:44 T:140556018059008 DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
06:12:44 T:140556057073408 DEBUG: Previous line repeats 1 times.
06:12:44 T:140556057073408 INFO: CActiveAESink::OpenSink 2nd - initialize sink
06:12:44 T:140513503001024 DEBUG: GL: BaseYUV2RGBGLSLShader: defines:
#define XBMC_texture_rectangle 0
#define XBMC_texture_rectangle_hack 0
#define XBMC_STRETCH 0
#define XBMC_YV12
06:12:44 T:140513503001024 NOTICE: GL: Selecting Single Pass YUV 2 RGB shader
06:12:44 T:140513503001024 DEBUG: GL: Vertex Shader compilation log:
06:12:44 T:140513503001024 DEBUG: GL: Vertex Shader compiled successfully
06:12:44 T:140513503001024 DEBUG: GL: Pixel Shader compilation log:
06:12:44 T:140513503001024 DEBUG: GL: Fragment Shader compiled successfully
06:12:44 T:140556057073408 DEBUG: CActiveAESink::OpenSink 2nd - trying to open device PULSE:bluez_sink.00_53_0C_42_06_6E
06:12:44 T:140556057073408 DEBUG: PulseAudio: Context authorizing
06:12:44 T:140556057073408 DEBUG: PulseAudio: Context setting name
06:12:44 T:140556057073408 DEBUG: PulseAudio: Context ready
06:12:44 T:140556057073408 DEBUG: PULSE does not support format: AE_FMT_FLOATP - will fallback to AE_FMT_FLOAT
06:12:44 T:140556057073408 ERROR: PulseAudio: Sink bluez_sink.00_53_0C_42_06_6E not found
06:12:44 T:140556057073408 DEBUG: CActiveAESink::OpenSink 2nd - trying to open device PULSE:Default
06:12:44 T:140556057073408 DEBUG: PulseAudio: Context authorizing
06:12:44 T:140556057073408 DEBUG: PulseAudio: Context setting name
06:12:44 T:140556057073408 DEBUG: PulseAudio: Context ready
06:12:44 T:140556057073408 DEBUG: PULSE does not support format: AE_FMT_FLOATP - will fallback to AE_FMT_FLOAT
06:12:44 T:140513503001024 DEBUG: GL: Vertex Shader compilation log:
06:12:44 T:140513503001024 DEBUG: GL: Vertex Shader compiled successfully
06:12:44 T:140513503001024 DEBUG: GL: Pixel Shader compilation log:
06:12:44 T:140513503001024 DEBUG: GL: Fragment Shader compiled successfully
06:12:44 T:140513503001024 NOTICE: GL: NPOT texture support detected
06:12:44 T:140513503001024 NOTICE: GL: Using GL_ARB_pixel_buffer_object
06:12:44 T:140556057073408 DEBUG: PulseAudio: Stream ready
06:12:44 T:140556057073408 NOTICE: PulseAudio: Opened device Default in pcm mode with Buffersize 150 ms
06:12:44 T:140556057073408 DEBUG: CActiveAESink::OpenSink 2nd - PULSE Initialized:
06:12:44 T:140556057073408 DEBUG: Output Device : Default
06:12:44 T:140556057073408 DEBUG: Sample Rate : 48000
06:12:44 T:140556057073408 DEBUG: Sample Format : AE_FMT_FLOAT
06:12:44 T:140556057073408 DEBUG: Channel Count : 2
06:12:44 T:140556057073408 DEBUG: Channel Layout: FL,FR
06:12:44 T:140556057073408 DEBUG: Frames : 2400
06:12:44 T:140556057073408 DEBUG: Frame Samples : 4800
06:12:44 T:140556057073408 DEBUG: Frame Size : 8
06:12:44 T:140556065466112 DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
06:12:44 T:140555719722752 DEBUG: Previous line repeats 1 times.
06:12:44 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2256547528.934998, should be:2255904000.000000, error:-643528.934998
06:12:44 T:140555396826880 DEBUG: CDVDPlayer::HandleMessages - player started 1
06:12:44 T:140555396826880 DEBUG: CDVDPlayer::HandleMessages - player started 2
06:12:44 T:140513503001024 DEBUG: Activating window ID: 12005
06:12:44 T:140513503001024 DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
06:12:44 T:140513503001024 NOTICE: CWinSystemX11::SetFullScreen - calling xrandr
06:12:44 T:140513503001024 DEBUG: OnLostDevice - notify display change event
06:12:44 T:140513503001024 DEBUG: Flush - flushing renderer
06:12:44 T:140513503001024 INFO: XRANDR: /usr/local/lib/kodi/kodi-xrandr --screen 0 --output HDMI-0 --mode 0x281
06:12:44 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2256011231.020996, should be:2255904000.000000, error:-107231.020996
06:12:44 T:140555746649856 DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
06:12:44 T:140513503001024 INFO: GL: Maximum texture width: 16384
06:12:45 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2257258276.962982, should be:2256816000.000000, error:-442276.962982
06:12:45 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2256969439.162018, should be:2256816000.000000, error:-153439.162018
06:12:46 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2256942385.649963, should be:2256816000.000000, error:-126385.649963
06:12:46 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2256942781.735016, should be:2256816000.000000, error:-126781.735016
06:12:46 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2256879354.778961, should be:2256990391.731842, error:111036.952881
06:12:46 T:140513503001024 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
06:12:46 T:140513503001024 DEBUG: ------ Window Init (VideoFullScreen.xml) ------
06:12:46 T:140513503001024 DEBUG: Window VideoFullScreen.xml was already loaded
06:12:46 T:140513503001024 DEBUG: Alloc resources: 210.70m
06:12:46 T:140513503001024 DEBUG: NotifyXRREvent - notify display reset event
06:12:46 T:140513503001024 DEBUG: RecreateWindow - current output: HDMI-0, mode: 0x281, refresh: 59.939
06:12:46 T:140513503001024 DEBUG: OnLostDevice - notify display change event
06:12:46 T:140513503001024 DEBUG: Flush - flushing renderer
06:12:47 T:140513503001024 DEBUG: Window Manager Name: Compiz
06:12:47 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2257876731.829834, should be:2257758852.282623, error:-117879.547211
06:12:47 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2257948857.179657, should be:2257824000.000000, error:-124857.179657
06:12:47 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2258077217.651001, should be:2257968000.000000, error:-109217.651001
06:12:47 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2258221147.452972, should be:2258075217.009705, error:-145930.443268
06:12:47 T:140513503001024 DEBUG: SECTION:LoadDLL(special://xbmcbin/system/ImageLib-x86_64-linux.so)
06:12:47 T:140513503001024 DEBUG: Loading: /usr/local/lib/kodi/system/ImageLib-x86_64-linux.so
06:12:49 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2259401756.994720, should be:2259292830.550873, error:-108926.443848
06:12:49 T:140555707135744 DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
06:12:49 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2259704278.968872, should be:2259586353.688202, error:-117925.280670
06:12:49 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2259902911.987183, should be:2260018523.721985, error:115611.734802
06:12:49 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2260176562.248993, should be:2260285228.845398, error:108666.596405
06:12:50 T:140555388434176 DEBUG: CPullupCorrection: detected pattern of length 1: 33366.70, frameduration: 33366.666667
06:12:50 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2261076754.793396, should be:2260968000.000000, error:-108754.793396
06:12:51 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2261411381.031006, should be:2261607401.256897, error:196020.225891
06:12:51 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError1 - was:2261664717.138885, should be:2261830953.729614, error:166236.590729
06:12:52 T:140513503001024 DEBUG: CWinSystemX11::RefreshGlxContext: refreshing context
06:12:52 T:140513503001024 INFO: GL: Maximum texture width: 16384
06:12:52 T:140513503001024 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
06:12:52 T:140513503001024 ERROR: CRenderManager::PrepareNextRender - asked to prepare with nothing available
06:12:52 T:140513503001024 NOTICE: Using GL_TEXTURE_2D
06:12:52 T:140513503001024 DEBUG: GL: Requested render method: 0
06:12:52 T:140513503001024 DEBUG: GL: BaseYUV2RGBGLSLShader: defines:
#define XBMC_texture_rectangle 0
#define XBMC_texture_rectangle_hack 0
#define XBMC_STRETCH 0
#define XBMC_YV12
06:12:52 T:140513503001024 NOTICE: GL: Selecting Single Pass YUV 2 RGB shader
06:12:52 T:140513503001024 DEBUG: GL: Vertex Shader compilation log:
06:12:52 T:140513503001024 DEBUG: GL: Vertex Shader compiled successfully
06:12:52 T:140513503001024 DEBUG: GL: Pixel Shader compilation log:
06:12:52 T:140513503001024 DEBUG: GL: Fragment Shader compiled successfully
06:12:52 T:140513503001024 DEBUG: GL: Vertex Shader compilation log:
06:12:52 T:140513503001024 DEBUG: GL: Vertex Shader compiled successfully
06:12:52 T:140513503001024 DEBUG: GL: Pixel Shader compilation log:
06:12:52 T:140513503001024 DEBUG: GL: Fragment Shader compiled successfully
06:12:52 T:140513503001024 NOTICE: GL: NPOT texture support detected
06:12:52 T:140513503001024 NOTICE: GL: Using GL_ARB_pixel_buffer_object
06:12:52 T:140555388434176 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:12:53 T:140555719722752 DEBUG: CDVDClock::Discontinuity - CDVDPlayerAudio::HandleSyncError2 - was:2263832261.093597, should be:2263880119.410977, error:47858.317379
06:12:54 T:140555405219584 DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
06:12:54 T:140555405219584 DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
06:12:54 T:140555746649856 DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
06:12:55 T:140513503001024 DEBUG: Previous line repeats 1 times.
06:12:55 T:140513503001024 DEBUG: Keyboard: scancode: 0xae, sym: 0x00b2, unicode: 0x0000, modifier: 0x0
06:12:55 T:140513503001024 DEBUG: OnKey: stop (0xf0bc) pressed, action is Stop
06:12:55 T:140513503001024 NOTICE: CDVDPlayer::CloseFile()
06:12:55 T:140513503001024 NOTICE: DVDPlayer: waiting for threads to exit
06:12:55 T:140555396826880 NOTICE: CDVDPlayer::OnExit()
06:12:55 T:140555396826880 NOTICE: Closing stream player 1
06:12:55 T:140555396826880 NOTICE: Waiting for audio thread to exit
06:12:55 T:140555719722752 NOTICE: thread end: CDVDPlayerAudio::OnExit()
06:12:55 T:140555719722752 DEBUG: Thread DVDPlayerAudio 140555719722752 terminating
