Custom Scan and Last.FM

[MeSue]

About a week or two ago, I enabled the Last.fm scanning in the custom scan plug-in. Well, after I did this, I started to notice that SqueezeCenter would become unresponsive for long periods shortly after the time of the scheduled scan. To the point where nothing can be played, the Web UI won't load, and all the squeezeboxes in the house will show the incorrect time on the clock (lagging the actual time by 10-20 minutes).

I have since gone back into custom scan and disabled last.fm scanning and cleared the last.fm data from custom scan, but I still have the period of unresponsiveness with SqueezeCenter. How can I get things back the way they were?

[erland]

Enable logging on Custom Scan in "SqueezeCenter Settings/Logging" and perform a scanning and post the log.

In the log you should be able to see what happens in Custom Scan and which steps that takes long time.

As you describe what you have done it sounds like you have done everything correctly.

The LastFM scanning module takes some time to scan the whole library, approximately a few seconds per artist in your library. During this time SqueezeCenter will be very unresponsive. After you have done the scanning once it should be fast, because it will then only scan new artists not retrieved the first time.

There is no easy way to avoid this unresponsiveness due to licensing restrictions on LastFM's side, the license only allows one request per second.
The Amazon scanning module has the same issues.

[MeSue]

I just tried "delete unused statistics" in Trackstat to see if that might help and it has been grinding away on that for about a half hour now. I will try the logging and rescan after I get access to the UI again. Should I do a clear and rescan everything or look for new and changed items?

[erland]

I just tried "delete unused statistics" in Trackstat to see if that might help and it has been grinding away on that for about a half hour now.

That seems very slow, what hardware are you running SqueezeCenter on ?
Do you have a very large music library ?

I will try the logging and rescan after I get access to the UI again. Should I do a clear and rescan everything or look for new and changed items?

It doesn't matter, Custom Scan does the same scanning after the the normal SqueezeCenter scan independent on if you run a full or "new and changed" rescan.

[MeSue]

Yeah, something is definitely not right. I clicked the "delete unused statistics" button around 12:20. It is now 1:30 and all my SB's still show 12:20 as the time and SC is completely unresponsive.

It is running on a HP MediaSmart Server (Windows Home Server). My library is about 17,000 tracks.

I think I will restart SC and try the clean rescan. Do I have to restore a backup of TrackStat data after doing that?

[erland]

I think I will restart SC and try the clean rescan. Do I have to restore a backup of TrackStat data after doing that?

No, you don't need to restore any backup.

Have you installed TrackStat recently ?
If you have, it might be the cause of things because it also performs some operations at the end of a rescan.
So if you don't see anything strange in the Custom Scan logs, you can also try to enable the TrackStat debug logging.

[MeSue]

I first installed TrackStat around last May, but I recently updated to the latest version, either yesterday or the day before. I will try the clean scan now...

[MeSue]

I did a rescan and got the same period of unresponsiveness. Here is the section of the log where it becomes unresponsive for almost a half hour:

[08-09-02 15:56:22.2525] Plugins::CustomScan::Scanner::refreshData (1928) Starting to update custom scan track data based on urls
[08-09-02 16:26:04.7034] Plugins::CustomScan::Scanner::refreshData (1947) Finished updating custom scan track data based on urls, updated 459587 items : It took 1782.451161 seconds

Then it comes back for a short time and goes unresponsive again.

[MeSue]

The second stall lasted nearly an hour.

[08-09-02 16:40:41.6496] Plugins::CustomScan::Scanner::refreshData (1949) CustomScan: Synchronization finished
[08-09-02 16:40:41.6508] Plugins::CustomScan::Scanner::initTrackScan (1256) Clearing track data, inserting data in new table...
[08-09-02 17:32:52.0156] Plugins::CustomScan::Scanner::initTrackScan (1260) Clearing track data, dropping temporary table...
[08-09-02 17:32:52.7322] Plugins::CustomScan::Scanner::initTrackScan (1273) Deleted track data after 3220.963043 seconds

[erland]

The problem is data scanned by the Custom Scan scanning modules "Custom Tag" or "Mixed Tag". If you aren't using the data scanned by those scanning modules, the problem is easiest solved by just hitting the "clear" button beside them and disable them during automatic scans.
If you aren't using any Custom Scan scanning modules, you can of course also just disable the Custom Scan plugin.

However, it really shouldn't be this slow on decent hardware. If I've found the correct hardware specifications, the HP MediaSmart Server should have a 1.8GHz AMD processor with 512MB memory, could this be correct ?
In that case it spontaneously feels like it ought to be A LOT faster than this but the memory could be a limiting factor depending on how much else is running. Is there any way to check the memory usage on the HP MediaSmart Server to see if it's running out of memory ?

Is SqueezeCenter generally running fast in this setup or does it feel slow also if you aren't using Custom Scan ?

Did the problem start after you installed the Custom Scan plugin ?

Unfortunately I've no way of testing this on similar hardware in my own setup since I neither have a HP MediaSmart Server nor have a possibility to run Windows Home Server.

My suspicion is that the problem could be caused by:
- Too slow hardware (probably to little memory)
- The SqueezeCenter MySQL database may work differently on HP MediaSmart Server than a standard Windows XP machine.

[MeSue]

Thanks. You got the specs right on the HP server, but mine is upgraded to 1 GB memory. According to "Spotlight on Windows" (a performance monitor), I have a around 200 MB free memory. Whether this is true through the whole scanning process, I don't know, as I only checked it just now.

I was using a custom tag, but if it is causing this problem, I can live without it. Custom Scan isn't required for Trackstat ratings? I thought it was. If it's not, then I will just disable Custom Scan.

I didn't notice the problem until just this past week, but it is possible it was always happening and I just didn't notice because I wasn't using my Squeezeboxes at those times of day when it was getting bogged down. Now that I have one in the kitchen, I tend to use it at various times throughout the day, more than I used to.

[erland]

Thanks. You got the specs right on the HP server, but mine is upgraded to 1 GB memory. According to "Spotlight on Windows" (a performance monitor), I have a around 200 MB free memory. Whether this is true through the whole scanning process, I don't know, as I only checked it just now.

1 GB spontaneously sounds like it should be enough.

The normal time of the queries that takes over 30 minutes in your setup is maximum a few seconds, so it feels like something is seriously wrong somewhere.

One thing that might be worth a try is to temporarily install the Database Query plugin and look at the result of its "Custom Scan Statistics" query. This should give me some kind of idea if there is anything wrong with your Custom Scan data.

I would not try the "Custom Scan Inconsistency/Problems" query, because that will probably take hours to execute in your setup.

It might also be interesting to temporarily enable TrackStat debug logging in "SqueezeCenter Settings/Logging" and then issue a "Refresh statistic after rescan" from the "SqueezeCenter Settings/Plugins/TrackStat/Backup Restore Clear" section of TrackStat setting pages. Post the TrackStat log entries in the SqueezeCenter log after it has finished.
The reason this is interesting is that TrackStat runs similar queries, and if those also takes long time it would indicate a general performance problem of MySQL in your setup.

Custom Scan isn't required for Trackstat ratings? I thought it was. If it's not, then I will just disable Custom Scan.

It's only needed if you use the iTunes, Music IP or Amarok integration provided by TrackStat to sync rating between these applications and SqueezeCenter.

[MeSue]

Here's the Database Query result:

parameter;value
Number of song attributes;181620
Number of artist attributes;0
Number of album attributes;0
Number of songs with attributes;17366
Number of songs without attributes;0
Number of artists with attributes;0
Number of artists without attributes;992
Number of albums with attributes;0
Number of albums without attributes;1355
Number of songs with attributes from customtag;8602
Number of songs with attributes from mixedtag;17366
Number of songs with attributes from ratingtag;7724
Number of song attributes from customtag;98324
Number of song attributes from mixedtag;75572
Number of song attributes from ratingtag;7724
Number of songs without attributes from customtag;8764
Number of songs without attributes from mixedtag;0
Number of albums without attributes from csamazon;1355
Number of artists without attributes from cslastfm;992
Number of songs with customtag attributes of type COMMENT;8602
Number of songs with mixedtag attributes of type ALBUM;17366
Number of songs with mixedtag attributes of type ALBUMARTIST;2729
Number of songs with mixedtag attributes of type ARTIST;17366
Number of songs with mixedtag attributes of type COMPOSER;586
Number of songs with mixedtag attributes of type GENRE;17366
Number of songs with mixedtag attributes of type TRACKARTIST;2729
Number of songs with mixedtag attributes of type YEAR;17366
Number of songs with ratingtag attributes of type RATING;7724

Here's what was in the log after running trackstat refresh:

[08-09-02 21:32:17.1782] Slim::Web::Settings::handler (153) Preference names must be prefixed by "pref_" in the page template: backup_file (PLUGIN_TRACKSTAT_SETTINGS_BACKUP)
[08-09-02 21:32:17.1793] Slim::Web::Settings::handler (153) Preference names must be prefixed by "pref_" in the page template: backup_dir (PLUGIN_TRACKSTAT_SETTINGS_BACKUP)
[08-09-02 21:32:17.1802] Slim::Web::Settings::handler (153) Preference names must be prefixed by "pref_" in the page template: backup_time (PLUGIN_TRACKSTAT_SETTINGS_BACKUP)
[08-09-02 21:32:17.2677] Plugins::TrackStat::Storage::refreshTracks (1089) Checking if additional indexes are needed for tracks
[08-09-02 21:32:19.0788] Plugins::TrackStat::Storage::refreshTracks (1113) Starting to analyze indexes
[08-09-02 21:32:19.7504] Plugins::TrackStat::Storage::refreshTracks (1126) Finished analyzing indexes : It took 2.483006 seconds
[08-09-02 21:32:19.7508] Plugins::TrackStat::Storage::refreshTracks (1131) Starting to update urls in statistic data based on musicbrainz ids
[08-09-02 21:32:19.8011] Plugins::TrackStat::Storage::refreshTracks (1150) Finished updating urls in statistic data based on musicbrainz ids, updated 0 items : It took 0.050079 seconds
[08-09-02 21:32:19.8015] Plugins::TrackStat::Storage::refreshTracks (1155) Starting to update musicbrainz id's in statistic data based on urls
[08-09-02 21:32:20.5629] Plugins::TrackStat::Storage::refreshTracks (1175) Finished updating musicbrainz id's in statistic data based on urls, updated 0 items : It took 0.761193 seconds
[08-09-02 21:32:20.5636] Plugins::TrackStat::Storage::refreshTracks (1180) Starting to update ratings in standard slimserver database based on urls
[08-09-02 21:32:27.7663] Plugins::TrackStat::Storage::refreshTracks (1200) Finished updating ratings in standard slimserver database based on urls, updated 0 items : It took 7.202306 seconds
[08-09-02 21:32:27.7671] Plugins::TrackStat::Storage::refreshTracks (1205) Starting to update added times in statistic data based on urls
[08-09-02 21:32:35.8131] Plugins::TrackStat::Storage::refreshTracks (1225) Finished updating added times in statistic data based on urls, updated 0 items : It took 8.045812 seconds
[08-09-02 21:32:35.8139] Plugins::TrackStat::Storage::refreshTracks (1230) Starting to update play counts in statistic data based on urls
[08-09-02 21:32:48.0159] Plugins::TrackStat::Storage::refreshTracks (1254) Finished updating play counts in statistic data based on urls, updated 0 items : It took 12.202116 seconds
[08-09-02 21:32:48.0168] Plugins::TrackStat::Storage::refreshTracks (1259) Starting to update last played times in statistic data based on urls
[08-09-02 21:33:02.2506] Plugins::TrackStat::Storage::refreshTracks (1283) Finished updating last played times in statistic data based on urls, updated 0 items : It took 14.233643 seconds
[08-09-02 21:33:02.2515] Plugins::TrackStat::Storage::refreshTracks (1288) Starting to add tracks without added times in statistic data based on urls
[08-09-02 21:33:12.6725] Plugins::TrackStat::Storage::refreshTracks (1312) Finished adding tracks without added times in statistic data based on urls, added 0 items : It took 10.420868 seconds
[08-09-02 21:33:12.6733] Plugins::TrackStat::Storage::refreshTracks (1317) Starting to update ratings in statistic data based on urls
[08-09-02 21:33:16.9538] Plugins::TrackStat::Storage::refreshTracks (1341) Finished updating ratings in statistic data based on urls, updated 0 items : It took 4.280239 seconds
[08-09-02 21:33:16.9545] Plugins::TrackStat::Storage::refreshTracks (1346) Starting to update unrated ratings in statistic data based on null
[08-09-02 21:33:17.4092] Plugins::TrackStat::Storage::refreshTracks (1366) Finished updating unrated ratings in statistic data based on null, updated 0 items : It took 0.454719 seconds
[08-09-02 21:33:17.4096] Plugins::TrackStat::Storage::refreshTracks (1372) Starting to update urls in track_history based on musicbrainz ids
[08-09-02 21:33:17.7347] Plugins::TrackStat::Storage::refreshTracks (1392) Finished updating urls in track_history based on musicbrainz ids, updated 0 items : It took 0.32493 seconds
[08-09-02 21:33:17.7352] Plugins::TrackStat::Storage::refreshTracks (1397) Starting to update musicbrainz id's in track_history based on urls
[08-09-02 21:33:19.2347] Plugins::TrackStat::Storage::refreshTracks (1417) Finished updating musicbrainz id's in statistic data based on urls, updated 0 items : It took 1.499405 seconds
[08-09-02 21:33:19.2354] Plugins::TrackStat::Storage::refreshTracks (1422) Starting to add missing entries to history table
[08-09-02 21:33:30.6881] Plugins::TrackStat::Storage::refreshTracks (1442) Finished adding missing entries to history table, adding 0 items : It took 11.452458 seconds
[08-09-02 21:33:30.6889] Plugins::TrackStat::Storage::refreshTracks (1447) Starting to update unrated ratings in history table based on null
[08-09-02 21:33:30.7022] Plugins::TrackStat::Storage::refreshTracks (1467) Finished updating unrated ratings in history table based on null, updated 0 items : It took 0.013048 seconds

I'm going to try removing Custom Scan to see if performance improves.

[MeSue]

I'm going to try removing Custom Scan to see if performance improves.

So far so good. I removed Custom Scan and did a rescan for changes and there was no bog down during or after it.

I don't think I even needed Custom Scan for what I thought I did anyway. I was doing some SQL playlists based on keywords. My Music Manager puts custom tags into the comment tag. I thought I needed Custom Scan to pick up those keywords, but I guess the comment field is picked up with a standard scan because my SQL playlist still works.

Thank you for all your help in figuring this out.

[erland]

Here's the Database Query result:

parameter;value
Number of song attributes;181620
Number of artist attributes;0
Number of album attributes;0
Number of songs with attributes;17366
Number of songs without attributes;0
Number of artists with attributes;0
Number of artists without attributes;992
Number of albums with attributes;0
Number of albums without attributes;1355
Number of songs with attributes from customtag;8602
Number of songs with attributes from mixedtag;17366
Number of songs with attributes from ratingtag;7724
Number of song attributes from customtag;98324
Number of song attributes from mixedtag;75572
Number of song attributes from ratingtag;7724
Number of songs without attributes from customtag;8764
Number of songs without attributes from mixedtag;0
Number of albums without attributes from csamazon;1355
Number of artists without attributes from cslastfm;992
Number of songs with customtag attributes of type COMMENT;8602
Number of songs with mixedtag attributes of type ALBUM;17366
Number of songs with mixedtag attributes of type ALBUMARTIST;2729
Number of songs with mixedtag attributes of type ARTIST;17366
Number of songs with mixedtag attributes of type COMPOSER;586
Number of songs with mixedtag attributes of type GENRE;17366
Number of songs with mixedtag attributes of type TRACKARTIST;2729
Number of songs with mixedtag attributes of type YEAR;17366
Number of songs with ratingtag attributes of type RATING;7724

Nothing strange there as far as I can see

Here's what was in the log after running trackstat refresh:

[08-09-02 21:32:17.1782] Slim::Web::Settings::handler (153) Preference names must be prefixed by "pref_" in the page template: backup_file (PLUGIN_TRACKSTAT_SETTINGS_BACKUP)
[08-09-02 21:32:17.1793] Slim::Web::Settings::handler (153) Preference names must be prefixed by "pref_" in the page template: backup_dir (PLUGIN_TRACKSTAT_SETTINGS_BACKUP)
[08-09-02 21:32:17.1802] Slim::Web::Settings::handler (153) Preference names must be prefixed by "pref_" in the page template: backup_time (PLUGIN_TRACKSTAT_SETTINGS_BACKUP)
[08-09-02 21:32:17.2677] Plugins::TrackStat::Storage::refreshTracks (1089) Checking if additional indexes are needed for tracks
[08-09-02 21:32:19.0788] Plugins::TrackStat::Storage::refreshTracks (1113) Starting to analyze indexes
[08-09-02 21:32:19.7504] Plugins::TrackStat::Storage::refreshTracks (1126) Finished analyzing indexes : It took 2.483006 seconds
[08-09-02 21:32:19.7508] Plugins::TrackStat::Storage::refreshTracks (1131) Starting to update urls in statistic data based on musicbrainz ids
[08-09-02 21:32:19.8011] Plugins::TrackStat::Storage::refreshTracks (1150) Finished updating urls in statistic data based on musicbrainz ids, updated 0 items : It took 0.050079 seconds
[08-09-02 21:32:19.8015] Plugins::TrackStat::Storage::refreshTracks (1155) Starting to update musicbrainz id's in statistic data based on urls
[08-09-02 21:32:20.5629] Plugins::TrackStat::Storage::refreshTracks (1175) Finished updating musicbrainz id's in statistic data based on urls, updated 0 items : It took 0.761193 seconds
[08-09-02 21:32:20.5636] Plugins::TrackStat::Storage::refreshTracks (1180) Starting to update ratings in standard slimserver database based on urls
[08-09-02 21:32:27.7663] Plugins::TrackStat::Storage::refreshTracks (1200) Finished updating ratings in standard slimserver database based on urls, updated 0 items : It took 7.202306 seconds
[08-09-02 21:32:27.7671] Plugins::TrackStat::Storage::refreshTracks (1205) Starting to update added times in statistic data based on urls
[08-09-02 21:32:35.8131] Plugins::TrackStat::Storage::refreshTracks (1225) Finished updating added times in statistic data based on urls, updated 0 items : It took 8.045812 seconds
[08-09-02 21:32:35.8139] Plugins::TrackStat::Storage::refreshTracks (1230) Starting to update play counts in statistic data based on urls
[08-09-02 21:32:48.0159] Plugins::TrackStat::Storage::refreshTracks (1254) Finished updating play counts in statistic data based on urls, updated 0 items : It took 12.202116 seconds
[08-09-02 21:32:48.0168] Plugins::TrackStat::Storage::refreshTracks (1259) Starting to update last played times in statistic data based on urls
[08-09-02 21:33:02.2506] Plugins::TrackStat::Storage::refreshTracks (1283) Finished updating last played times in statistic data based on urls, updated 0 items : It took 14.233643 seconds
[08-09-02 21:33:02.2515] Plugins::TrackStat::Storage::refreshTracks (1288) Starting to add tracks without added times in statistic data based on urls
[08-09-02 21:33:12.6725] Plugins::TrackStat::Storage::refreshTracks (1312) Finished adding tracks without added times in statistic data based on urls, added 0 items : It took 10.420868 seconds
[08-09-02 21:33:12.6733] Plugins::TrackStat::Storage::refreshTracks (1317) Starting to update ratings in statistic data based on urls
[08-09-02 21:33:16.9538] Plugins::TrackStat::Storage::refreshTracks (1341) Finished updating ratings in statistic data based on urls, updated 0 items : It took 4.280239 seconds
[08-09-02 21:33:16.9545] Plugins::TrackStat::Storage::refreshTracks (1346) Starting to update unrated ratings in statistic data based on null
[08-09-02 21:33:17.4092] Plugins::TrackStat::Storage::refreshTracks (1366) Finished updating unrated ratings in statistic data based on null, updated 0 items : It took 0.454719 seconds
[08-09-02 21:33:17.4096] Plugins::TrackStat::Storage::refreshTracks (1372) Starting to update urls in track_history based on musicbrainz ids
[08-09-02 21:33:17.7347] Plugins::TrackStat::Storage::refreshTracks (1392) Finished updating urls in track_history based on musicbrainz ids, updated 0 items : It took 0.32493 seconds
[08-09-02 21:33:17.7352] Plugins::TrackStat::Storage::refreshTracks (1397) Starting to update musicbrainz id's in track_history based on urls
[08-09-02 21:33:19.2347] Plugins::TrackStat::Storage::refreshTracks (1417) Finished updating musicbrainz id's in statistic data based on urls, updated 0 items : It took 1.499405 seconds
[08-09-02 21:33:19.2354] Plugins::TrackStat::Storage::refreshTracks (1422) Starting to add missing entries to history table
[08-09-02 21:33:30.6881] Plugins::TrackStat::Storage::refreshTracks (1442) Finished adding missing entries to history table, adding 0 items : It took 11.452458 seconds
[08-09-02 21:33:30.6889] Plugins::TrackStat::Storage::refreshTracks (1447) Starting to update unrated ratings in history table based on null
[08-09-02 21:33:30.7022] Plugins::TrackStat::Storage::refreshTracks (1467) Finished updating unrated ratings in history table based on null, updated 0 items : It took 0.013048 seconds

A bit slower than normal but not close to the performance decrease you saw in the corresponding Custom Scan refresh operation.

So far so good. I removed Custom Scan and did a rescan for changes and there was no bog down during or after it.

The TrackStat refresh seemed a bit long to and that also happens after rescan, but hopefully its fast enough so the Squeezebox buffering is able to compensate for it.

There is two option in "SqueezeCenter Settings/Plugins/TrackStat" called "Startup refresh" and "Rescan refresh" which can be used to disable the TrackStat refresh operation. So if you get problems due to the TrackStat refresh, you can use these options to disable it. The consequence of disabling it is that you will loose statistics and ratings for a track if you rename or move any music file. If you don't have musicbrainz tags in your music, you will always loose the statistics and rating when moving/renaming files independent if the refresh operation is active or not.

I don't think I even needed Custom Scan for what I thought I did anyway. I was doing some SQL playlists based on keywords. My Music Manager puts custom tags into the comment tag. I thought I needed Custom Scan to pick up those keywords, but I guess the comment field is picked up with a standard scan because my SQL playlist still works.

Comment field is picked up by standard SqueezeCenter scanning.
From the statistics you shown it looked like you had data in the "Rating Tag" scanning module use to retrieve ratings from tags, if this is something you use you probably just want to disable and clear the "Custom Tag" and "Mixed Tag" scanning modules.