MediaPortal startup time (1 Viewer)

[Terra]

Hi,

I reviewed my MePo logs because I wanted to see why MePo takes so long for starting up and if there is something I could do to improve the situation. e.g. I found out that I had a corrupt VideoDatabaseV5.db3 which MePo tried to open for about 15 seconds and in the end gave up and continued the startup.

After fixing the corrupted database I reviewed the log after starting MePo with Watchdog and a question to the developers. I see that there is no log entry for about 19 seconds in the attached log:

2013-02-03 21:48:51.379499 [Info.][FilterChecker(4)]: FilterChecker: Version of installed quartz.dll: 6.6.7600.16385
2013-02-03 21:49:10.114570 [Info.][MPMain(1)]: TVHome V1.2.200.0:ctor

I see this at every startup, usually after the "Prefered language 3 is eng" line.

The whole startup takes 28 seconds, including those 19 seconds where no log is written.
Is there something wrong with my installation and/or is there something I can do to speed this up?
I have MePo on an SSD.

thanks & br

 

[Paranoid Delusion]

First thing, have you got a lot of plugins active, that is the one thing I notice slows down startup time, which for me is around 30 seconds with 5 plugins enabled using hdd and Titan as skin, more graphically intensive skins like StreamMP will add a few more seconds to that.

 

[DragonQ]

Yeah plugins are usually the biggest cause of slow startup. Mine takes 20 seconds with an SSD. 5 seconds of that is HTPCInfo producing "Input string was not in a correct format." errors, and the only other event that takes more than a second is "Main: Activating windowmanager".

 

[Terra]

I have considered that and I started Media Portal without any plugins in watchdog, also with the default Skin.
So the attached log is a start from my MePo without any plugins and it takes 28 seconds.

 

[DragonQ]

Using the Watchdog will likely slow down startup due to the debug mode being changed, but it should probably still be faster than with plugins enabled.

You forgot to attach logs though...

 

[Terra]

You forgot to attach logs though...

The logs are in the first post

 

[DragonQ]

Oh sorry, misread.

Yeah that definitely isn't right. Without the gap before "TVHome V1.2.200.0:ctor" the total startup time would be 7 seconds, which is reasonable. I can't access my own logs right now to compare though, sorry.

 

[DragonQ]

OK in my logs the only stuff between your two troublesome lines is plugin related. None of your log files gives any clue as to what's going on. If I start without plugins, I have many log lines in between your two key ones:

2013-02-05 09:42:16.480162 [Info.][FilterChecker(5)]: FilterChecker: Found quartz.dll from 26/10/2011 located at C:\Windows\SysWOW64\quartz.dll
2013-02-05 09:42:16.481162 [Info.][FilterChecker(5)]: FilterChecker: Version of installed quartz.dll: 6.6.7600.16385
2013-02-05 09:42:17.418216 [Debug][MPMain(1)]: TexturePacker: Cache root C:\ProgramData\Team MediaPortal\MediaPortal\Cache\DefaultWide\packedgfx23.png filled
2013-02-05 09:42:18.358270 [Debug][MPMain(1)]: TexturePacker: Cache root C:\ProgramData\Team MediaPortal\MediaPortal\Cache\DefaultWide\packedgfx24.png filled
2013-02-05 09:42:19.367327 [Debug][MPMain(1)]: TexturePacker: Cache root C:\ProgramData\Team MediaPortal\MediaPortal\Cache\DefaultWide\packedgfx25.png filled
2013-02-05 09:42:20.548395 [Debug][MPMain(1)]: TexturePacker: Cache root C:\ProgramData\Team MediaPortal\MediaPortal\Cache\DefaultWide\packedgfx26.png filled
2013-02-05 09:42:21.605455 [Debug][MPMain(1)]: TexturePacker: Cache root C:\ProgramData\Team MediaPortal\MediaPortal\Cache\DefaultWide\packedgfx27.png filled
2013-02-05 09:42:21.978477 [Debug][MPMain(1)]: TexturePacker: Cache root C:\ProgramData\Team MediaPortal\MediaPortal\Cache\DefaultWide\packedgfx28.png filled
2013-02-05 09:42:22.025479 [Warn.][MPMain(1)]: GraphicContext: NO screen calibration file found for resolution 1920x1080!
2013-02-05 09:42:22.026479 [Info.][MPMain(1)]: GraphicContext: MP will render at 50 FPS, use animations = True
2013-02-05 09:42:22.078482 [Info.][MPMain(1)]:   fonts.SafeDispose()
2013-02-05 09:42:22.080483 [Info.][MPMain(1)]:   Load fonts from C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\fonts.xml
2013-02-05 09:42:22.095483 [Debug][MPMain(1)]:   fonts.InitializeDeviceObjects()
2013-02-05 09:42:22.119485 [Debug][MPMain(1)]:   Loaded font:debug height:12 texture:256x256 chars:[32-255] miplevels:1
2013-02-05 09:42:22.140486 [Debug][MPMain(1)]:   Loaded font:font9 height:18 texture:512x256 chars:[32-256] miplevels:1
2013-02-05 09:42:22.171488 [Debug][MPMain(1)]:   Loaded font:font10 height:20 texture:512x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.194489 [Debug][MPMain(1)]:   Loaded font:font11 height:22 texture:512x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.215490 [Debug][MPMain(1)]:   Loaded font:font12 height:24 texture:512x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.249492 [Debug][MPMain(1)]:   Loaded font:font13 height:26 texture:1024x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.285494 [Debug][MPMain(1)]:   Loaded font:font14 height:28 texture:1024x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.322496 [Debug][MPMain(1)]:   Loaded font:font15 height:30 texture:1024x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.358498 [Debug][MPMain(1)]:   Loaded font:font16 height:30 texture:1024x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.394500 [Debug][MPMain(1)]:   Loaded font:font17 height:33 texture:1024x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.430503 [Debug][MPMain(1)]:   Loaded font:font18 height:35 texture:1024x512 chars:[32-256] miplevels:1
2013-02-05 09:42:22.433503 [Info.][MPMain(1)]:   Loading plugins whitelist:
2013-02-05 09:42:22.434503 [Info.][MPMain(1)]:	 ProcessPlugins.dll
2013-02-05 09:42:22.434503 [Info.][MPMain(1)]:	 PowerScheduler.Interfaces.dll
2013-02-05 09:42:22.434503 [Info.][MPMain(1)]:	 PowerSchedulerClientPlugin.dll
2013-02-05 09:42:22.435503 [Info.][MPMain(1)]:	 WindowPlugins.dll
2013-02-05 09:42:22.435503 [Info.][MPMain(1)]:	 Dialogs.dll
2013-02-05 09:42:22.435503 [Info.][MPMain(1)]:	 TvPlugin.dll
2013-02-05 09:42:22.437503 [Info.][MPMain(1)]:   LoadWindowPlugins()
2013-02-05 09:42:22.441503 [Info.][MPMain(1)]:   Load plugins from : C:\Program Files (x86)\Team MediaPortal\MediaPortal\Plugins\windows\WindowPlugins.dll
2013-02-05 09:42:22.452504 [Info.][MPMain(1)]:   File Version : 1.2.200.0
2013-02-05 09:42:22.538509 [Info.][MPMain(1)]: MusicDatabase: Opening database
2013-02-05 09:42:22.549509 [Info.][MPMain(1)]: using sqlite 3.7.11
2013-02-05 09:42:22.550509 [Info.][MPMain(1)]: MusicDatabase: Database opened
2013-02-05 09:42:22.605513 [Debug][MPMain(1)]: GUIMusicPlayingNow: Viz disabled - ShowViz True, VizName None
2013-02-05 09:42:22.615513 [Info.][MPMain(1)]:   Loading references from C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\references.xml
2013-02-05 09:42:22.617513 [Info.][MPMain(1)]:   original skin size:1280x720
2013-02-05 09:42:22.762522 [Debug][MPMain(1)]: Cacheing expression: #(iif(and(neq(L(102012), #currentmodule), neq(L(102002), #currentmodule), neq(L(100100), #currentmodule), neq(L(102015), #currentmodule)), #currentmodule, ' '))
2013-02-05 09:42:22.774522 [Debug][MPMain(1)]: Cacheing expression: and(neq(L(102012), #currentmodule), neq(L(102002), #currentmodule), neq(L(100100), #currentmodule), neq(L(102015), #currentmodule))
2013-02-05 09:42:22.774522 [Debug][MPMain(1)]: Cacheing expression: neq(L(102012), #currentmodule)
2013-02-05 09:42:22.774522 [Debug][MPMain(1)]: Cacheing expression: L(102012)
2013-02-05 09:42:22.775522 [Debug][MPMain(1)]: Cacheing expression: 102012
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: #currentmodule
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: neq(L(102002), #currentmodule)
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: L(102002)
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: 102002
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: neq(L(100100), #currentmodule)
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: L(100100)
2013-02-05 09:42:22.776522 [Debug][MPMain(1)]: Cacheing expression: 100100
2013-02-05 09:42:22.777522 [Debug][MPMain(1)]: Cacheing expression: neq(L(102015), #currentmodule)
2013-02-05 09:42:22.777522 [Debug][MPMain(1)]: Cacheing expression: L(102015)
2013-02-05 09:42:22.777522 [Debug][MPMain(1)]: Cacheing expression: 102015
2013-02-05 09:42:22.777522 [Debug][MPMain(1)]: Cacheing expression: ' '
2013-02-05 09:42:22.790523 [Debug][MPMain(1)]: Cacheing expression: #(L(180))
2013-02-05 09:42:22.790523 [Debug][MPMain(1)]: Cacheing expression: 180
2013-02-05 09:42:22.798524 [Debug][MPMain(1)]: Cacheing expression: #(L(171))
2013-02-05 09:42:22.798524 [Debug][MPMain(1)]: Cacheing expression: 171
2013-02-05 09:42:22.799524 [Debug][MPMain(1)]: Cacheing expression: #(L(179))
2013-02-05 09:42:22.799524 [Debug][MPMain(1)]: Cacheing expression: 179
2013-02-05 09:42:22.799524 [Debug][MPMain(1)]: Cacheing expression: #(L(170))
2013-02-05 09:42:22.799524 [Debug][MPMain(1)]: Cacheing expression: 170
2013-02-05 09:42:22.800524 [Debug][MPMain(1)]: Cacheing expression: #(L(435))
2013-02-05 09:42:22.800524 [Debug][MPMain(1)]: Cacheing expression: 435
2013-02-05 09:42:22.801524 [Debug][MPMain(1)]: Cacheing expression: #(L(436))
2013-02-05 09:42:22.801524 [Debug][MPMain(1)]: Cacheing expression: 436
2013-02-05 09:42:22.841526 [Info.][MPMain(1)]: GUIMusicPlaylist: Loading default playlist default.m3u
2013-02-05 09:42:22.868528 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\musicOverlay.xml' is missing control id 0 (window property: _videoRectangle)
2013-02-05 09:42:22.868528 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\musicOverlay.xml' is missing control id 6 (window property: _labelBigPlayTime)
2013-02-05 09:42:22.868528 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\musicOverlay.xml' is missing control id 9 (window property: _videoWindow)
2013-02-05 09:42:22.898529 [Info.][MPMain(1)]: opening video database
2013-02-05 09:42:22.920531 [Info.][MPMain(1)]: Cleaned up 0 rows for unwanted paths.
2013-02-05 09:42:22.921531 [Info.][MPMain(1)]: Found 0 files without path link. Cleaning files related tables.
2013-02-05 09:42:22.921531 [Info.][MPMain(1)]: Cleaned up 0 rows for tables without file link.
2013-02-05 09:42:22.921531 [Info.][MPMain(1)]: Clean up files (no path link): 0 rows affected.
2013-02-05 09:42:22.922531 [Info.][MPMain(1)]: Clean up path (no file link): 0 rows affected.
2013-02-05 09:42:22.922531 [Info.][MPMain(1)]: Clean up movie (no path link): 0 rows affected.
2013-02-05 09:42:22.923531 [Info.][MPMain(1)]: Clean up actorinfo (no actorId link to actors): 0 rows affected.
2013-02-05 09:42:22.923531 [Info.][MPMain(1)]: Clean up actorlinkmovie (no actorId link to actors): 0 rows affected.
2013-02-05 09:42:22.923531 [Info.][MPMain(1)]: Clean up actorlinkmovie (no movie link): 0 rows affected.
2013-02-05 09:42:22.924531 [Info.][MPMain(1)]: Clean up actorinfomovies (no actorId link to actors): 0 rows affected.
2013-02-05 09:42:22.924531 [Info.][MPMain(1)]: Clean up movieinfo (no movie link): 0 rows affected.
2013-02-05 09:42:22.925531 [Info.][MPMain(1)]: Clean up genrelinkmovie (no movie link): 0 rows affected.
2013-02-05 09:42:22.925531 [Info.][MPMain(1)]: Compacting videodatabase: 417792 bytes
2013-02-05 09:42:22.938532 [Info.][MPMain(1)]: Compacting finished successfully. New file lenght: 417792 bytes
2013-02-05 09:42:22.945532 [Info.][MPMain(1)]: video database opened
2013-02-05 09:42:23.126542 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\videoOverlay.xml' is missing control id 6 (window property: _labelBigPlayTime)
2013-02-05 09:42:23.141543 [Info.][MPMain(1)]:   Load plugins from : C:\Program Files (x86)\Team MediaPortal\MediaPortal\Plugins\windows\Dialogs.dll
2013-02-05 09:42:23.143543 [Info.][MPMain(1)]:   File Version : 1.2.200.0
2013-02-05 09:42:23.157544 [Debug][MPMain(1)]: Cacheing expression: #(string.formatcount(iif(eq(#countdownseconds,''),0,#countdownseconds), 1912))
2013-02-05 09:42:23.158544 [Debug][MPMain(1)]: Cacheing expression: iif(eq(#countdownseconds,''),0,#countdownseconds)
2013-02-05 09:42:23.158544 [Debug][MPMain(1)]: Cacheing expression: eq(#countdownseconds,'')
2013-02-05 09:42:23.158544 [Debug][MPMain(1)]: Cacheing expression: #countdownseconds
2013-02-05 09:42:23.158544 [Debug][MPMain(1)]: Cacheing expression: ''
2013-02-05 09:42:23.158544 [Debug][MPMain(1)]: Cacheing expression: 0
2013-02-05 09:42:23.158544 [Debug][MPMain(1)]: Cacheing expression: 1912
2013-02-05 09:42:23.172545 [Debug][MPMain(1)]: Cacheing expression: #(string.format(1903,#countdownseconds))
2013-02-05 09:42:23.172545 [Debug][MPMain(1)]: Cacheing expression: 1903
2013-02-05 09:42:23.190546 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\stdKeyboard.xml' is missing control id 2 (window property: _background)
2013-02-05 09:42:23.191546 [Info.][MPMain(1)]:   Load plugins from : C:\Program Files (x86)\Team MediaPortal\MediaPortal\Plugins\windows\TvPlugin.dll
2013-02-05 09:42:23.197546 [Info.][MPMain(1)]:   File Version : 1.2.200.0
2013-02-05 09:42:23.250549 [Info.][MPMain(1)]: RadioHome:OnAdded
2013-02-05 09:42:23.849584 [Debug][MPMain(1)]: TvFullScreen:ctor
2013-02-05 09:42:23.852584 [Info.][MPMain(1)]: xml:C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\mytvFullScreen.xml image id:16 width:0 height:0 gfx:video-overlay.png
2013-02-05 09:42:23.878585 [Debug][MPMain(1)]: TvFullScreen:Init
2013-02-05 09:42:23.898586 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\mytvguide.xml' is missing control id 98 (window property: videoBackground)
2013-02-05 09:42:23.899587 [Warn.][MPMain(1)]: GUIWindow:OnWindowLoaded: 'C:\ProgramData\Team MediaPortal\MediaPortal\Skin\DefaultWide\mytvguide.xml' is missing control id 99 (window property: videoWindow)
2013-02-05 09:42:23.901587 [Info.][MPMain(1)]: TvCropManager: Started
2013-02-05 09:42:23.925588 [Info.][MPMain(1)]: TVHome:OnAdded
2013-02-05 09:42:23.929588 [Debug][MPMain(1)]: g_player: Setting ShowFullScreenWindowTV to MediaPortal.Player.g_Player+ShowFullScreenWindowHandler
2013-02-05 09:42:23.930588 [Info.][MPMain(1)]: Remote control:master server :HTPC
2013-02-05 09:42:23.934589 [Debug][MPMain(1)]: Common.IsSingleSeat: HostName = HTPC / Environment.MachineName = HTPC
2013-02-05 09:42:23.935589 [Debug][MPMain(1)]: TVHome: HeartBeat Transmitter started.
2013-02-05 09:42:23.936589 [Debug][MPMain(1)]: ChannelNavigator: ctor()
2013-02-05 09:42:23.940589 [Info.][MPMain(1)]: get channels from database
2013-02-05 09:42:23.959590 [Info.][TvClient-TvHome: HeartBeat transmitter thread(11)]: TVHome: OnRemotingConnected, recovered from a disconnection
2013-02-05 09:42:24.005593 [Info.][MPMain(1)]: found:873 tv channels
2013-02-05 09:42:24.005593 [Info.][MPMain(1)]: TvNotify:OnNotifiesChanged
2013-02-05 09:42:24.121599 [Info.][MPMain(1)]: Done.
2013-02-05 09:42:24.121599 [Info.][MPMain(1)]: get all groups from database
2013-02-05 09:42:24.318611 [Info.][MPMain(1)]: loaded 9 tv groups
2013-02-05 09:42:24.323611 [Info.][MPMain(1)]: ChannelNavigator::LoadSettings()
2013-02-05 09:42:24.331611 [Debug][MPMain(1)]: TVHome.LoadSettings(): Preferred Audio Languages: eng;
2013-02-05 09:42:24.333611 [Info.][MPMain(1)]: Prefered language 1 is eng
2013-02-05 09:42:27.339783 [Info.][MPMain(1)]: TVHome V1.2.200.0:ctor

It took longer than usual to start up but this seems to be from texture caching (because I don't usually use DefaultWide). Could you open Task Manager and Resource Monitor during startup and see if CPU or HDD usage goes up during the time when it's apparently twiddling its thumbs?

 

[Paranoid Delusion]

Also RC is now out, so upgrade and see if anything changes, then we need fresh logs.

We know there is a delay if you use MyVideo\Music database, Deda has some idea's about speeding these up

 

[Sebastiii]

Hi,

I have see this long startup too (but maybe not related here) about TVServer on server and MP on client (so related to connexion to TVServer).
My Server was rnning on SQL Server and it was related to firewall because MSSQL use random port in setting to connect, when i have fixed that connection port in MSSQL, the startup was really better .