25th Oct, 2014, 12:46 AM
Running Xbian for the first time on a Pi B+ over wi-fi and wired. In general it's a lovely piece of work, particularly the first-time setup wizard and the seamless CEC control. Damned impressive.
However I'm noticing an extreme lag between the moment a web-based video is selected for play, eg a Youtube video in the Youtube add-on, and the moment that it actually starts playing. Typically this is up to 15-30 seconds for even SD content.
I'm using default settings across the board on Xbian.
The following example is relatively quick at 17 seconds, but still a bit too slow for comfortable browsing of web media. A Youtube trailer is selected for play at "10:17:43" and play begins at "10:18:00".
Is this typical, and is there optimisation to be done?
10:17:43 T:2994771008 DEBUG: CecLogMessage - received data: header:00030004 p0:00004401 p1:00000000 p2:00000000 p3:00000000 reason:4
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> 01:44:00
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): user control pressed (44)
10:17:43 T:2942288960 DEBUG: CecLogMessage - key pressed: select (0)
10:17:43 T:2942288960 DEBUG: PushCecKeypress - received key b duration 0
10:17:43 T:3038285824 DEBUG: OnKey: 11 (0x0b) pressed, action is Select
10:17:43 T:2994771008 DEBUG: CecLogMessage - received data: header:00030008 p0:00004501 p1:00000000 p2:00000000 p3:00000000 reason:8
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> 01:8b:00
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): vendor remote button up (8B)
10:17:43 T:2942288960 DEBUG: CecLogMessage - key released: select (0)
10:17:43 T:2942288960 DEBUG: PushCecKeypress - received key b duration 68
10:17:43 T:3038285824 DEBUG: OnPlayMedia plugin://plugin.video.youtube/?path=/root/video&action=play_video&videoid=epANfLtEoBA
10:17:43 T:3038285824 DEBUG: CAnnouncementManager - Announcement: OnClear from xbmc
10:17:43 T:3038285824 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
10:17:43 T:3038285824 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
10:17:43 T:3038285824 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
10:17:43 T:3038285824 DEBUG: StartScript - calling plugin YouTube('plugin://plugin.video.youtube/','7','?path=/root/video&action=play_video&videoid=epANfLtEoBA')
10:17:43 T:3038285824 DEBUG: WaitOnScriptResult - waiting on the YouTube (id=12) plugin...
10:17:43 T:2732586048 NOTICE: Thread LanguageInvoker start, auto delete: false
10:17:43 T:2732586048 INFO: initializing python engine.
10:17:43 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): start processing
10:17:45 T:3038285824 DEBUG: DialogProgress::StartModal called
10:17:45 T:3038285824 DEBUG: ------ Window Init (DialogProgress.xml) ------
10:17:45 T:2732586048 NOTICE: -->Python Interpreter Initialized<--
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): the source file to load is "/home/xbian/.xbmc/addons/plugin.video.youtube/default.py"
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): setting the Python path to /home/xbian/.xbmc/addons/plugin.video.youtube:/home/xbian/.xbmc/addons/script.module.simplejson/lib:/home/xbian/.xbmc/addons/script.module.beautifulsoup/lib:/usr/local/share/xbmc/addons/script.module.pil/lib:/home/xbian/.xbmc/addons/script.common.plugin.cache/lib:/home/xbian/.xbmc/addons/script.module.simple.downloader/lib:/home/xbian/.xbmc/addons/script.module.requests/lib:/home/xbian/.xbmc/addons/script.module.mechanize/lib:/usr/local/share/xbmc/addons/xbmc.debug/:/home/xbian/.xbmc/addons/script.module.parsedom/lib:/home/xbian/.xbmc/addons/script.module.elementtree/lib:/usr/lib/python2.7:/usr/lib/python2.7/plat-linux2:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload:/usr/local/lib/python2.7/dist-packages:/usr/lib/python2.7/dist-packages
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): entering source directory /home/xbian/.xbmc/addons/plugin.video.youtube
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): instantiating addon using automatically obtained id of "plugin.video.youtube" dependent on version 2.1.0 of the xbmc.python api
10:17:49 T:2732586048 NOTICE: Loading cookies from :'/home/xbian/.xbmc/userdata/addon_data/plugin.video.youtube/yt-cookiejar.txt'
10:17:49 T:2732586048 NOTICE: YouTube-4.4.10
10:17:50 T:2994771008 DEBUG: CecLogMessage - received data: header:00050002 p0:E000870F p1:00000091 p2:00000000 p3:00000000 reason:2
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> 0f:87:00:e0:91
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): device vendor id (87)
10:17:50 T:2942288960 DEBUG: CecLogMessage - << Recorder 1 (1) -> Broadcast (F): vendor id LG (e091)
10:17:50 T:2942288960 DEBUG: CecLogMessage - << 1f:87:00:e0:91
10:17:50 T:2942288960 DEBUG: CecLogMessage - sending data: len = 4, payload = 1F:87:00:E0:91
10:17:50 T:2994771008 DEBUG: CecLogMessage - received data: header:00050001 p0:E000871F p1:00000091 p2:00000000 p3:00000000 reason:1
10:17:50 T:2942288960 DEBUG: CecLogMessage - command transmitted
10:17:50 T:2994771008 DEBUG: CecLogMessage - received data: header:00020002 p0:00000001 p1:00000000 p2:00000000 p3:00000000 reason:2
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> 01:00
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): feature abort ( 0)
10:17:51 T:2732586048 NOTICE: CommonFunctions-2.5.1
10:17:51 T:2732586048 DEBUG: LocalizeStrings: no strings.po file exist at /home/xbian/.xbmc/addons/plugin.video.youtube/resources/language/English, fallback to strings.xml
10:17:55 T:2732586048 NOTICE: links: 'dict'
10:17:56 T:2732586048 WARNING: GetDurationFromMinuteString <runtime> should be in minutes. Interpreting '0' as 0 minutes
10:17:56 T:2732586048 INFO: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): script successfully run
10:17:56 T:3038285824 DEBUG: WaitOnScriptResult- plugin returned successfully
10:17:56 T:3038285824 INFO: easy_aquire - Created session to http://r7---sn-bvvbax-h5ol.googlevideo.com
10:17:56 T:3038285824 DEBUG: CCurlFile::GetMimeType - http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...x%2F16.0.1 -> video/mp4
10:17:56 T:2732586048 INFO: Python script stopped
10:17:56 T:2732586048 DEBUG: Thread LanguageInvoker 2732586048 terminating
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers(http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...%2F16.0.1)
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtv
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: hdhomerun/myth/mms/udp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: streams
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: aacp/sdp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mp2
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (4)
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: OMXPlayer (4)
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: added 2 players
10:17:56 T:3028325440 DEBUG: CAESinkPi:Drain delay:78ms now:0ms
10:17:56 T:3028325440 DEBUG: CAESinkPi:Deinitialize
10:17:56 T:3028325440 DEBUG: CAESinkPi:SetAudioProps hdmi_stream_channels 0 hdmi_channel_map 00000000
10:17:56 T:3028325440 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.audio_render handle 0xb07e44f8
10:17:56 T:3038285824 NOTICE: COMXPlayer: Opening: http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...x%2F16.0.1
10:17:56 T:3038285824 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
10:17:56 T:3038285824 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
10:17:56 T:3038285824 DEBUG: LinuxRendererGL: Cleaning up GL resources
10:17:56 T:2732586048 NOTICE: Thread OMXPlayer start, auto delete: false
10:17:56 T:2732586048 NOTICE: Creating InputStream
10:17:56 T:2732586048 DEBUG: CFileCache::Open - opening <videoplayback> using cache
10:17:56 T:2732586048 DEBUG: CurlFile::Open(0x44658d8) http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...29&itag=22
10:17:56 T:2732586048 NOTICE: Creating Demuxer
10:17:56 T:2842686528 NOTICE: Thread FileCache start, auto delete: false
10:17:56 T:2732586048 DEBUG: Open - probing detected format [mov,mp4,m4a,3gp,3g2,mj2]
10:17:56 T:2732586048 DEBUG: Open - avformat_find_stream_info starting
10:17:57 T:3038285824 DEBUG: ------ Window Init (DialogBusy.xml) ------
10:17:57 T:3038285824 INFO: CheckIdle - Closing session to http://r3---sn-bvvbax-h5oe.googlevideo.com (easy=0xaa0a2398, multi=0x3cafef8)
10:17:57 T:3038285824 DEBUG: ------ Window Deinit (DialogProgress.xml) ------
10:17:58 T:2896208960 DEBUG: Thread JobWorker 2896208960 terminating (autodelete)
10:17:58 T:2683302976 DEBUG: Thread JobWorker 2683302976 terminating (autodelete)
10:17:58 T:2904597568 DEBUG: Thread JobWorker 2904597568 terminating (autodelete)
10:17:58 T:2732586048 DEBUG: Open - av_find_stream_info finished
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3eShw8AAxG&mt=1414160212&ip=94.173.124.61&key=yt5&ratebypass=yes&initcwndbps=2525000&mv=m&sparams=id,initcwndbps,ip,ipbits,itag,mime,mm,ms,mv,ratebypass,source,upn,expire&source=youtube&ms=au&sver=3&fexp=900222,922243,927622,930666,930672,931983,932404,935685,947209,947215,951501,952302,952901,957103,958303&upn=RfYmLk4mIMM&mm=31&signature=F78BA6A0B373B3A6D9E197DF2C7D7E6896110E97.7291673740DD674644D33E055612880076BF2329&itag=22':
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Metadata:
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: major_brand : mp42
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: minor_version : 0
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: compatible_brands: isommp42
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: creation_time : 2014-10-17 16:53:39
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Duration: 00:00:50.18, start: 0.000000, bitrate: 1345 kb/s
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Stream #0:0(und): Video: h264 (High) (avc1 / 0x31637661), yuv420p, 1280x720 [SAR 1:1 DAR 16:9], 1150 kb/s, 23.98 fps, 23.98 tbr, 24k tbn, 47.95 tbc
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Metadata:
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: handler_name : VideoHandler
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Stream #0:1(und): Audio: aac (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 191 kb/s
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Metadata:
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: creation_time : 2014-10-17 16:53:39
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: handler_name : IsoMedia File Produced by Google, 5-11-2011
10:17:58 T:2732586048 DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
10:17:58 T:2732586048 DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
10:17:58 T:2732586048 DEBUG: CDVDInputStreamFile::SetReadRate - set cache throttle rate to 803783 bytes per second
10:17:58 T:2732586048 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.clock input port 80 output port 81 m_handle 0x3d73e68
10:17:58 T:2732586048 DEBUG: OMXClock::OMXStop
10:17:58 T:2732586048 DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
10:17:58 T:2732586048 NOTICE: Opening video stream: 0 source: 256
10:17:58 T:2732586048 DEBUG: DllBcm: Using omx system library
10:17:58 T:2732586048 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_decode input port 130 output port 131 m_handle 0x4085518
10:17:58 T:2732586048 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.video_decode) - port(130), nBufferCountMin(1), nBufferCountActual(120), nBufferSize(81920), nBufferAlignmen(16)
10:17:58 T:2732586048 DEBUG: COMXVideo::Open - decoder_component(0x0x4085518), input_port(0x82), output_port(0x83) deinterlace 0 hdmiclocksync 1
10:17:58 T:2732586048 INFO: OMXPlayerVideo::OpenDecoder : Video codec omx-h264 width 1280 height 720 profile 100 fps 23.976025
10:17:58 T:2732586048 INFO: OMXPlayerVideo::OpenDecoder fps: 23.976025 hdmi_ntsc_freqs 1
10:17:58 T:2732586048 NOTICE: Creating video thread
10:17:58 T:2732586048 NOTICE: Opening audio stream: 1 source: 256
10:17:58 T:2904597568 NOTICE: Thread OMXPlayerVideo start, auto delete: false
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
10:17:58 T:2732586048 NOTICE: Creating audio thread
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.image_decode input port 320 output port 321 m_handle 0xaa2c1a68
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.image_decode) - port(320), nBufferCountMin(2), nBufferCountActual(2), nBufferSize(81920), nBufferAlignmen(16)
10:17:58 T:2683302976 NOTICE: Thread OMXPlayerAudio start, auto delete: false
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.resize input port 60 output port 61 m_handle 0xaa236160
10:17:58 T:2732586048 DEBUG: OnPlayBackStarted : play state was 1, starting 1
10:17:58 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 1
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 0
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.egl_render input port 220 output port 221 m_handle 0xb07c4208
10:17:58 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 3
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 INFO: COMXPlayerVideo - Stillframe left, switching to normal playback
10:17:58 T:2904597568 DEBUG: OMXVideo::Decode VDec : setStartTime 0.000000
10:17:58 T:2904597568 INFO: Output - renderer not started
10:17:58 T:2732586048 DEBUG: COMXPlayer::HandleMessages - player started 2 (tpa:0,a:0,v:1)
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::UseEGLImage component(OMX.broadcom.egl_render) - port(221), nBufferCountMin(1), nBufferCountActual(1), nBufferSize(15360) nBufferAlignmen(16)
10:17:59 T:2683302976 DEBUG: COMXAudioCodecOMX::Decode(0xaa2e56e0,557) format=8(8) chan=2 samples=1024 size=8192 data=0x4686710,0x4688710,(nil),(nil),(nil),(nil),(nil),(nil)
10:17:59 T:2683302976 DEBUG: COMXAudioCodecOMX::GetData size=8192/8192 line=4096/4096 cont=0 buf=0x428cb10
10:17:59 T:2683302976 DEBUG: COMXAudio::SetCodingType OMX_AUDIO_CodingPCM
10:17:59 T:2683302976 INFO: CPCMRemap: I channel map: FL,FR
10:17:59 T:2683302976 INFO: CPCMRemap: O channel map: FL,FR
10:17:59 T:2683302976 DEBUG: CPCMRemap: Downmix normalization is disabled
10:17:59 T:2683302976 DEBUG: CPCMRemap: FL = FL(1.000000*)
10:17:59 T:2683302976 DEBUG: CPCMRemap: FR = FR(1.000000*)
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_decode input port 120 output port 121 m_handle 0x446ae98
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.audio_decode) - port(120), nBufferCountMin(4), nBufferCountActual(16), nBufferSize(49152), nBufferAlignmen(16)
10:17:59 T:3038285824 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.image_decode handle 0xaa2c1a68
10:17:59 T:3038285824 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.resize handle 0xaa236160
10:17:59 T:3038285824 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.egl_render handle 0xb07c4208
10:17:59 T:2683302976 DEBUG: COMXAudio::Initialize Input bps 32 samplerate 44100 channels 2 buffer size 529200 bytes per second 176400
10:17:59 T:2683302976 DEBUG: pcm->direction : input
10:17:59 T:2683302976 DEBUG: pcm->nPortIndex : 0
10:17:59 T:2683302976 DEBUG: pcm->eNumData : 0
10:17:59 T:2683302976 DEBUG: pcm->eEndian : 1
10:17:59 T:2683302976 DEBUG: pcm->bInterleaved : 1
10:17:59 T:2683302976 DEBUG: pcm->nBitPerSample : 32
10:17:59 T:2683302976 DEBUG: pcm->ePCMMode : 0
10:17:59 T:2683302976 DEBUG: pcm->nChannels : 2
10:17:59 T:2683302976 DEBUG: pcm->nSamplingRate : 44100
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelLF
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelRF
10:17:59 T:2683302976 DEBUG: COMXAudio::Initialize device passthrough 0 hwdecode 0
10:17:59 T:2683302976 INFO: Audio codec channels 2 samplerate 44100 bitspersample 16
10:17:59 T:2683302976 DEBUG: COMXAudio::Decode ADec : setStartTime 0.000000
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_mixer input port 232 output port 231 m_handle 0x38787f8
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_render input port 100 output port 100 m_handle 0x3073120
10:17:59 T:2683302976 INFO: COMXAudio::ApplyVolume - Volume=0.00 (* 1.00 * 1.00)
10:17:59 T:2683302976 DEBUG: COMXAudio::PortSettingsChanged - Output bps 16 samplerate 44100 channels 2 buffer size 529200 bytes per second 176400
10:17:59 T:2683302976 DEBUG: pcm->direction : output
10:17:59 T:2683302976 DEBUG: pcm->nPortIndex : 231
10:17:59 T:2683302976 DEBUG: pcm->eNumData : 0
10:17:59 T:2683302976 DEBUG: pcm->eEndian : 1
10:17:59 T:2683302976 DEBUG: pcm->bInterleaved : 1
10:17:59 T:2683302976 DEBUG: pcm->nBitPerSample : 16
10:17:59 T:2683302976 DEBUG: pcm->ePCMMode : 0
10:17:59 T:2683302976 DEBUG: pcm->nChannels : 2
10:17:59 T:2683302976 DEBUG: pcm->nSamplingRate : 44100
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelLF
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelRF
10:17:59 T:2683302976 DEBUG: COMXAudio::PortSettingsChanged - bits:32 mode:0 channels:2 srate:44100 nopassthrough
10:17:59 T:2732586048 DEBUG: COMXPlayer::HandleMessages - player started RESET
10:17:59 T:2732586048 NOTICE: OMXClock using audio as reference
10:17:59 T:2732586048 DEBUG: OMXClock::OMXReset audio / video : 1 / 1 wait mask 0->3 state : 2->1
10:17:59 T:2732586048 DEBUG: COMXPlayer::HandleMessages - player started 1 (tpa:0,a:1,v:1)
10:17:59 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 4
10:17:59 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 1000
10:17:59 T:2683302976 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 0)
10:17:59 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 1000
10:17:59 T:2904597568 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 41708.333333, 1)
10:17:59 T:2904597568 INFO: Output - renderer not started
10:17:59 T:2904597568 INFO: Previous line repeats 9 times.
10:17:59 T:2904597568 NOTICE: not a 3D movie
10:17:59 T:2904597568 DEBUG: ResolutionUpdateCallBack - change configuration. video:1920x1080. framerate: 23.98. 1280x720 format: BYPASS
10:17:59 T:2904597568 NOTICE: Display resolution ADJUST : 1920x1080 (1920x1080) @ 24.00 - Full Screen (23) (weight: 0.001)
10:17:59 T:2904597568 DEBUG: CXBMCRenderManager::Configure - 3
10:17:59 T:3038285824 INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1.00 * 1.00)
10:17:59 T:3038285824 INFO: Previous line repeats 1 times.
10:17:59 T:3038285824 DEBUG: Activating window ID: 12005
10:17:59 T:3003159616 DEBUG: CecLogMessage - GetPhysicalAddress - physical address = 2000
10:17:59 T:3003159616 DEBUG: CecLogMessage - physical address changed to 2000
10:17:59 T:3003159616 DEBUG: CecLogMessage - physical address unchanged (2000)
10:17:59 T:2904597568 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_render input port 90 output port 90 m_handle 0xaa2e12f0
10:17:59 T:2904597568 DEBUG: COMXVideo::PortSettingsChanged - 1280x720@23.98 interlace:0 deinterlace:0
10:17:59 T:3038285824 DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
10:17:59 T:2904597568 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_scheduler input port 10 output port 11 m_handle 0xaa081888
10:17:59 T:2732586048 DEBUG: Resume 0.23,0.42 (A:01 V:01) EOF:0 FULL:0 T:0.20
10:17:59 T:2732586048 DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
10:17:59 T:3038285824 DEBUG: EGL set HDMI mode (1,32)=0
10:17:59 T:3003159616 DEBUG: EGL tv_service_callback (8,1,32)
10:17:59 T:3038285824 DEBUG: EGL set resolution 1920x1080 -> 1920x1080 @ 24.00 fps (1,32) flags:20010004 aspect:1.00
10:17:59 T:3038285824 DEBUG: CreateWindow: Created surface of size 1920x1080
10:17:59 T:3038285824 INFO: GLES: Maximum texture width: 2048
10:17:59 T:3038285824 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
10:17:59 T:2683302976 INFO: COMXPlayerAudio - Switching to normal playback
10:17:59 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 0
10:17:59 T:3038285824 DEBUG: ------ Window Init (VideoFullScreen.xml) ------
10:17:59 T:3038285824 DEBUG: PlayFile : OpenFile succeed, play state 2
10:17:59 T:3038285824 DEBUG: OnPlayBackStarted : play state was 2, starting 0
10:17:59 T:3038285824 NOTICE: Using GL_TEXTURE_2D
10:17:59 T:3038285824 DEBUG: GL: Requested render method: 0
10:17:59 T:3038285824 NOTICE: GL: Using BYPASS render method
10:17:59 T:3038285824 NOTICE: GL: NPOT texture support detected
10:17:59 T:3038285824 DEBUG: CGUIInfoManager::SetCurrentMovie(http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...%2F16.0.1)
10:17:59 T:3038285824 DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
10:17:59 T:3038285824 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
10:17:59 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: got notification for event Player.OnPlay. player.isPlayingLiveTV() = False
10:17:59 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: emitting Upstart event: sudo initctl emit -n -q player ACTION=PLAY TYPE=MOVIE
10:18:00 T:3038285824 DEBUG: dest_rect.x_offset 0 dest_rect.y_offset 0 dest_rect.width 1920 dest_rect.height 1080
10:18:00 T:3038285824 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
10:18:00 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: calculated priority: 4, based on monitor.screensaver=False, monitor.library_statuses={'scanning_video': False, 'cleaning_video': False, 'scanning_music': False, 'cleaning_music': False}, player.isPlaying()=1, player.isPlayingLiveTV()=False
10:18:00 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: emitting Upstart event: sudo initctl emit -n -q xbmcplevel PREVLEVEL=3 LEVEL=4
Edited! Next time use pastebin for logs as mentioned in forum rules for posting! Thanks // rikardo1979
However I'm noticing an extreme lag between the moment a web-based video is selected for play, eg a Youtube video in the Youtube add-on, and the moment that it actually starts playing. Typically this is up to 15-30 seconds for even SD content.
I'm using default settings across the board on Xbian.
The following example is relatively quick at 17 seconds, but still a bit too slow for comfortable browsing of web media. A Youtube trailer is selected for play at "10:17:43" and play begins at "10:18:00".
Is this typical, and is there optimisation to be done?
log file (Click to View)
10:17:43 T:2994771008 DEBUG: CecLogMessage - received data: header:00030004 p0:00004401 p1:00000000 p2:00000000 p3:00000000 reason:4
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> 01:44:00
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): user control pressed (44)
10:17:43 T:2942288960 DEBUG: CecLogMessage - key pressed: select (0)
10:17:43 T:2942288960 DEBUG: PushCecKeypress - received key b duration 0
10:17:43 T:3038285824 DEBUG: OnKey: 11 (0x0b) pressed, action is Select
10:17:43 T:2994771008 DEBUG: CecLogMessage - received data: header:00030008 p0:00004501 p1:00000000 p2:00000000 p3:00000000 reason:8
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> 01:8b:00
10:17:43 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): vendor remote button up (8B)
10:17:43 T:2942288960 DEBUG: CecLogMessage - key released: select (0)
10:17:43 T:2942288960 DEBUG: PushCecKeypress - received key b duration 68
10:17:43 T:3038285824 DEBUG: OnPlayMedia plugin://plugin.video.youtube/?path=/root/video&action=play_video&videoid=epANfLtEoBA
10:17:43 T:3038285824 DEBUG: CAnnouncementManager - Announcement: OnClear from xbmc
10:17:43 T:3038285824 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
10:17:43 T:3038285824 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
10:17:43 T:3038285824 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
10:17:43 T:3038285824 DEBUG: StartScript - calling plugin YouTube('plugin://plugin.video.youtube/','7','?path=/root/video&action=play_video&videoid=epANfLtEoBA')
10:17:43 T:3038285824 DEBUG: WaitOnScriptResult - waiting on the YouTube (id=12) plugin...
10:17:43 T:2732586048 NOTICE: Thread LanguageInvoker start, auto delete: false
10:17:43 T:2732586048 INFO: initializing python engine.
10:17:43 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): start processing
10:17:45 T:3038285824 DEBUG: DialogProgress::StartModal called
10:17:45 T:3038285824 DEBUG: ------ Window Init (DialogProgress.xml) ------
10:17:45 T:2732586048 NOTICE: -->Python Interpreter Initialized<--
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): the source file to load is "/home/xbian/.xbmc/addons/plugin.video.youtube/default.py"
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): setting the Python path to /home/xbian/.xbmc/addons/plugin.video.youtube:/home/xbian/.xbmc/addons/script.module.simplejson/lib:/home/xbian/.xbmc/addons/script.module.beautifulsoup/lib:/usr/local/share/xbmc/addons/script.module.pil/lib:/home/xbian/.xbmc/addons/script.common.plugin.cache/lib:/home/xbian/.xbmc/addons/script.module.simple.downloader/lib:/home/xbian/.xbmc/addons/script.module.requests/lib:/home/xbian/.xbmc/addons/script.module.mechanize/lib:/usr/local/share/xbmc/addons/xbmc.debug/:/home/xbian/.xbmc/addons/script.module.parsedom/lib:/home/xbian/.xbmc/addons/script.module.elementtree/lib:/usr/lib/python2.7:/usr/lib/python2.7/plat-linux2:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload:/usr/local/lib/python2.7/dist-packages:/usr/lib/python2.7/dist-packages
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): entering source directory /home/xbian/.xbmc/addons/plugin.video.youtube
10:17:45 T:2732586048 DEBUG: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): instantiating addon using automatically obtained id of "plugin.video.youtube" dependent on version 2.1.0 of the xbmc.python api
10:17:49 T:2732586048 NOTICE: Loading cookies from :'/home/xbian/.xbmc/userdata/addon_data/plugin.video.youtube/yt-cookiejar.txt'
10:17:49 T:2732586048 NOTICE: YouTube-4.4.10
10:17:50 T:2994771008 DEBUG: CecLogMessage - received data: header:00050002 p0:E000870F p1:00000091 p2:00000000 p3:00000000 reason:2
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> 0f:87:00:e0:91
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Broadcast (F): device vendor id (87)
10:17:50 T:2942288960 DEBUG: CecLogMessage - << Recorder 1 (1) -> Broadcast (F): vendor id LG (e091)
10:17:50 T:2942288960 DEBUG: CecLogMessage - << 1f:87:00:e0:91
10:17:50 T:2942288960 DEBUG: CecLogMessage - sending data: len = 4, payload = 1F:87:00:E0:91
10:17:50 T:2994771008 DEBUG: CecLogMessage - received data: header:00050001 p0:E000871F p1:00000091 p2:00000000 p3:00000000 reason:1
10:17:50 T:2942288960 DEBUG: CecLogMessage - command transmitted
10:17:50 T:2994771008 DEBUG: CecLogMessage - received data: header:00020002 p0:00000001 p1:00000000 p2:00000000 p3:00000000 reason:2
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> 01:00
10:17:50 T:2942288960 DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): feature abort ( 0)
10:17:51 T:2732586048 NOTICE: CommonFunctions-2.5.1
10:17:51 T:2732586048 DEBUG: LocalizeStrings: no strings.po file exist at /home/xbian/.xbmc/addons/plugin.video.youtube/resources/language/English, fallback to strings.xml
10:17:55 T:2732586048 NOTICE: links: 'dict'
10:17:56 T:2732586048 WARNING: GetDurationFromMinuteString <runtime> should be in minutes. Interpreting '0' as 0 minutes
10:17:56 T:2732586048 INFO: CPythonInvoker(12, /home/xbian/.xbmc/addons/plugin.video.youtube/default.py): script successfully run
10:17:56 T:3038285824 DEBUG: WaitOnScriptResult- plugin returned successfully
10:17:56 T:3038285824 INFO: easy_aquire - Created session to http://r7---sn-bvvbax-h5ol.googlevideo.com
10:17:56 T:3038285824 DEBUG: CCurlFile::GetMimeType - http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...x%2F16.0.1 -> video/mp4
10:17:56 T:2732586048 INFO: Python script stopped
10:17:56 T:2732586048 DEBUG: Thread LanguageInvoker 2732586048 terminating
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers(http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...%2F16.0.1)
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtv
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: hdhomerun/myth/mms/udp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: streams
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: aacp/sdp
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mp2
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
10:17:56 T:3038285824 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (4)
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: OMXPlayer (4)
10:17:56 T:3038285824 DEBUG: CPlayerCoreFactory::GetPlayers: added 2 players
10:17:56 T:3028325440 DEBUG: CAESinkPi:Drain delay:78ms now:0ms
10:17:56 T:3028325440 DEBUG: CAESinkPi:Deinitialize
10:17:56 T:3028325440 DEBUG: CAESinkPi:SetAudioProps hdmi_stream_channels 0 hdmi_channel_map 00000000
10:17:56 T:3028325440 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.audio_render handle 0xb07e44f8
10:17:56 T:3038285824 NOTICE: COMXPlayer: Opening: http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...x%2F16.0.1
10:17:56 T:3038285824 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
10:17:56 T:3038285824 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
10:17:56 T:3038285824 DEBUG: LinuxRendererGL: Cleaning up GL resources
10:17:56 T:2732586048 NOTICE: Thread OMXPlayer start, auto delete: false
10:17:56 T:2732586048 NOTICE: Creating InputStream
10:17:56 T:2732586048 DEBUG: CFileCache::Open - opening <videoplayback> using cache
10:17:56 T:2732586048 DEBUG: CurlFile::Open(0x44658d8) http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...29&itag=22
10:17:56 T:2732586048 NOTICE: Creating Demuxer
10:17:56 T:2842686528 NOTICE: Thread FileCache start, auto delete: false
10:17:56 T:2732586048 DEBUG: Open - probing detected format [mov,mp4,m4a,3gp,3g2,mj2]
10:17:56 T:2732586048 DEBUG: Open - avformat_find_stream_info starting
10:17:57 T:3038285824 DEBUG: ------ Window Init (DialogBusy.xml) ------
10:17:57 T:3038285824 INFO: CheckIdle - Closing session to http://r3---sn-bvvbax-h5oe.googlevideo.com (easy=0xaa0a2398, multi=0x3cafef8)
10:17:57 T:3038285824 DEBUG: ------ Window Deinit (DialogProgress.xml) ------
10:17:58 T:2896208960 DEBUG: Thread JobWorker 2896208960 terminating (autodelete)
10:17:58 T:2683302976 DEBUG: Thread JobWorker 2683302976 terminating (autodelete)
10:17:58 T:2904597568 DEBUG: Thread JobWorker 2904597568 terminating (autodelete)
10:17:58 T:2732586048 DEBUG: Open - av_find_stream_info finished
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3eShw8AAxG&mt=1414160212&ip=94.173.124.61&key=yt5&ratebypass=yes&initcwndbps=2525000&mv=m&sparams=id,initcwndbps,ip,ipbits,itag,mime,mm,ms,mv,ratebypass,source,upn,expire&source=youtube&ms=au&sver=3&fexp=900222,922243,927622,930666,930672,931983,932404,935685,947209,947215,951501,952302,952901,957103,958303&upn=RfYmLk4mIMM&mm=31&signature=F78BA6A0B373B3A6D9E197DF2C7D7E6896110E97.7291673740DD674644D33E055612880076BF2329&itag=22':
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Metadata:
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: major_brand : mp42
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: minor_version : 0
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: compatible_brands: isommp42
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: creation_time : 2014-10-17 16:53:39
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Duration: 00:00:50.18, start: 0.000000, bitrate: 1345 kb/s
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Stream #0:0(und): Video: h264 (High) (avc1 / 0x31637661), yuv420p, 1280x720 [SAR 1:1 DAR 16:9], 1150 kb/s, 23.98 fps, 23.98 tbr, 24k tbn, 47.95 tbc
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Metadata:
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: handler_name : VideoHandler
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Stream #0:1(und): Audio: aac (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 191 kb/s
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: Metadata:
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: creation_time : 2014-10-17 16:53:39
10:17:58 T:2732586048 INFO: ffmpeg[A2DFF440]: handler_name : IsoMedia File Produced by Google, 5-11-2011
10:17:58 T:2732586048 DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
10:17:58 T:2732586048 DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
10:17:58 T:2732586048 DEBUG: CDVDInputStreamFile::SetReadRate - set cache throttle rate to 803783 bytes per second
10:17:58 T:2732586048 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.clock input port 80 output port 81 m_handle 0x3d73e68
10:17:58 T:2732586048 DEBUG: OMXClock::OMXStop
10:17:58 T:2732586048 DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
10:17:58 T:2732586048 NOTICE: Opening video stream: 0 source: 256
10:17:58 T:2732586048 DEBUG: DllBcm: Using omx system library
10:17:58 T:2732586048 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_decode input port 130 output port 131 m_handle 0x4085518
10:17:58 T:2732586048 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.video_decode) - port(130), nBufferCountMin(1), nBufferCountActual(120), nBufferSize(81920), nBufferAlignmen(16)
10:17:58 T:2732586048 DEBUG: COMXVideo::Open - decoder_component(0x0x4085518), input_port(0x82), output_port(0x83) deinterlace 0 hdmiclocksync 1
10:17:58 T:2732586048 INFO: OMXPlayerVideo::OpenDecoder : Video codec omx-h264 width 1280 height 720 profile 100 fps 23.976025
10:17:58 T:2732586048 INFO: OMXPlayerVideo::OpenDecoder fps: 23.976025 hdmi_ntsc_freqs 1
10:17:58 T:2732586048 NOTICE: Creating video thread
10:17:58 T:2732586048 NOTICE: Opening audio stream: 1 source: 256
10:17:58 T:2904597568 NOTICE: Thread OMXPlayerVideo start, auto delete: false
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
10:17:58 T:2732586048 NOTICE: Creating audio thread
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.image_decode input port 320 output port 321 m_handle 0xaa2c1a68
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.image_decode) - port(320), nBufferCountMin(2), nBufferCountActual(2), nBufferSize(81920), nBufferAlignmen(16)
10:17:58 T:2683302976 NOTICE: Thread OMXPlayerAudio start, auto delete: false
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.resize input port 60 output port 61 m_handle 0xaa236160
10:17:58 T:2732586048 DEBUG: OnPlayBackStarted : play state was 1, starting 1
10:17:58 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 1
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 0
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.egl_render input port 220 output port 221 m_handle 0xb07c4208
10:17:58 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 3
10:17:58 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
10:17:58 T:2904597568 INFO: COMXPlayerVideo - Stillframe left, switching to normal playback
10:17:58 T:2904597568 DEBUG: OMXVideo::Decode VDec : setStartTime 0.000000
10:17:58 T:2904597568 INFO: Output - renderer not started
10:17:58 T:2732586048 DEBUG: COMXPlayer::HandleMessages - player started 2 (tpa:0,a:0,v:1)
10:17:58 T:3038285824 DEBUG: COMXCoreComponent::UseEGLImage component(OMX.broadcom.egl_render) - port(221), nBufferCountMin(1), nBufferCountActual(1), nBufferSize(15360) nBufferAlignmen(16)
10:17:59 T:2683302976 DEBUG: COMXAudioCodecOMX::Decode(0xaa2e56e0,557) format=8(8) chan=2 samples=1024 size=8192 data=0x4686710,0x4688710,(nil),(nil),(nil),(nil),(nil),(nil)
10:17:59 T:2683302976 DEBUG: COMXAudioCodecOMX::GetData size=8192/8192 line=4096/4096 cont=0 buf=0x428cb10
10:17:59 T:2683302976 DEBUG: COMXAudio::SetCodingType OMX_AUDIO_CodingPCM
10:17:59 T:2683302976 INFO: CPCMRemap: I channel map: FL,FR
10:17:59 T:2683302976 INFO: CPCMRemap: O channel map: FL,FR
10:17:59 T:2683302976 DEBUG: CPCMRemap: Downmix normalization is disabled
10:17:59 T:2683302976 DEBUG: CPCMRemap: FL = FL(1.000000*)
10:17:59 T:2683302976 DEBUG: CPCMRemap: FR = FR(1.000000*)
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_decode input port 120 output port 121 m_handle 0x446ae98
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.audio_decode) - port(120), nBufferCountMin(4), nBufferCountActual(16), nBufferSize(49152), nBufferAlignmen(16)
10:17:59 T:3038285824 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.image_decode handle 0xaa2c1a68
10:17:59 T:3038285824 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.resize handle 0xaa236160
10:17:59 T:3038285824 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.egl_render handle 0xb07c4208
10:17:59 T:2683302976 DEBUG: COMXAudio::Initialize Input bps 32 samplerate 44100 channels 2 buffer size 529200 bytes per second 176400
10:17:59 T:2683302976 DEBUG: pcm->direction : input
10:17:59 T:2683302976 DEBUG: pcm->nPortIndex : 0
10:17:59 T:2683302976 DEBUG: pcm->eNumData : 0
10:17:59 T:2683302976 DEBUG: pcm->eEndian : 1
10:17:59 T:2683302976 DEBUG: pcm->bInterleaved : 1
10:17:59 T:2683302976 DEBUG: pcm->nBitPerSample : 32
10:17:59 T:2683302976 DEBUG: pcm->ePCMMode : 0
10:17:59 T:2683302976 DEBUG: pcm->nChannels : 2
10:17:59 T:2683302976 DEBUG: pcm->nSamplingRate : 44100
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelLF
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelRF
10:17:59 T:2683302976 DEBUG: COMXAudio::Initialize device passthrough 0 hwdecode 0
10:17:59 T:2683302976 INFO: Audio codec channels 2 samplerate 44100 bitspersample 16
10:17:59 T:2683302976 DEBUG: COMXAudio::Decode ADec : setStartTime 0.000000
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_mixer input port 232 output port 231 m_handle 0x38787f8
10:17:59 T:2683302976 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_render input port 100 output port 100 m_handle 0x3073120
10:17:59 T:2683302976 INFO: COMXAudio::ApplyVolume - Volume=0.00 (* 1.00 * 1.00)
10:17:59 T:2683302976 DEBUG: COMXAudio::PortSettingsChanged - Output bps 16 samplerate 44100 channels 2 buffer size 529200 bytes per second 176400
10:17:59 T:2683302976 DEBUG: pcm->direction : output
10:17:59 T:2683302976 DEBUG: pcm->nPortIndex : 231
10:17:59 T:2683302976 DEBUG: pcm->eNumData : 0
10:17:59 T:2683302976 DEBUG: pcm->eEndian : 1
10:17:59 T:2683302976 DEBUG: pcm->bInterleaved : 1
10:17:59 T:2683302976 DEBUG: pcm->nBitPerSample : 16
10:17:59 T:2683302976 DEBUG: pcm->ePCMMode : 0
10:17:59 T:2683302976 DEBUG: pcm->nChannels : 2
10:17:59 T:2683302976 DEBUG: pcm->nSamplingRate : 44100
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelLF
10:17:59 T:2683302976 DEBUG: OMX_AUDIO_ChannelRF
10:17:59 T:2683302976 DEBUG: COMXAudio::PortSettingsChanged - bits:32 mode:0 channels:2 srate:44100 nopassthrough
10:17:59 T:2732586048 DEBUG: COMXPlayer::HandleMessages - player started RESET
10:17:59 T:2732586048 NOTICE: OMXClock using audio as reference
10:17:59 T:2732586048 DEBUG: OMXClock::OMXReset audio / video : 1 / 1 wait mask 0->3 state : 2->1
10:17:59 T:2732586048 DEBUG: COMXPlayer::HandleMessages - player started 1 (tpa:0,a:1,v:1)
10:17:59 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 4
10:17:59 T:2683302976 DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 1000
10:17:59 T:2683302976 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 0)
10:17:59 T:2904597568 DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 1000
10:17:59 T:2904597568 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 41708.333333, 1)
10:17:59 T:2904597568 INFO: Output - renderer not started
10:17:59 T:2904597568 INFO: Previous line repeats 9 times.
10:17:59 T:2904597568 NOTICE: not a 3D movie
10:17:59 T:2904597568 DEBUG: ResolutionUpdateCallBack - change configuration. video:1920x1080. framerate: 23.98. 1280x720 format: BYPASS
10:17:59 T:2904597568 NOTICE: Display resolution ADJUST : 1920x1080 (1920x1080) @ 24.00 - Full Screen (23) (weight: 0.001)
10:17:59 T:2904597568 DEBUG: CXBMCRenderManager::Configure - 3
10:17:59 T:3038285824 INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1.00 * 1.00)
10:17:59 T:3038285824 INFO: Previous line repeats 1 times.
10:17:59 T:3038285824 DEBUG: Activating window ID: 12005
10:17:59 T:3003159616 DEBUG: CecLogMessage - GetPhysicalAddress - physical address = 2000
10:17:59 T:3003159616 DEBUG: CecLogMessage - physical address changed to 2000
10:17:59 T:3003159616 DEBUG: CecLogMessage - physical address unchanged (2000)
10:17:59 T:2904597568 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_render input port 90 output port 90 m_handle 0xaa2e12f0
10:17:59 T:2904597568 DEBUG: COMXVideo::PortSettingsChanged - 1280x720@23.98 interlace:0 deinterlace:0
10:17:59 T:3038285824 DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
10:17:59 T:2904597568 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_scheduler input port 10 output port 11 m_handle 0xaa081888
10:17:59 T:2732586048 DEBUG: Resume 0.23,0.42 (A:01 V:01) EOF:0 FULL:0 T:0.20
10:17:59 T:2732586048 DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
10:17:59 T:3038285824 DEBUG: EGL set HDMI mode (1,32)=0
10:17:59 T:3003159616 DEBUG: EGL tv_service_callback (8,1,32)
10:17:59 T:3038285824 DEBUG: EGL set resolution 1920x1080 -> 1920x1080 @ 24.00 fps (1,32) flags:20010004 aspect:1.00
10:17:59 T:3038285824 DEBUG: CreateWindow: Created surface of size 1920x1080
10:17:59 T:3038285824 INFO: GLES: Maximum texture width: 2048
10:17:59 T:3038285824 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
10:17:59 T:2683302976 INFO: COMXPlayerAudio - Switching to normal playback
10:17:59 T:2732586048 DEBUG: COMXPlayer::SetCaching - caching state 0
10:17:59 T:3038285824 DEBUG: ------ Window Init (VideoFullScreen.xml) ------
10:17:59 T:3038285824 DEBUG: PlayFile : OpenFile succeed, play state 2
10:17:59 T:3038285824 DEBUG: OnPlayBackStarted : play state was 2, starting 0
10:17:59 T:3038285824 NOTICE: Using GL_TEXTURE_2D
10:17:59 T:3038285824 DEBUG: GL: Requested render method: 0
10:17:59 T:3038285824 NOTICE: GL: Using BYPASS render method
10:17:59 T:3038285824 NOTICE: GL: NPOT texture support detected
10:17:59 T:3038285824 DEBUG: CGUIInfoManager::SetCurrentMovie(http://r7---sn-bvvbax-h5ol.googlevideo.com/videoplayback?ipbits=0&expire=1414181874&mime=video/mp4&id=o-APjePDhqWGloE4hLw9qICIn9syUaa1WG5i3e...%2F16.0.1)
10:17:59 T:3038285824 DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
10:17:59 T:3038285824 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
10:17:59 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: got notification for event Player.OnPlay. player.isPlayingLiveTV() = False
10:17:59 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: emitting Upstart event: sudo initctl emit -n -q player ACTION=PLAY TYPE=MOVIE
10:18:00 T:3038285824 DEBUG: dest_rect.x_offset 0 dest_rect.y_offset 0 dest_rect.width 1920 dest_rect.height 1080
10:18:00 T:3038285824 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
10:18:00 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: calculated priority: 4, based on monitor.screensaver=False, monitor.library_statuses={'scanning_video': False, 'cleaning_video': False, 'scanning_music': False, 'cleaning_music': False}, player.isPlaying()=1, player.isPlayingLiveTV()=False
10:18:00 T:2871043136 DEBUG: XBian XBMC-Upstart bridge: emitting Upstart event: sudo initctl emit -n -q xbmcplevel PREVLEVEL=3 LEVEL=4