+- Forum (http://forum.xbian.org)
+-- Forum: Software (/forum-6.html)
+--- Forum: Kodi (/forum-18.html)
+--- Thread: [PROBLEM] Loading web media is slooow - 1.0rc3 (/thread-2532.html)
Loading web media is slooow - 1.0rc3 - danryu - 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?
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-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|User-Agent=Mozilla%2F5.0+%28Windows+NT+6.2%3B+Win64%3B+x64%3B+rv%3A16.0.1%29+Gecko%2F20121011+Firefox%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-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|User-Agent=Mozilla%2F5.0+%28Windows+NT+6.2%3B+Win64%3B+x64%3B+rv%3A16.0.1%29+Gecko%2F20121011+Firefox%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-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|User-Agent=Mozilla%2F5.0+%28Windows+NT+6.2%3B+Win64%3B+x64%3B+rv%3A16.0.1%29+Gecko%2F20121011+Firefox%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-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: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-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|User-Agent=Mozilla%2F5.0+%28Windows+NT+6.2%3B+Win64%3B+x64%3B+rv%3A16.0.1%29+Gecko%2F20121011+Firefox%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
RE: Loading web media is slooow - 1.0rc3 - menakite - 25th Oct, 2014 01:48 AM
Don't expect a Raspberry Pi to be much responsive when using plugins.
With that being said, it seems it spends an unusual amount of time to just load the plugin. Do you experience the same huge delay with different plugins (e.g. this)?
RE: Loading web media is slooow - 1.0rc3 - f1vefour - 25th Oct, 2014 04:27 PM
Thanks for posting the log but please use pastebin in the future when posting long logs.