7.6 slow initial query

[gharris999]

Just to be clear: it's not just the New Music query that's slow on startup. Here's My Muisic->Genres->German Baroque->Bach, J S:

[11-04-17 14:28:35.6570] Logging DB Access    >  0.05000s
[11-04-17 14:28:50.5123] DB Access    0.27662 : SELECT COUNT( * ) FROM albums me:
[11-04-17 14:28:56.6211] DB Access    6.10021 : SELECT COUNT( * ) FROM (SELECT me.id FROM contributors me LEFT JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id LEFT JOIN albums album ON album.id = contributorAlbums.album WHERE ( ( ( album.compilation IS NULL OR album.compilation = ? ) AND contributorAlbums.role IN ( ?, ? ) ) ) GROUP BY me.id) count_subq: '0', '1', '5'
[11-04-17 14:29:31.3924] DB Access    0.17556 : SELECT COUNT( * ) FROM (SELECT me.id FROM tracks me WHERE ( me.audio = ? ) GROUP BY me.id) count_subq: '1'
[11-04-17 14:29:32.1337] DB Access    0.17506 : SELECT COUNT( * ) FROM (SELECT me.id FROM tracks me WHERE ( me.audio = ? ) GROUP BY me.id) count_subq: '1'
[11-04-17 14:29:32.2099] DB Access    0.05405 : SELECT COUNT( * ) FROM (SELECT me.id FROM contributors me LEFT JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id LEFT JOIN albums album ON album.id = contributorAlbums.album WHERE ( ( ( album.compilation IS NULL OR album.compilation = ? ) AND contributorAlbums.role IN ( ?, ? ) ) ) GROUP BY me.id) count_subq: '0', '1', '5'
[11-04-17 14:29:41.1004] DB Access    0.13129 : SELECT COUNT( * ) FROM (SELECT me.id FROM tracks me WHERE ( me.audio = ? ) GROUP BY me.id) count_subq: '1'
[11-04-17 14:29:59.6141] DB Access   15.67782 : SELECT COUNT( * ) FROM (SELECT contributor.id FROM genres me JOIN genre_track genreTracks ON genreTracks.genre = me.id JOIN tracks track ON track.id = genreTracks.track JOIN albums album ON album.id = track.album JOIN contributor_track contributorTracks ON contributorTracks.track = track.id JOIN contributors contributor ON contributor.id = contributorTracks.contributor WHERE ( ( contributorTracks.role IN ( ?, ? ) AND ( ( album.compilation IS NULL OR album.compilation = ? ) AND me.id = ? ) ) ) GROUP BY contributor.id) count_subq: '1', '5', '0', '189'
[11-04-17 14:29:59.8249] DB Access    0.20446 : SELECT SUBSTR(contributor.namesort, 1, 1), COUNT( DISTINCT(contributor.id) ) FROM genres me LEFT JOIN genre_track genreTracks ON genreTracks.genre = me.id JOIN tracks track ON track.id = genreTracks.track JOIN albums album ON album.id = track.album LEFT JOIN contributor_track contributorTracks ON contributorTracks.track = track.id JOIN contributors contributor ON contributor.id = contributorTracks.contributor WHERE ( ( contributorTracks.role IN ( ?, ? ) AND ( ( album.compilation IS NULL OR album.compilation = ? ) AND me.id = ? ) ) ) GROUP BY SUBSTR(contributor.namesort, 1, 1) ORDER BY contributor.namesort COLLATE en_US : '1', '5', '0', '189'
[11-04-17 14:30:01.1113] DB Access    1.28037 : SELECT COUNT( * ) FROM (SELECT me.id FROM albums me LEFT JOIN tracks tracks ON tracks.album = me.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id WHERE ( ( genreTracks.genre = ? AND me.compilation = ? ) ) GROUP BY me.id) count_subq: '189', '1'
[11-04-17 14:30:01.3416] DB Access    0.21421 : SELECT contributor.id, contributor.name, contributor.namesort, contributor.musicmagic_mixable, contributor.namesearch, contributor.musicbrainz_id FROM genres me LEFT JOIN genre_track genreTracks ON genreTracks.genre = me.id JOIN tracks track ON track.id = genreTracks.track JOIN albums album ON album.id = track.album LEFT JOIN contributor_track contributorTracks ON contributorTracks.track = track.id JOIN contributors contributor ON contributor.id = contributorTracks.contributor WHERE ( ( contributorTracks.role IN ( ?, ? ) AND ( ( album.compilation IS NULL OR album.compilation = ? ) AND me.id = ? ) ) ) GROUP BY contributor.id ORDER BY contributor.namesort COLLATE en_US  LIMIT 26: '1', '5', '0', '189'
[11-04-17 14:30:01.4549] DB Access    0.08773 : SELECT COUNT( * ) FROM (SELECT track.id FROM genre_track me JOIN tracks track ON track.id = me.track WHERE ( me.genre = ? ) GROUP BY track.id) count_subq: '189'
[11-04-17 14:30:03.0110] DB Access    1.55243 : SELECT COUNT( * ) FROM (SELECT album.id FROM genre_track me JOIN tracks track ON track.id = me.track JOIN albums album ON album.id = track.album WHERE ( me.genre = ? ) GROUP BY album.id) count_subq: '189'
[11-04-17 14:30:03.1865] DB Access    0.16818 : SELECT COUNT( * ) FROM (SELECT contributor.id FROM genres me JOIN genre_track genreTracks ON genreTracks.genre = me.id JOIN tracks track ON track.id = genreTracks.track JOIN albums album ON album.id = track.album JOIN contributor_track contributorTracks ON contributorTracks.track = track.id JOIN contributors contributor ON contributor.id = contributorTracks.contributor WHERE ( ( contributorTracks.role IN ( ?, ? ) AND ( ( album.compilation IS NULL OR album.compilation = ? ) AND me.id = ? ) ) ) GROUP BY contributor.id) count_subq: '1', '5', '0', '189'
[11-04-17 14:30:06.7356] DB Access    0.08731 : SELECT COUNT( * ) FROM (SELECT album.id FROM contributors me JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id JOIN albums album ON album.id = contributorAlbums.album LEFT JOIN tracks tracks ON tracks.album = album.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id WHERE ( ( genreTracks.genre = ? AND ( contributorAlbums.role IN ( ?, ?, ? ) AND me.id = ? ) ) ) GROUP BY album.id) count_subq: '189', '1', '5', '6', '9186'
[11-04-17 14:30:06.8623] DB Access    0.12169 : SELECT SUBSTR(album.titlesort, 1, 1), COUNT( DISTINCT(album.id) ) FROM contributors me LEFT JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id JOIN albums album ON album.id = contributorAlbums.album LEFT JOIN tracks tracks ON tracks.album = album.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id WHERE ( ( genreTracks.genre = ? AND ( contributorAlbums.role IN ( ?, ?, ? ) AND me.id = ? ) ) ) GROUP BY SUBSTR(album.titlesort, 1, 1) ORDER BY 0 || album.titlesort COLLATE en_US : '189', '1', '5', '6', '9186'
[11-04-17 14:30:07.0107] DB Access    0.14177 : SELECT album.id, album.titlesort, album.contributor, album.compilation, album.year, album.artwork, album.disc, album.discc, album.musicmagic_mixable, album.titlesearch, album.replay_gain, album.replay_peak, album.musicbrainz_id, album.title FROM contributors me LEFT JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id JOIN albums album ON album.id = contributorAlbums.album LEFT JOIN tracks tracks ON tracks.album = album.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id WHERE ( ( genreTracks.genre = ? AND ( contributorAlbums.role IN ( ?, ?, ? ) AND me.id = ? ) ) ) GROUP BY album.id ORDER BY 0 || album.titlesort COLLATE en_US  LIMIT 159: '189', '1', '5', '6', '9186'
[11-04-17 14:30:08.2146] DB Access    0.08340 : SELECT COUNT( * ) FROM (SELECT tracks.id FROM contributors me JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id JOIN albums album ON album.id = contributorAlbums.album JOIN tracks tracks ON tracks.album = album.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id WHERE ( ( genreTracks.genre = ? AND ( contributorAlbums.role IN ( ?, ?, ? ) AND me.id = ? ) ) ) GROUP BY tracks.id) count_subq: '189', '1', '5', '6', '9186'
[11-04-17 14:30:08.2845] DB Access    0.06469 : SELECT COUNT( * ) FROM (SELECT album.id FROM contributors me JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id JOIN albums album ON album.id = contributorAlbums.album LEFT JOIN tracks tracks ON tracks.album = album.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id WHERE ( ( genreTracks.genre = ? AND ( contributorAlbums.role IN ( ?, ?, ? ) AND me.id = ? ) ) ) GROUP BY album.id) count_subq: '189', '1', '5', '6', '9186'
[11-04-17 14:30:08.3477] DB Access    0.05833 : SELECT COUNT( * ) FROM (SELECT contributor.id FROM contributors me JOIN contributor_album contributorAlbums ON contributorAlbums.contributor = me.id JOIN albums album ON album.id = contributorAlbums.album LEFT JOIN tracks tracks ON tracks.album = album.id LEFT JOIN genre_track genreTracks ON genreTracks.track = tracks.id JOIN contributors contributor ON contributor.id = album.contributor WHERE ( ( genreTracks.genre = ? AND ( contributorAlbums.role IN ( ?, ?, ? ) AND me.id = ? ) ) ) GROUP BY contributor.id) count_subq: '189', '1', '5', '6', '9186'

A 15 second delay just to fetch the artist list within a genre seems like a annoyance...even if it's just for the 1st query of the day.

One odd thing: Having started SBS from the command line as in the previous post, if I then exit SBS via a ctrl-c and then restart SBS, the initial query lag isn't nearly as pronounced. So it seems like there must be some OS involvement in this problem. With a cold OS start (or reboot), this problem seems to be exacerbated.

[JJZolx]

Would it make sense for SBS, on startup, to do some kind of 'seed' query on its own so we can get whatever work happens there out of the way?

Something tells me that if you tried to do this it would only block the server from being able to do anything for that same amount of time. In the end it probably wouldn't really make a difference, but if you're waiting for the server to come up, it could be even more annoying.

[Triode]

One odd thing: Having started SBS from the command line as in the previous post, if I then exit SBS via a ctrl-c and then restart SBS, the initial query lag isn't nearly as pronounced. So it seems like there must be some OS involvement in this problem. With a cold OS start (or reboot), this problem seems to be exacerbated.

The os may be able to cache the database file in memory if you are not doing anything else and it fits? This may explain the difference. Are you really restarting the OS from scratch each day? Sounds like the underlying problem is the performance of your server machine + size of your database...

[JJZolx]

It would be interesting to see whether or not you can elicit more than one really slow query, or if it really is just _one_ initial slow query. The query time appears to depend on the particular query that's run, but I wonder if additional queries continue to fill some kind of internal SQLite buffer or cache.

[JJZolx]

The os may be able to cache the database file in memory if you are not doing anything else and it fits? This may explain the difference.

If that were the case, wouldn't the initial stats queries (seen prior to the slow query in both examples above) be sufficient for the OS to pull the database file into memory?

[Phil Leigh]

I dont see anything like this sort of performance issue.. New Music takes <1 second immediately after SBS restart (XP, 40k tracks)

[gharris999]

The os may be able to cache the database file in memory if you are not doing anything else and it fits? This may explain the difference. Are you really restarting the OS from scratch each day? Sounds like the underlying problem is the performance of your server machine + size of your database...

Yep, everyday, this server runs some chores in the wee hours of the morning at 2:00 am and then reboots. It then goes into S3 sleep by 2:15 am and stays that way until iPeng WOLs it when I crawl out of bed. I've been noticing more and more over the past month or so that iPeng is unresponsive for a minute or more after it first wakes the server. It never behaves this way again until the next server reboot. My tests have proven to me that this is some kind of OS/SBS issue and has nothing to do with iPeng.

This server isn't particularly underpowered: Core2 Duo mobile CPU at 1.6ghz, 2 gigs of RAM, 60gig OS disk at 7200rpm.

The size of the squeezebox.db file is 184mb.

The installation is pretty plain-jane Ubuntu Server 10.04. Nothing exotic in the config.

[gharris999]

Something tells me that if you tried to do this it would only block the server from being able to do anything for that same amount of time. In the end it probably wouldn't really make a difference, but if you're waiting for the server to come up, it could be even more annoying.

Not annoying in my case, as it will run automatically at 2:15 am. My server spends most of its life in S3 sleep when it's not actively playing. When it does boot (or reboot), it's generally in those wee hours.

Additionally, that "seed" query only partially blocks. I just tested this with a playlist pre-loaded for my transporter. I rebooted the server and as soon as SBS was stared, I was able to start playing that playlist. The playlist continued to play while the "tracks 0 500 new" query was fired off in the background. True, I couldn't change tracks for those 46 seconds, but the the player continued playing...probably due to buffering in the transporter.

Since SrvrPowerCtrl defaults to waking the server up 5 minutes before alarms, even if it's waking from a cold shutdown, the "seed" query should be done in plenty of time so that it won't interfere with the alarm.

So, on balance, I'm thinking that the seed query is less annoying for me than the regular SBS behavior I'm seeing.

I'm not suggesting that my solution here is anything more than an ugly kludge. It will solve the problem for me, though.

[gharris999]

I dont see anything like this sort of performance issue.. New Music takes <1 second immediately after SBS restart (XP, 40k tracks)

So, this is probably more an OS than a SBS problem, per se. But, again, rather than SBS restart, what about after reboot? On XP, do you still get New Music in <1 second?

[Phil Leigh]

So, this is probably more an OS than a SBS problem, per se. But, again, rather than SBS restart, what about after reboot? On XP, do you still get New Music in <1 second?

well, that is very hard to measure... a lot happens during a reboot, most of which has nothing to do with SBS. I can't easily tell exactly when SBS is ready for the first query after a reboot.