Bugzilla – Bug 7340
Very slow SqueezeCenter startup
Last modified: 2009-09-08 09:27:19 UTC
There are a lot of reports in the forums of very slow startup times for SqueezeCenter. These are generally described as being in the 'several minutes' time range, during which time the web interface is unusable or appears to be loading. Needless to say, this is a big problem for anyone who either powers up their server when needed or stops and starts SqueezeCenter as a user program. I couldn't say whether everyone is seeing the same problem, but there's definitely something not right going on. I'm seeing it, but only occasionally, when SqueezeCenter is started. What I usually observe is that the initial time before I see anything displayed on my nearby SB2 is longer than normal, 30-45 seconds vs. 5-10 normally. And then it takes several minutes before the web interface becomes responsive. I have no idea what's going on during this time period, but it does not appear to be scanning the library, as nothing is logged in the server or scanner logs.
When you say nothing is logged, have you actually turned on any debugging??
Created attachment 3000 [details] server.log file The last time it happened, logging was set at the WARN level for all categories. This is the tail end of server.log file when it happened. The scanner.log was empty.
Important detail: all the reports so far have been on Windows?
QA to try to reproduce.
Turn on a ton of logging and try to get more detail. Also, try this if there's no upstream net connection and see if that could be a cause.
I was able to get it to happen again today, but after setting all logging levels to DEBUG before shutting down the server, I forgot to check 'Save logging settings'. Sorry. It took 1:57 before the server became responsive. This time, the Default skin loaded with everything except the browse pane information, but the rest of the page may have been in the browser's cache. During this time period 'Now Playing ->' was displayed on the SB2 and it was unresponsive to the IR remote. When the server finally came up, it appears as though the backlogged remote ui commands were executed. After the initial time starting, subsequent restarts were relatively quick. *** Disconnecting my Internet upstream in later tests had no effect on the startup times. They were normal.
This is just a hunch, but... It seems to happen only if it's been a while since the last time the server was started. Could it be the cache maintenance taking place during startup, and could the slowness be attributed to the very large number of image files now being cached? My cache directory, which I haven't manually cleared in a long time, is at 84MB and 5125 files. I see these log entries from the latest fast startups: [08-02-27 12:46:47.7369] main::init (373) mDNS init... [08-02-27 12:46:47.7373] Slim::Networking::mDNS::init (44) Skipping initialization on Windows. [08-02-27 12:46:47.7376] main::init (376) Cache init... [08-02-27 12:46:47.7409] Slim::Utils::Timers::setTimer (384) [norm] Set Slim::Utils::Cache::cleanup, in 9.25942611694336 seconds [08-02-27 12:46:47.7414] main::init (389) SqueezeCenter HTTP init... [08-02-27 12:46:47.7558] Slim::Web::HTTP::init (132) Found Template::Stash::XS! It still took 9 seconds to do the cache cleanup, even though it had been done a few minutes before. Does the HTTP server not start until the cache cleanup is finished?
Steven was trying to reproduce this earlier and had a theory about artwork cache, as well. Perhaps he can update us with any news. :)
Cache cleanup is an expensive operation and blocks the server, so yes it needs to be run before you can use the server. Not sure what kind of user is going to have an SC server that they don't run very often though, under normal usage you shouldn't see this problem. I think I am going to look at improving the cache for 7.0.1. To get a better log including cache info, run with --debug server.
Steven, can you comment on your progress?
(In reply to comment #9) > Not sure what kind of user is going to have an SC server > that they don't run very often though, under normal usage > you shouldn't see this problem. Isn't SqueezeNetwork there so users don't have to run a local server? The more folks using SN, the more there will be running their servers only occasionally. And anyone running SC on a dedicated server probably _re_starts the server very infrequently. There have already been a lot of reports in the forums, but usually the user can't figure out what's going on. Did the server actually start? Why is the web page only partially loading? Even if it's just something like 10 or 15 seconds, using the tray icon to start up the server and launch the web ui in a browser doesn't work very well.
I have not been able to distinguish any noticeable differences with startup times with the music libraries I have been testing with. I plan on using a larger library with more artwork to see if I can reproduce. Has there been any reports of this with systems running something other then Windows?
Matt said today he sees it with his Linux server every day when he updates to the latest version.
Created attachment 3019 [details] server.log showing artwork cache cleanup time Here's the tail end of the latest server log during a slow startup, with server logging at the DEBUG level. The startup took right around 1:55 - about the same as the last time. The library has 1700 albums, 5145 total files in the cache, 5105 files in the artwork cache. Windows XP Pro, 3.0GHz P4, 2GB RAM, with the music library on two internal 7200 RPM drives. The artwork cache cleanup took 93 seconds.
What about making the cleanup of the 'Artwork' namespace a part of a library scan instead of doing it at server startup? Would that keep the process from blocking the server? Cover art isn't likely to change much, if at all, between scans, so you wouldn't expect many files in need of purging. And with the large number of image files now being precached, it's going to be a very small percentage of the total, so there's not a lot to gain with regular purging. Using a purge interval of something like 10-30 days would probably be sufficient.
So artwork is cached for 10 days, do you see this happening about every 10 days or so?
Andy to adjust the cache time.
(In reply to comment #16) > So artwork is cached for 10 days, do you see this happening about > every 10 days or so? No, it looks like just one or two days is sufficient time between restarts to see it. From server\Slim\Utils\Cache.pm, line 58, it looks like the purging interval is 24 hours. I think all that the 93 second cleanup usually does is to go through every file in the artwork cache and check the expiration time, without actually deleting anything. If I understand how the cleanup works, changing the cache expiration time would have no effect on the startup time. Changing the purging interval to something longer would just make it less frequent.
Andy, is this committed?
JJ is right, it's a bit more complicated. I think for 7.0 the only thing we can do is not purge the Artwork cache ever. It gets deleted outright during a wipe & rescan, so it shouldn't be that big of a deal.
I'm good with that.
If the artwork in an mp3 changes, though, will it be detected? What about a artwork jpg file?
This change won't affect those things, if they work now they will continue to work. The only side effect of this is that the artwork cache may become bigger than it should be.
Fixed in change 17767. Set artwork cache items to not expire, and don't do any purging of the artwork cache.
This bug is being closed since it was resolved for a version which is now released! Please download the new version of SqueezeCenter (formerly SlimServer) at http://www.slimdevices.com/su_downloads.html If you are still seeing this bug, please re-open it and we will consider it for a future release.