MediaPortal startup time (2 Viewers)

Terra

Portal Pro
August 25, 2009
230
57
Home Country
Austria Austria
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

Moderation Manager
  • Premium Supporter
  • June 13, 2005
    13,062
    2,978
    Cheshire
    Home Country
    United Kingdom United Kingdom
    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

    Portal Pro
    August 30, 2011
    644
    79
    Home Country
    United Kingdom United Kingdom
    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

    Portal Pro
    August 25, 2009
    230
    57
    Home Country
    Austria Austria
    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

    Portal Pro
    August 30, 2011
    644
    79
    Home Country
    United Kingdom United Kingdom
    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...
     
    Last edited:

    DragonQ

    Portal Pro
    August 30, 2011
    644
    79
    Home Country
    United Kingdom United Kingdom
    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.
     
    Last edited:

    DragonQ

    Portal Pro
    August 30, 2011
    644
    79
    Home Country
    United Kingdom United Kingdom
    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:

    Code:
    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

    Moderation Manager
  • Premium Supporter
  • June 13, 2005
    13,062
    2,978
    Cheshire
    Home Country
    United Kingdom United Kingdom
    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

    Development Group
  • Team MediaPortal
  • November 12, 2007
    16,579
    10,397
    France
    Home Country
    France France
    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 :).
     

    Users who are viewing this thread

    Top Bottom