Add a covering index on tracks (album_id, length)

lomereiter commented 6 months ago

The covering index also includes length, so that SQLite can avoid reading the rows.

In my experiments with the DB provided by @cascooscuro (see https://github.com/sentriz/gonic/issues/478), adding this index already helps to cut the query time from 2.8s to 1.0s. Replacing the join with subqueries cuts down the time further to 0.3s.

Query plan for the original query:

QUERY PLAN
|--SCAN albums
|--SEARCH album_artists USING COVERING INDEX idx_album_artists_album_id (album_id=?)
|--SEARCH tracks USING COVERING INDEX idx_tracks_album_id (album_id=?) LEFT-JOIN
`--USE TEMP B-TREE FOR ORDER BY

When using subqueries:

QUERY PLAN
|--SCAN albums
|--SEARCH album_artists USING COVERING INDEX idx_album_artists_album_id (album_id=?)
|--CORRELATED SCALAR SUBQUERY 1
|  `--SEARCH tracks USING COVERING INDEX idx_tracks_album_id (album_id=?)
|--CORRELATED SCALAR SUBQUERY 2
|  `--SEARCH tracks USING COVERING INDEX idx_tracks_album_id (album_id=?)
`--USE TEMP B-TREE FOR ORDER BY

fixes #478

sentriz commented 5 months ago

thanks! @cascooscuro can you confirm if the issue is solved when checking out this branch? with read timeouts removed

cascooscuro commented 5 months ago

Sometimes I still get a timeout, but only have seen it when connecting to jamstash the first time:

14:23:09 response  0  OPTIONS /getPodcasts.view?c=Jamstash&callback=angular.callbacks._4&f=jsonp&includeEpisodes=false&p=enc:12345678901234567&u=user&v=1.15.0
14:23:09 response  0  OPTIONS /getPlaylists.view?c=Jamstash&callback=angular.callbacks._2&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:10 response  0  OPTIONS /getMusicFolders.view?c=Jamstash&callback=angular.callbacks._0&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:09 response  0  OPTIONS /getIndexes.view?c=Jamstash&callback=angular.callbacks._1&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:09 response  0  OPTIONS /getGenres.view?c=Jamstash&callback=angular.callbacks._3&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:10 response  200  GET /getMusicFolders?c=Jamstash&callback=angular.callbacks._0&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:10 response  200  GET /getPlaylists?c=Jamstash&callback=angular.callbacks._2&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:10 response  200  GET /getGenres?c=Jamstash&callback=angular.callbacks._3&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
14:23:16 response  200  GET /getPodcasts?c=Jamstash&callback=angular.callbacks._4&f=jsonp&includeEpisodes=false&p=enc:12345678901234567&u=user&v=1.15.0
14:23:16 error writing subsonic response: write tcp 10.11.12.13:4747->10.11.12.13:39728: i/o timeout
14:23:16 response  200  GET /getIndexes?c=Jamstash&callback=angular.callbacks._1&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0

For the rest of the operations like search, play I see it responds much quicker and have not timeouts.

Maybe having the config option to modify the http timeout is good enough.

Thanks both for your help.

sentriz commented 5 months ago

hmm maybe I'll just bump the timeout to 10 secs globally

lomereiter commented 5 months ago

I'm assuming these calls come from here, and the timeout happens in getArtists: https://github.com/tsquillario/Jamstash/blob/master/app/subsonic/subsonic.js#L704-L709

I noticed that gonic reads entire artist_infos rows in the handler, whereas it needs just the image URL. I pushed a fix for this, hope it helps.

Also, the join with albums for checking the directory is quite expensive, so if you have just one music folder, it's best to avoid sending the musicFolderId parameter (hopefully there's a way to unset it in the client).

sentriz commented 5 months ago

@lomereiter thanks very much for the work here 👌👌 going to test and ship this shortly

also I think it makes sense to update the http logging middleware to print the response times for each request - making it easy for someone like @cascooscuro to identify endpoints which could be optimised for big libraries

cascooscuro commented 5 months ago

an update after the latest commit (https://github.com/sentriz/gonic/pull/508/commits/1c7cb8fe9cea4448676fcbdbf7ed2a2bb661e202):

gonic[639721]: 2024/05/31 09:50:02 response [0.000s]  0  OPTIONS /getIndexes.view?c=Jamstash&callback=angular.callbacks._1&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:02 response [0.000s]  0  OPTIONS /getGenres.view?c=Jamstash&callback=angular.callbacks._3&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:02 response [0.000s]  0  OPTIONS /getPodcasts.view?c=Jamstash&callback=angular.callbacks._4&f=jsonp&includeEpisodes=false&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:02 response [0.000s]  0  OPTIONS /getMusicFolders.view?c=Jamstash&callback=angular.callbacks._0&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:02 response [0.000s]  0  OPTIONS /getPlaylists.view?c=Jamstash&callback=angular.callbacks._2&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:10 response [8.489s]  200  GET /getMusicFolders?c=Jamstash&callback=angular.callbacks._0&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:10 response [8.490s]  200  GET /getPlaylists?c=Jamstash&callback=angular.callbacks._2&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:11 error writing subsonic response: write tcp 10.11.12.13:4747->10.11.12.13:42030: i/o timeout
gonic[639721]: 2024/05/31 09:50:11 response [9.045s]  200  GET /getGenres?c=Jamstash&callback=angular.callbacks._3&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:11 response [9.055s]  200  GET /getPodcasts?c=Jamstash&callback=angular.callbacks._4&f=jsonp&includeEpisodes=false&p=enc:12345678901234567&u=user&v=1.15.0
gonic[639721]: 2024/05/31 09:50:11 error writing subsonic response: write tcp 10.11.12.13:4747->10.11.12.13:42020: i/o timeout
gonic[639721]: 2024/05/31 09:50:11 response [9.102s]  200  GET /getIndexes?c=Jamstash&callback=angular.callbacks._1&f=jsonp&p=enc:12345678901234567&u=user&v=1.15.0

lomereiter commented 5 months ago

In my opinion, Jamstash is badly designed for big libraries, and there's only so much we can do on gonic side: right at the start Jamstash is simultaneously doing multiple heavy API calls.

Compare to Supersonic behavior, for example:

when you open it, it only loads the data needed for the current tab (album list, genres, and cover art)
it also uses offset and size parameters for the album list, loading more as you scroll
it loads the artists and their pictures when you switch to the artists tab

May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /ping?c=supersonic&f=xml&s=FsPmeTx6jG&t=7aa4d3e50bd520c5a5f84c32cad212de&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /ping?c=supersonic&f=xml&s=hUkuW622TX&t=a09615c3e0bb8f3f2ccb022a9212fe7a&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /ping?c=supersonic&f=xml&s=cp3e1AFHvK&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.015s]  200  GET /getAlbumList2?c=supersonic&f=xml&offset=0&s=cp3e1AFHvK&size=20&t=a6961f6381c0cf535bad86689a9d5ca3&type=newest&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.016s]  200  GET /getGenres?c=supersonic&f=xml&s=cp3e1AFHvK&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.001s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.001s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 subsonic error code 10: please provide an `id` parameter
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:49:58 localhost systemd-gonic[6961]: 2024/05/31 10:49:58 response [0.005s]  200  GET /getAlbumList2?c=supersonic&f=xml&offset=20&s=cp3e1AFHvK&size=20&t=a6961f6381c0cf535bad86689a9d5ca3&type=newest&u=admin&v=1.15.0
May 31 12:50:29 localhost systemd-gonic[6961]: 2024/05/31 10:50:29 response [0.017s]  200  GET /getArtists?c=supersonic&f=xml&s=cp3e1AFHvK&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:29 subsonic error code 10: please provide an `id` parameter
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 subsonic error code 10: please provide an `id` parameter
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 subsonic error code 10: please provide an `id` parameter
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 subsonic error code 10: please provide an `id` parameter
May 31 12:50:30 localhost systemd-gonic[6961]: 2024/05/31 10:50:30 response [0.000s]  200  GET /getCoverArt?c=supersonic&f=xml&id=&s=cp3e1AFHvK&size=300&t=a6961f6381c0cf535bad86689a9d5ca3&u=admin&v=1.15.0

lomereiter commented 5 months ago

I had yet another look at it, and added an index for the getIndexes query. However, the performance of this endpoint will remain suboptimal because GORM v1 runs two additional queries under the hood for Preload() - using left joins for this is possible only with GORM v2, migrating to which is anything but easy.

sentriz / gonic

Add a covering index on tracks (album_id, length) #508