Controller Performance Problem

[Mnyb]

Are your playlists stored on the NAS to ?
try to have to playlist directory on the server.

[CardinalFang]

Am glad to see that I am not the only one experiencing this!

My controller was really slow on most things until I changed from using a old PowerMac to a new MacBook Pro. Now things are really snappy, fast music selection and scrolling, music starts almost instantly etc. So despite the fact that you can run SC on a low end machine, it really benefits the whole system if you run it on some powerful hardware.

I know that's common sense, but since part of the appeal is that you can use old hardware, I assumed it wouldn't make too much of a difference - it does.

[cwinson]

Done some more testing with various setups and it looks like the problem is related to the location of the physical music files in relation to the squeezecenter

Mounting music via NAS seems to be causing the problem. If I copy to a local disk, things are much quicker - around 2 seconds to retrieve track level information as opposed to 10-15 when accessing via NAS.

So, next question.... what is SqueezeCenter actually doing behind the scenes and why does it take so long with NAS? Also interested to know why this is not cached locally during the scan.

[EliteAV]

My controller was really slow on most things until I changed from using a old PowerMac to a new MacBook Pro. Now things are really snappy, fast music selection and scrolling, music starts almost instantly etc. So despite the fact that you can run SC on a low end machine, it really benefits the whole system if you run it on some powerful hardware.

I know that's common sense, but since part of the appeal is that you can use old hardware, I assumed it wouldn't make too much of a difference - it does.

Its a sensible point, however, my controller is way over-specced for what it needs to do (Intel Dual core 2.6Ghz processors with 6MB cache, 3GB RAM etc) i.e. it can decode 1080p video (without hardware acceleration) with < 30% cpu utilisation, so the processing requirements from SqueezeCenter would be minimal in comparison. However, thanks for the thought.

Done some more testing with various setups and it looks like the problem is related to the location of the physical music files in relation to the squeezecenter

Mounting music via NAS seems to be causing the problem. If I copy to a local disk, things are much quicker - around 2 seconds to retrieve track level information as opposed to 10-15 when accessing via NAS.

So, next question.... what is SqueezeCenter actually doing behind the scenes and why does it take so long with NAS? Also interested to know why this is not cached locally during the scan.

I was beginning to suspect this may be the issue as most people probably arent using NAS drives and separate PCs (running SqueezeCenter). If they are using NAS drives (like the Infrant ReadyNAS I am using, they may be running SqueezeCenter on the NAS itself - which isnt an option for me, as it wouldnt be powerfull enough to transcode WMA files) or are using something like Windows Home Server with local storage.

As you say, it would be interesting to see what SqueezeCenter needs to retrieve from the media folders when just browsing music as it should have everything it needs (track listings, genre/artist info, album art etc) in it's local library (cache) until a specific track is selected for playback.

When I was setting up the list of exclusion folders for my Avast anti-virus software (as I thought this may have been the cause), I temporarily enabled the full info setting in Avast to show every file being scanned when I was using the SqueezeBox Controller (SBC) remote. This highlighted something interesting - when I selected an album on the SBC to view the track listings, SqueezeCenter was accessing the folder.jpg file on the media folders (i.e. on my NAS drive). I have no idea why it does this as it already has all of the album art in it's library. This could be a red herring but I suspect not.

Enabling logging in SqueezeCenter would confirm exactly which files are being accessed, but there are so many logging options, it is hard to know where to start!

Being able to hold all of music (& documents, other media etc) in a single centralised location (using a NAS) is a key requirement for me as this greatly simplifies file management/backup and I have already invested a fair amount of money in the NAS over the years to scrap this and move to Windows Home Server which would be powerfull to transcode WMA files and provide large amounts of local storage.

It would be good to get some feedback from one of the developers on exactly SqueezeCenter does when just browsing music.

[cwinson]

Agree - could really do with a response from someone who knows the code or know how to debug.

Ideally, I would be running SqueezeCenter on the NAS (RadyNAS NV+) which would presumably not encounter this issue (local disks). Problem is it runs like a dog compared to running on a PC - constantly locks up and cover art availability is intermittent. Admitedly, I've only got 256MB or RAM, but haven't seen anything that indicated if this is an issue.

[EliteAV]

I really should leave this alone;-) but I had a play with some of the SqueezeCenter logging settings to see if I could see what was causing this issue and the results are interesting.

I enabled these logging options:

Debug - (artwork) - Artwork Display & Matching
Debug - (database.info) - Metadata & Parsing Logging
Debug - (database.sql) - SQL Logging (Advanced)

I then selected an album on the SBC by Amy Macdonald called This Is the Life.

The following is an an extract from the server log:

[08-06-01 19:53:21.9695] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/02%20This%20Is%20the%20Life.wma
[08-06-01 19:53:21.9701] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\02 This Is the Life.wma]
[08-06-01 19:53:22.0781] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:22.7372] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:22.8136] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/03%20Poison%20Prince.wma
[08-06-01 19:53:22.8143] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\03 Poison Prince.wma]
[08-06-01 19:53:22.9164] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:23.5672] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:23.6284] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/04%20Youth%20of%20Today.wma
[08-06-01 19:53:23.6291] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\04 Youth of Today.wma]
[08-06-01 19:53:23.7209] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:24.3772] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:24.4504] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/05%20Run.wma
[08-06-01 19:53:24.4510] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\05 Run.wma]
[08-06-01 19:53:24.5470] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:25.2022] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:25.2707] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/06%20Let's%20Start%20a%20Band.wma
[08-06-01 19:53:25.2714] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\06 Let's Start a Band.wma]
[08-06-01 19:53:25.3623] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:26.0122] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:26.0711] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/07%20Barrowland%20Ballroom.wma
[08-06-01 19:53:26.0717] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\07 Barrowland Ballroom.wma]
[08-06-01 19:53:26.1644] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:26.8172] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:26.9072] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/08%20L.A.wma
[08-06-01 19:53:26.9078] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\08 L.A.wma]
[08-06-01 19:53:27.0046] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:27.6572] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:27.7369] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/09%20A%20Wish%20for%20Something%20More.wma
[08-06-01 19:53:27.7376] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\09 A Wish for Something More.wma]
[08-06-01 19:53:27.8277] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:28.4872] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:28.5592] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/10%20Footballer's%20Wife.wma
[08-06-01 19:53:28.5599] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\10 Footballer's Wife.wma]
[08-06-01 19:53:28.6460] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:29.3022] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

[08-06-01 19:53:29.3746] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/Amy%20MacDonald/This%20Is%20the%20Life/11%20The%20Road%20to%20Home.wma
[08-06-01 19:53:29.3753] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\Amy MacDonald\This Is the Life\11 The Road to Home.wma]
[08-06-01 19:53:29.4656] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\Amy MacDonald\This Is the Life
[08-06-01 19:53:30.1272] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\Amy MacDonald\This Is the Life\folder.jpg

From this you can see that SqueezeCenter is setting cover art *per track* using the folder.jpg file on the NAS rather than using album art from it's cache (generated by the previous music scan). Once it has the album art for a track it then performs a SQL UPDATE to store the path of this artwork file for the specified track in the cache/library (the SQL command to do this is ommitted from the above log trace for brevity).

Note: There are actually 11 tracks on the album, but SqueezeCenter doesnt perform the artwork lookup for the 1st track for some reason.

When the album is viewed for a subsequent time, the above process is not repeated hence the reason that it is much quicker.

So this proves why we see delays of approx 10 seconds for each album, the above operation takes about 1 second per track.

The question now is why doesnt the scanner set the album art for every track on an album as part of the library scanning process (when you wouldnt notice the 1 second cost per track etc)?

[cwinson]

Interesting results EliteAV. Definitely raises the question why this isn't done as part of the initial scan.

Looking at the time stamps, most of the time seems to be spent in searching for (code 264) and subsequently finding (code 352) the folder.jpg. Is this where the database updates which you mention are occuring?

Out of interest, did you notice anywhere how the scaling of the artwork takes place and whether this is cached? The controller interface has a number of different thumbnail sizes - album listing, now playing (2 sizes) and full screen. Keen to know how and when this is done - I'm seeing lots of sporadic issues with artwork when running SC on the ReadyNAS. If this can be fine tuned as well then it may be workable.

[Triode]

If you start the server from the command line with --perfwarn=0.5 then the server will log to the command line and the perfmon.log file anything taking more than half a second to complete. Does this show many things being logged and if so what?

[EliteAV]

Interesting results EliteAV. Definitely raises the question why this isn't done as part of the initial scan.

Looking at the time stamps, most of the time seems to be spent in searching for (code 264) and subsequently finding (code 352) the folder.jpg. Is this where the database updates which you mention are occuring?

No, the db update happens immediately after the code 352.

I havent looked into the artwork scaling yet. The majority of my artwork is 250x250 pixels, but I didnt adjust any of the defaults (i.e. image size, resampling etc) when I installed SqueezeCenter .

[EliteAV]

I just thought I would provide an update on some further investigation work I have been doing today.

Listed below is another snippet from the SC logfile when I selected an album by ABC on the controller (SBC):

[08-06-07 18:51:03.6787] Slim::Schema::Track::coverArt (271) Retrieving artwork for: file:////NAS600/media/my%20music/ABC/Traffic/02%20The%20Very%20First%20Time.wma
[08-06-07 18:51:03.6794] Slim::Music::Artwork::_readCoverArtTags (220) Looking for a cover art image in the tags of: [\\NAS600\media\my music\ABC\Traffic\02 The Very First Time.wma]
[08-06-07 18:51:03.7951] Slim::Music::Artwork::_readCoverArtFiles (264) Looking for image files in \\NAS600\media\my music\ABC\Traffic
[08-06-07 18:51:04.5691] Slim::Music::Artwork::_readCoverArtFiles (352) Found image file: \\NAS600\media\my music\ABC\Traffic\folder.jpg
[08-06-07 18:51:04.5700] Slim::Schema:ebug::query_start (26) UPDATE tracks SET cover = ? WHERE ( id = ? ): '\\NAS600\media\my music\ABC\Traffic\folder.jpg', '5210'

The key bit is the last line where you can see that SqueezeCenter is updating the COVER column in the TRACKS table (on the SLIMSERVER db) with the location of the cover/album art for track ID 5210 ("The Very First Time").

This suggested to me that it should be possible to create my own SQL script that would set the cover art for every track where the cover art was missing (in the db) i.e. TRACKS.COVER was NULL. This would then avoid the performance hit of SqueezeCenter doing this every time I selected an album on the controller (SBC).

As I wanted to have a look at the MySQL db schema, I used the MySQL Query Browser tool (from http://www.mysql.com/products/tools/query-browser/) and with this found the column on the TRACKS table that I could use to derive the filepath for the cover art:

SELECT T.URL FROM SLIMSERVER.TRACKS T WHERE T.ID=5210

Result:

file:////NAS600/media/my%20music/ABC/Traffic/02%20The%20Very%20First%20Time.wma

As all of my album art is held in \<artist>\<album>\folder.jpg files, all I needed to do was to set the location of this file based on the URL filepath for the track. After a bit of playing around, I came up with the following SQL statement:

UPDATE SLIMSERVER.TRACKS T SET T.COVER=REPLACE(CONCAT(SUBSTRING(SUBSTRING(T.URL,1 , LENGTH(T.URL)-LOCATE('/',REVERSE(T.URL))+1),LENGTH('File://')+1),'Folder.jpg'),'%20',' ')
WHERE T.ALBUM IS NOT NULL AND T.COVER IS NULL

Basically all this is doing is working from the end of the URL to find the lowest folder location, it then adds the "folder.jpg" to this folder path, then strips out the URL encoding stuff. I am sure that there are probably more elegant ways of doing this, but I hadnt used MySQL until today, so apologies if the SQL offends any of you MySQL gurus;-)


Anyway, after I had run this against the database (it updated approx 4000+ records in about 2 seconds), I verified it by selecting a dozen different albums on the controller and the track listing came back virtually instantaneously. I have some further testing to do but am very pleased with the results so far.

I will obviously need to run this whenever I add new music to the library but as it executes so quickly, this isnt a problem.

I should add that this workaround wont necessarily work as is for everyone who has the same performance issues (running SC on a separate PC from a NAS) as your music library may be organised differently. Plus, of course Logitech could change the db schema at any point (although this is probably unlikely on any great scale). However hopefully this may be of use to someone else.