subsonic slow refresh

[marco44]

Hi, I think there's a query that shouldn't be run while refreshing subsonic. My client (strawberry) does a getAlbum.view?id=album-7577&c=Strawberry&v=1.11.0&f=json&...

Each of those trigger this query:

SELECT
                                                "oc_music_genres"."id",
                                                "oc_music_genres"."name",
                                                "oc_music_genres"."lower_name",
                                                "oc_music_genres"."created",
                                                "oc_music_genres"."updated",
                                                COUNT("track"."id") AS "trackCount",
                                                COUNT(DISTINCT("track"."album_id")) AS "albumCount",
                                                COUNT(DISTINCT("track"."artist_id")) AS "artistCount"
                                        FROM "oc_music_genres"
                                        LEFT JOIN "oc_music_tracks" "track"
                                        ON "track"."genre_id" = "oc_music_genres"."id"
                                        WHERE "oc_music_genres"."user_id" = $1 AND "oc_music_genres"."id" = $2
                                        GROUP BY
                                                "oc_music_genres"."id",
                                                "oc_music_genres"."name",
                                                "oc_music_genres"."lower_name",
                                                "oc_music_genres"."created",
                                                "oc_music_genres"."updated"
                                        HAVING COUNT("track"."id") > 0 

I don't even see this count in the returned json. This query takes 40ms each time, and is run for each album, there are 10 000 of them. Sorry, I'm more of a dba type than a developer type, so I didn't look into the code. But as I don't see this data in the returned json, I think this query could be avoided.

[marco44]

By the way, I think getAlbumList2.view has the exact same problem

[paulijar]

Thanks for the report. What happens here is that the Subsonic controller creates a Genre object for each genre referred on the album. These objects are then used just to obtain the name of each of those genres, so indeed much of the information queried from the database is not actually used. And obviously it would be possible to optimize this by fetching just the genre names and not every field needed to construct the Genre object.

However, effect of this optimization on the perceived performance in your use case might not be all that great. There's so much overhead on each call to the ownCloud/Nextcloud server that 40 ms is just a small part of the execution time of the call. So even if the optimization could save e.g. 6 minutes on your 10k album collection (that's huge, btw), I expect that the process of calling getAlbum for each of the albums would still take at least half an hour. So the biggest problem here is that the Strawberry client wants to get the included tracks of all the albums up-front, while the Subsonic API is designed for way of working where tracks would be queried on-demand when expanding each album.

Now, the potential gains on the getAlbumList and getAlbumList2 would be much greater. There, one call may be used to obtain up to 500 albums and 40ms per album could pile up to 20 seconds. Meanwhile, the optimized call might well be less than 1 second (just a guesstimate).

[paulijar]

For what it is worth, I did some measurements on somewhat smaller mock-up library of around 60k tracks and 1500 albums. I compared the Music app as it is now, and a version where all the code related to the genre name fetching was commented out. For the action getAlbum, I couldn't really see the difference because the random variance of the execution time was way greater than the difference of these two versions. For getAlbumList with size=500, I saw the execution time to be mostly around 900 ms (but occasionally twice or thrice that much) for the unmodified code and around 700 ms with the genre name logic removed. So obviously, the unnecessary DB queries took a lot less than 40 ms each on this setup.

[marco44]

Ok, I've collected more stats. First, I'm using PostgreSQL, so I can use pg_stat_statements to have a higher level profile of what's occuring during this refresh. I have 4755 albums. According to the nginx log, GetAlbumList2 (all the iterations, with the offset parameter) ran for 290s, and getAlbum 175s, so a total of 465s. Here is what is consumed on the DB side (there's more lost to network round trip, parsing, etc…, here, it's only execution time, so after the query is parsed and the query plan computed):

nextcloud=# select calls, total_exec_time,query from pg_stat_statements order by total_exec_time desc limit 5;
-[ RECORD 1 ]---+-------------------------------------------------------------------------------------------------------
calls           | 9969
total_exec_time | 345887.40054400015
query           | SELECT                                                                                                +
                |                                         "oc_music_genres"."id",                                       +
                |                                         "oc_music_genres"."name",                                     +
                |                                         "oc_music_genres"."lower_name",                               +
                |                                         "oc_music_genres"."created",                                  +
                |                                         "oc_music_genres"."updated",                                  +
                |                                         COUNT("track"."id") AS "trackCount",                          +
                |                                         COUNT(DISTINCT("track"."album_id")) AS "albumCount",          +
                |                                         COUNT(DISTINCT("track"."artist_id")) AS "artistCount"         +
                |                                 FROM "oc_music_genres"                                                +
                |                                 LEFT JOIN "oc_music_tracks" "track"                                   +
                |                                 ON "track"."genre_id" = "oc_music_genres"."id"                        +
                |                                 WHERE "oc_music_genres"."user_id" = $1 AND "oc_music_genres"."id" = $2+
                |                                 GROUP BY                                                              +
                |                                         "oc_music_genres"."id",                                       +
                |                                         "oc_music_genres"."name",                                     +
                |                                         "oc_music_genres"."lower_name",                               +
                |                                         "oc_music_genres"."created",                                  +
                |                                         "oc_music_genres"."updated"                                   +
                |                                 HAVING COUNT("track"."id") > $3
-[ RECORD 2 ]---+-------------------------------------------------------------------------------------------------------
calls           | 483
total_exec_time | 12489.526041
query           | SELECT DISTINCT "album_id", "genre_id"                                                                +
                |                                 FROM "oc_music_tracks"                                                +
                |                                 WHERE "user_id" = $1                                                  +
                |                                 AND "genre_id" IS NOT NULL
-[ RECORD 3 ]---+-------------------------------------------------------------------------------------------------------
calls           | 483
total_exec_time | 12103.342172
query           | SELECT DISTINCT "track"."album_id", "track"."artist_id"                                               +
                |                                 FROM "oc_music_tracks" "track"                                        +
                |                                 WHERE "track"."user_id" = $1
-[ RECORD 4 ]---+-------------------------------------------------------------------------------------------------------
calls           | 483
total_exec_time | 11249.137420999989
query           | SELECT DISTINCT "track"."album_id", "track"."year"                                                    +
                |                                 FROM "oc_music_tracks" "track"                                        +
                |                                 WHERE "track"."user_id" = $1                                          +
                |                                 AND "track"."year" IS NOT NULL
-[ RECORD 5 ]---+-------------------------------------------------------------------------------------------------------
calls           | 483
total_exec_time | 11138.773510000006
query           | SELECT "album_id", MAX("disk") AS "disc_count"                                                        +
                |                                 FROM "oc_music_tracks"                                                +
                |                                 WHERE "user_id" = $1                                                  +
                |                                 GROUP BY "album_id"

[marco44]

Now that I think of it, maybe there is something else, do you have a genre that is much more frequent than all others ? (most of my collection has no genre set). This would explain a lot, because most of my counts mean counting almost the whole collection. EDIT: no, even this doesn't make a big diference, there is no index on tracks on the genre

[paulijar]

do you have a genre that is much more frequent than all others ?

Yes I do. As said, this is a mock-up library. It contains some 2000 real-life tracks on about 170 albums, and then some 60k copies of a single file with slight modifications. All of these copies have genre set to "Other". Indeed, it doesn't necessarily quite reflect the properties of a large real-life library.

My server is RaspberryPi 3 and your server is probably much more powerful. But still, your total execution times are surprisingly fast: if you can execute getAlbum 4755 times in 175 seconds, that leaves only 37 ms per call. For me, it's at least 200 ms per call. And if 35 ms (*) out of those 37 ms is used on a single SQL query, then that leaves next to nothing for everything else. Or is it possible that many of those getAlbum calls can be run in parallel, so actually CPU time used is much more than 175 seconds?

Anyway, I'm not certain if any extra investigation would be worth the effort. It's probably easiest if I optimize out this one query, and you can retest with the next release (or a development version if you are eager).

(*) From your table, 345887 ms / 9969

[paulijar]

Okay, I found one more relevant piece of information while testing an initial optimized version: It turned out that I had query caching enabled on MySQL and this made wonders for the performance of the getAlbumList2 (at least). After I disabled the caching, I could no longer run the action with size=500 within the one minute connection timeout. The similar query with size=100 took around 30 seconds. With the optimized version, the query with size=100 took 4 seconds.

So it seems that the query caching is very useful but may also provide misleading information about the actual performance of the DB queries.

[marco44]

Yeah, and query caching is only useful in very rare cases, most of the time it's not really recommended on production servers: as soon as the data changes a lot, it costs more to maintain and discard than it saves. That's why most databases don't have one.

I'm interested in testing a development version, to confirm the problem is fixed with PG too, but I see no new commit on any branches here. Where do I find it ? :)

[paulijar]

query caching is only useful in very rare cases

Yep, this is probably true generally speaking, but this occasion was one of those rare cases. This case of getAlbumList was like made for query caching: the same or similar query was run thousands of times in a row and the content of the target tables changed rarely.

Where do I find it ?

It wasn't yet anywhere except on my work area, as I wanted to do some more testing first. But now you can find it from the master branch. Compared to the release v1.2.1, the branch contains also a few small front-end tweaks. To use these, you would need to build the webpack distributables from the sources. But if you don't care about them for now, then you should be fine just replacing the lib folder of the latest release with the one from the master branch.

[marco44]

Ok, it's better (the getAlbum is good), but now I have this loop during the getAlbumList2:

2021-07-28 14:06:25.119 CEST [1697947] owncloud@nextcloud LOG:  duration: 24.062 ms  execute <unnamed>: SELECT DISTINCT "track"."album_id", "track"."artist_id"
                                        FROM "oc_music_tracks" "track"
                                        WHERE "track"."user_id" = $1 
2021-07-28 14:06:25.119 CEST [1697947] owncloud@nextcloud DETAIL:  parameters: $1 = 'marc'
2021-07-28 14:06:25.148 CEST [1697947] owncloud@nextcloud LOG:  duration: 21.110 ms  execute <unnamed>: SELECT DISTINCT "track"."album_id", "track"."year"
                                        FROM "oc_music_tracks" "track"
                                        WHERE "track"."user_id" = $1
                                        AND "track"."year" IS NOT NULL 
2021-07-28 14:06:25.148 CEST [1697947] owncloud@nextcloud DETAIL:  parameters: $1 = 'marc'
2021-07-28 14:06:25.174 CEST [1697947] owncloud@nextcloud LOG:  duration: 21.551 ms  execute <unnamed>: SELECT "album_id", MAX("disk") AS "disc_count"
                                        FROM "oc_music_tracks"
                                        WHERE "user_id" = $1
                                        GROUP BY "album_id" 
2021-07-28 14:06:25.174 CEST [1697947] owncloud@nextcloud DETAIL:  parameters: $1 = 'marc'
2021-07-28 14:06:25.217 CEST [1697947] owncloud@nextcloud LOG:  duration: 37.359 ms  execute <unnamed>: SELECT DISTINCT "album_id", "genre_id", "oc_music_genres"."name" AS "genre_name"
                                        FROM "oc_music_tracks"
                                        LEFT JOIN "oc_music_genres"
                                        ON "genre_id" = "oc_music_genres"."id"
                                        WHERE "oc_music_tracks"."user_id" = $1
                                        AND "genre_id" IS NOT NULL 
2021-07-28 14:06:25.217 CEST [1697947] owncloud@nextcloud DETAIL:  parameters: $1 = 'marc'
2021-07-28 14:06:25.336 CEST [1697947] owncloud@nextcloud LOG:  duration: 12.953 ms  execute <unnamed>: SELECT "oc_music_albums".*, "artist"."name" AS "album_artist_name"
                                        FROM "oc_music_albums"
                                        INNER JOIN "oc_music_artists" "artist"
                                        ON "oc_music_albums"."album_artist_id" = "artist"."id"
                                        WHERE "oc_music_albums"."user_id" = $1 ORDER BY LOWER("oc_music_albums"."name") LIMIT 10 OFFSET 4828

But these are much more minor, the DB load is much lower. Still, those queries are executed, in a loop, returning the exact same records (why don't we pass only the album_ids we're interested in ?). It seems most of the time is spent in PHP now.

[marco44]

Anyway I'm down from 465s (8 minutes) to about 4, which is not that bad for an improvement :)

[paulijar]

why don't we pass only the album_ids we're interested in ?

That's actually a good question. There was a small oversight on my behalf, and the code was fetching the "extra fields" to be attached to the Album objects for all the albums owned by the user even when only a subset of those albums had been requested by the client. This is fixed now, and on my test setup, the execution time of getAlbumList2 with size=500 was still about halved from ~4.5s to a bit over 2s. With smaller size values the relative effect is even greater.

[marco44]

It's faster here too. Is there a place I can change the fetch size ?

[paulijar]

Strawberry Music Player seems to call getAlbumList2 without specifying the size argument. This means that the default patch size of 10 albums is used (as dictated by the Subsonic API specification). As the player anyways wants to get all the albums, it would make much more sense to pass the maximum allowed value size=500. If you want to test other patch sizes, you could modify the default value here: https://github.com/owncloud/music/blob/6d12fc05d4a56a9d60eb2fe37a96fedf68e33cda/lib/Controller/SubsonicController.php#L1212

Or you could call the API directly on your web browser using a URL which would be something like https:///<your_cloud_address>/index.php/apps/music/subsonic/rest/getAlbumList2.view?type=alphabeticalByName&offset=0&size=500&c=any_client_name&v=1.11.0&f=json&u=<your_user_name>&p=<your_api_key>

[marco44]

Ok, that's what I tried. I thought maybe there was a way to override it in a configuration file, because it's going to be lost at next update... Anyway, yes, fetching the album list this way is much faster, as the pagination isn't very efficient, using limit (but there's probably no other way to do it, given the API)

[paulijar]

The optimizations discussed here have now been published as part of the Music v1.3.1.