Announcement

Collapse
No announcement yet.

Library load takes more than 10 minutes

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    Library load takes more than 10 minutes

    As mentioned in my thread on the itunes plugin topic, Homeseer start up takes more than 10 minute, first i thought this was caused by the itunes plugin, but now i found out that squeezebox plugin is causing this
    I have an itunes database with over 40k entries

    After updating from version 2.0.1.0 to 2.0.3.2 the long load times started
    reverting to old version didn't bring a solution
    There is 10 minute gap in the log file, where nothing seems to happen
    here's the relevant part
    player count ?
    info total genres ?
    info total artists ?
    info total albums ?
    info total songs ?
    listen 1

    7/4/2011 10:06:31 AM...SqueezeBox Debug~~!~~Entered tcpClient_onSendComplete. DataSize: 121
    7/4/2011 10:06:31 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetGenres
    7/4/2011 10:06:31 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: genres 0 247
    7/4/2011 10:06:31 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetArtists. Album: Genre:
    7/4/2011 10:06:31 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: artists 0 1097
    7/4/2011 10:06:32 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetAlbums. Artist: Genre:
    7/4/2011 10:06:32 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: albums 0 3864
    7/4/2011 10:06:36 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetTracks. Artists: Album: Genre:
    7/4/2011 10:06:36 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: tracks 0 44907
    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibLoading: False Loaded: True
    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a12%3a1f%3a08 time ?
    00%3a04%3a20%3a12%3a1f%3a08 mode ?

    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a1f%3a8b%3a84 time ?
    00%3a04%3a20%3a1f%3a8b%3a84 mode ?

    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 7c%3a6d%3a62%3ab5%3ad0%3a0e time ?
    7c%3a6d%3a62%3ab5%3ad0%3a0e mode ?

    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a12%3a1f%3a08 time ?
    00%3a04%3a20%3a12%3a1f%3a08 mode ?

    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a1f%3a8b%3a84 time ?
    00%3a04%3a20%3a1f%3a8b%3a84 mode ?

    7/4/2011 10:16:32 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 7c%3a6d%3a62%3ab5%3ad0%3a0e time ?
    7c%3a6d%3a62%3ab5%3ad0%3a0e mode ?


    somebody any clue ?

    #2
    Upon startup and in order to speed up later HSTouch usage, the plugin builds caches of songs, artists, etc... the one that takes most of the time is to query the tracks (sent in chunks from the SB server). HS2 via a music API call checks if the libraries have been loaded.

    Comment


      #3
      But this doesn't explain why the previous version was not plagued by the long loadtime, even going back to the old version didn't bring back the short loadtimes,it used to be (far) less than 2 minutes and then my hs touch clients could already log in.Do I conclude well that the cache should reduce loadtimes when homeseer is started the second or third time ?. if so this is defintely not the case, every shutdown and new startup takes 10 to 15 minutes
      Last edited by ceesmf; July 6, 2011, 11:26 AM.

      Comment


        #4
        The caching was introduced in the SqueezeBox plugin V2.0.0 beta 2 (http://board.homeseer.com/showpost.p...22&postcount=1) and the cache is rebuilt at every HS2 start. I can look into adding a configuration to make the track cache optional at startup (would still build the other but these go quickly). Are the SB server and HS2 server running on the same server in your setup? Just curious at startup, do you know how much memory is available and what the CPU utilization is on the SB and HS2 servers (especially while getting the track (LibGetTracks section in the log)?

        Comment


          #5
          When you get a chance, could you add the following setting to the "Settings" section in the plugin ini file (hspi_squeezebox.ini), restart the HS2 and post the log content around LibGetTracks (like below)?

          PHP Code:
          [Settings]

          ...
          LogSBLibrary=True 
          By setting LogSBLibrary to true, the plugin will add additional entries to the log file related to library queries including timing spent getting the content from the SB server (over the network) and parsing the response. LogSBLibrary cannot be set via the Web configuration UI and your ini file most likely does not contain the keyword. It will help to determine where the time is going. Thanks.

          Comment


            #6
            Thanks for response
            Yes HS2 and SB are on same server AM2 dualcore 2.4Ghz 4gb (3gb usuable)
            Server handles a few things more, skype,itunes, weatherprogram, weather-plugin, utorrent, 5 hs-touch clients connected, all idle
            When everything is loaded, no active torrents, idle itunes, cpu idles between 15.. 25 %, freemem 1.1 Gb, during libraryload in present situation,cpu between 55 .. 65 %

            with the new line in config, no change in load cpu/free mem/load time, still 11 minutes
            here's the complete config
            [Settings]
            LogSBLibrary=True
            PluginHouseCode=[
            SlimServerHost=localhost
            SlimServerCLIPort=9090
            SlimServerWebPort=9000
            SlimServerUser=
            SlimServerPassword=
            MonitoringInterval=60
            PlayerMonitoringInterval=1
            NotificationDuration=15
            ArtworkDimension=16
            Debug=True
            VerboseDebugging=True
            LogToHS2=False
            [00:04:20:12:1f:08]
            enabled=True
            DeviceCodeBase=4
            [00:04:20:1f:8b:84]
            enabled=True
            DeviceCodeBase=12
            [7c:6d:62:b5:d0:0e]
            enabled=True
            DeviceCodeBase=20
            [IR]
            IRPlayer0=00:04:20:12:1f:08
            IRDevice0=amplifier
            IrButton0=power_on
            IRPlayer1=00:04:20:12:1f:08
            IRDevice1=amplifier
            IrButton1=power_off
            IRPlayer2=00:04:20:12:1f:08
            IRDevice2=amplifier
            IrButton2=dtv
            IRPlayer3=00:04:20:12:1f:08
            IRDevice3=amplifier
            IrButton3=cable
            IRPlayer4=00:04:20:12:1f:08
            IRDevice4=amplifier
            IrButton4=dvd
            IRPlayer5=00:04:20:12:1f:08
            IRDevice5=amplifier
            IrButton5=md
            IRPlayer6=00:04:20:12:1f:08
            IRDevice6=amplifier
            IrButton6=v+
            IRPlayer7=00:04:20:12:1f:08
            IRDevice7=amplifier
            IrButton7=v-
            IRPlayer8=00:04:20:12:1f:08
            IRDevice8=LC-42X
            IrButton8=Power
            IRPlayer9=00:04:20:12:1f:08
            IRDevice9=LC-42X
            IrButton9=PoweroffE
            IRPlayer10=00:04:20:12:1f:08
            IRDevice10=amplifier
            IrButton10=mute
            IRCode11=55aa807f
            IRPlayer11=00:04:20:12:1f:08
            IRCode12=55aa40bf
            IRPlayer12=00:04:20:12:1f:08
            IRCode13=55aac03f
            IRPlayer13=00:04:20:12:1f:08
            IRCode14=55aa20df
            IRPlayer14=00:04:20:12:1f:08
            IRCode15=55aaa05f
            IRPlayer15=00:04:20:12:1f:08
            IRCode16=55aa609f
            IRPlayer16=00:04:20:12:1f:08
            [04:1e:64:53:90:a7]
            enabled=True
            DeviceCodeBase=28
            [f4:6d:04:4a:8a:af]
            enabled=True
            DeviceCodeBase=36
            [PlayerMenus]
            ShowDevices=False
            ShowEvents=False
            ShowPhoneMessages=False
            ShowCallerID=False
            ShowMisc=True
            CIDHistoryLengthToShow=10
            PhoneMessagesDir=C:\Program Files (x86)\HomeSeer HSPRO\messages
            UseLocation2=False
            ShowCallerName=False
            [Screensaver Buttons]
            Left=
            Right=
            Next=
            Previous=
            [SpeakProxy]
            WaveInputURL=wavin:0
            WaveInputSpeakerClient=
            TTSVoice=Microsoft Anna - English (United States)
            TTSVolume=100
            TTSRate=0
            TTSAdditionalSpeechDuration=1000
            DelayBeforeSpeaking=1
            DelayAfterSpeaking=1
            Enabled=False
            UseWaveInput=False

            Comment


              #7
              Here's the log you requested

              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Entered QueryConfiguration().
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: version ?
              player count ?
              info total genres ?
              info total artists ?
              info total albums ?
              info total songs ?
              listen 1

              7/7/2011 10:26:51 AM...SqueezeBox Info~~!~~Squeezebox Classic MusicAPI -- Entered LibGetGenres
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetGenres
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Entered tcpClient_onSendComplete. DataSize: 121
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: genres 0 247
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Entered tcpClient_onLineArrival: version 7.5.4
              7/7/2011 10:26:51 AM...SqueezeBox Info~~!~~ QueryServerLibrary() [Mode=2 Call=00:00:00.2832031 SB=00:00:00.2792969]. Query: genres 0 247 Reply Array Size: 247
              7/7/2011 10:26:51 AM...SqueezeBox Info~~!~~Squeezebox Classic MusicAPI -- Entered LibGetArtists. Album: Genre:
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetArtists. Album: Genre:
              7/7/2011 10:26:51 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: artists 0 1097
              7/7/2011 10:26:52 AM...SqueezeBox Info~~!~~ QueryServerLibrary() [Mode=2 Call=00:00:01.3359375 SB=00:00:01.3183594]. Query: artists 0 1097 Reply Array Size: 1097
              7/7/2011 10:26:52 AM...SqueezeBox Info~~!~~Squeezebox Classic MusicAPI -- Entered LibGetAlbums. Artist: Genre:
              7/7/2011 10:26:52 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetAlbums. Artist: Genre:
              7/7/2011 10:26:52 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: albums 0 3864
              7/7/2011 10:26:56 AM...SqueezeBox Info~~!~~ QueryServerLibrary() [Mode=2 Call=00:00:03.9052734 SB=00:00:03.7490234]. Query: albums 0 3864 Reply Array Size: 3598
              7/7/2011 10:26:56 AM...SqueezeBox Info~~!~~Squeezebox Classic MusicAPI -- Entered LibGetTracks. Artists: Album: Genre:
              7/7/2011 10:26:56 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibGetTracks. Artists: Album: Genre:
              7/7/2011 10:26:56 AM...SqueezeBox Debug~~!~~Entered QueryServerLibrary(). Query: tracks 0 44907
              7/7/2011 10:37:18 AM...SqueezeBox Info~~!~~ QueryServerLibrary() [Mode=2 Call=00:10:22.0976563 SB=00:10:21.2949219]. Query: tracks 0 44907 Reply Array Size: 44886
              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Squeezebox Classic MusicAPI -- Entered LibLoading: False Loaded: True
              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~SlimServer version: Version 7.5.4
              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a12%3a1f%3a08 time ?
              00%3a04%3a20%3a12%3a1f%3a08 mode ?

              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a1f%3a8b%3a84 time ?
              00%3a04%3a20%3a1f%3a8b%3a84 mode ?

              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Entered tcpClient_onSendComplete. DataSize: 72
              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Entered tcpClient_onSendComplete. DataSize: 72
              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a12%3a1f%3a08 time ?
              00%3a04%3a20%3a12%3a1f%3a08 mode ?

              7/7/2011 10:37:18 AM...SqueezeBox Debug~~!~~Entered WriteLineToServer(). Sending: 00%3a04%3a20%3a1f%3a8b%3a84 time ?

              Comment


                #8
                Thanks. I did not expect it to be faster by adding this additional logging, only to provide additional details. You can remove the LogSBLibrary entry in the ini file to avoid future extra logging. This gives me the information I was looking for.

                FYI, the majority of the time in the plugin at startup is spent receiving the track information from the SB server (and the SB server to collect it of course): 00:10:21.2949219 is spent waiting/receiving the information from the SB server out of 00:10:22.0976563 (1 sec or so to build the parse the response and build the cache).

                Comment


                  #9
                  I think that all time is spend on collecting the data for the plugin as SB server is already fully up and running; apperently SB server reads it's database from disk; isn't possible to bypass SB server here and have the plugin read directly from the database too and add a manual update button ?
                  that would speed up the thing a lot. In the old version it didn't take so much time either

                  Comment


                    #10
                    Today a new version of squeezebox server was released and tada ..
                    load times are back as they used to be (less than 2 minutes) so problem solved

                    Comment


                      #11
                      Thanks for the update! I will try this new version when make it back home.

                      Comment

                      Working...
                      X