Queries that take >10 sec from rsp protocol make Roku Soundbridges time out.

[jimmiedave]

Testing with a Roku M500 and an M2000, Browse By Album (and sometimes other browse types, depending on streaming server load and other stuff, I guess) times out on the Soundbridge (M2000 and M500) at about the 10 sec mark.

Testing rsp in a browser, the server appears to return valid and complete XML.

Library size is ~18,000 songs.

Server could probably have a faster CPU - it's a QNAP TS-119+ NAS device with an armel-type processor.

Running Debian Buster, with latest updates. Also on the server: mythtv-backend (with MySQL) and mediatomb DLNA server - neither of which are in heavy use. Most often it's forked-daapd, the OS and nothing else in particular running.

I found an online suggestion that adding sqlite3 indexes for the queries could speed things along, stop the timeouts. I think custom collations mean the forked-daapd code has to handle that.

Per request of ejurgensen here:

• https://www.raspberrypi.org/forums/viewtopic.php?f=66&t=49928&p=1256620#p1256620

...I'm including the logs for the various queries the Soudbridge (M2000 in this case) is running against forked-daapd, below.

There's no indication in the forked-daapd.log file that forked-daapd has taken any notice of the Soundbridge timing out. Looks like success there. (probably just shoves the result down the pipe with http and goes on).

---

Excerpts from forked-daapd.log, set on debug level.

Browse Albums: timed out on Soundbridge after 10 sec

[2018-01-11 19:19:48] [DEBUG] rsp: RSP request: /rsp/db/0/album?type=browse [2018-01-11 19:19:48] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT f.album) FROM files f WHERE f.disabled = 0 AND f.album != '';' [2018-01-11 19:19:55] [DEBUG] db: Starting query 'SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 AND f.album != '' GROUP BY f.album_sort ;' [2018-01-11 19:20:04] [DEBUG] db: End of query results [2018-01-11 19:20:04] [DEBUG] httpd: Gzipping response

Browse Artists: sometimes times out - right on the 10 sec border

[2018-01-11 19:20:05] [DEBUG] rsp: RSP request: /rsp/db/0/artist?type=browse [2018-01-11 19:20:05] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT f.album_artist) FROM files f WHERE f.disabled = 0 AND f.album_artist != '';' [2018-01-11 19:20:09] [DEBUG] db: Starting query 'SELECT f.album_artist, f.album_artist_sort FROM files f WHERE f.disabled = 0 AND f.album_artist != '' GROUP BY f.album_artist_sort ;' [2018-01-11 19:20:15] [DEBUG] db: End of query results [2018-01-11 19:20:15] [DEBUG] httpd: Gzipping response

Browse Songs: timed out this time - I think 'cause of logging.

[2018-01-11 19:20:22] [DEBUG] rsp: RSP request: /rsp/db/0?type=id [2018-01-11 19:20:22] [DEBUG] db: Running query 'SELECT COUNT() FROM files f WHERE f.disabled = 0;' [2018-01-11 19:20:22] [DEBUG] db: Starting query 'SELECT f. FROM files f WHERE f.disabled = 0 ;' /... many 'client advertises...no transcode needed' lines removed .../ [2018-01-11 19:20:51] [DEBUG] httpd: Gzipping response

Browse Genres: timed out this time - I think 'cause of logging

[2018-01-11 19:20:51] [DEBUG] rsp: RSP request: /rsp/db/0/genre?type=browse [2018-01-11 19:20:51] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT f.genre) FROM files f WHERE f.disabled = 0 AND f.genre != '';' [2018-01-11 19:20:53] [DEBUG] db: Starting query 'SELECT f.genre, f.genre FROM files f WHERE f.disabled = 0 AND f.genre != '' GROUP BY f.genre ;' [2018-01-11 19:20:54] [DEBUG] db: End of query results [2018-01-11 19:20:54] [DEBUG] httpd: Gzipping response

Browse Composers: worked

[2018-01-11 19:20:56] [DEBUG] rsp: RSP request: /rsp/db/0/composer?type=browse [2018-01-11 19:20:56] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT f.composer) FROM files f WHERE f.disabled = 0 AND f.composer != '';' [2018-01-11 19:20:57] [DEBUG] db: Starting query 'SELECT f.composer, f.composer_sort FROM files f WHERE f.disabled = 0 AND f.composer != '' GROUP BY f.composer_sort ;' [2018-01-11 19:21:00] [DEBUG] db: End of query results [2018-01-11 19:21:00] [DEBUG] httpd: Gzipping response

Browse Artists: worked this time

[2018-01-11 19:21:13] [DEBUG] rsp: RSP request: /rsp/db/0/artist?type=browse [2018-01-11 19:21:13] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT f.album_artist) FROM files f WHERE f.disabled = 0 AND f.album_artist != '';' [2018-01-11 19:21:18] [DEBUG] db: Starting query 'SELECT f.album_artist, f.album_artist_sort FROM files f WHERE f.disabled = 0 AND f.album_artist != '' GROUP BY f.album_artist_sort ;' [2018-01-11 19:21:23] [DEBUG] db: End of query results [2018-01-11 19:21:23] [DEBUG] httpd: Gzipping response

[ejurgensen]

Here is a little test I hope you can do:

1. Try to locate the file "forked-daapd-sqlext.so", usually located in something like /usr/lib/forked-daapd - then remember the location
2. As the forked-daapd user, run "sqlite3 /var/cache/forked-daapd/songs3.db"
3. Run ".load [location of forked-daapd-sqlext.so]"
4. Run "DROP INDEX idx_album;"
5. Run "CREATE INDEX idx_album ON files(disabled, album_sort, album);"
6. Now check the performance of the album browse

[chme]

I got curious and did some measuring.

With the old index: idx_album ON files(album, album_sort)

sqlite> SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 AND f.album != '' GROUP BY f.album_sort;
[...]
Run Time: real 2.172 user 2.010000 sys 0.090000

sqlite> EXPLAIN QUERY PLAN SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 AND f.album != '' GROUP BY f.album_sort;
0|0|0|SEARCH TABLE files AS f USING INDEX idx_albumartist (disabled=?)
0|0|0|USE TEMP B-TREE FOR GROUP BY

With the new index: idx_album ON files(disabled, album_sort, album)

sqlite> SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 AND f.album != '' GROUP BY f.album_sort;
[...]
Run Time: real 0.482 user 0.290000 sys 0.090000

sqlite> EXPLAIN QUERY PLAN SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 AND f.album != '' GROUP BY f.album_sort;
0|0|0|SEARCH TABLE files AS f USING COVERING INDEX idx_album (disabled=?)

The index definitely helps improving the performance of the SQL query. But the SQL query does look strange. If there are badly tagged files for the same album with album name is equal and album_sort is different, we will return the album multiple times. The other way around, for different albums with album_sort is equal and album name is different, we will return only one album.

I think, the query should be grouped by "album" and not by "album_sort" (i understand album_sort as an info field for the client for how to sort the results):

sqlite> SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 AND f.album != '' GROUP BY f.album;

The index should then look like idx_album ON files(disabled, album, album_sort).

The f.album != '' is unnecessary and could be dropped (during scan we make sure album is never emtpy).

[ejurgensen]

The query does look peculiar, but I am mostly wondering about the lack of ORDER BY. For daap, the server is expected to return ordered results, hence the "album_sort" field which has the purpose of providing natural sorting (so that "The Wall - disc 10" gets listed under W and after disc 9). Maybe RSP clients do their own sorting, but that must mean a significant performance hit. So I'm thinking that perhaps the ordering was forgotten in forked-daapd's RSP implemenation?

I think you are right that in most cases it is best to group by album, otherwise "A Whole World" and "The Whole World" would get listed as one album (because album_sort is "Whole World"), even though the albums are probably different. However, since the ORDER BY needs to be considered, we would need some other index than the above.

Also note that the function that builds the query is generic, so it also applies to composers, genres etc. I don't remember if some of those fields are allowed to be blank.

[chme]

Yes, forked-daapd does not set an order by clause in browse queries from rsp. Often the client machine has more computing power compared to the music server, that means it is not necessarily bad for performance to return unordered results.

If we take an order by clause into account, we could do something like

CREATE INDEX idx_album ON files(disabled, album_sort, album);
EXPLAIN QUERY PLAN SELECT f.album, f.album_sort FROM files f WHERE f.disabled = 0 GROUP BY f.album_sort, f.album ORDER BY f.album_sort, f.album;

SEARCH TABLE files AS f USING COVERING INDEX idx_album3 (disabled=?)

Without the additional sorting by album, sqlite3 uses an additional B-TREE for sorting:

SEARCH TABLE files AS f USING COVERING INDEX idx_album (disabled=?)
USE TEMP B-TREE FOR ORDER BY

Also note that the function that builds the query is generic, so it also applies to composers, genres etc. I don't remember if some of those fields are allowed to be blank.

From what i figured out (after a short look), only composer can be blank. And maybe it would be better to keep composer in line with e. g. artist and set "unknown composer" if it is missing?

[ejurgensen]

Yes, that sounds like a good way of doing it. Will check it out, maybe make a branch for @jimmiedave to try as well.

Often the client machine has more computing power compared to the music server, that means it is not necessarily bad for performance to return unordered results.

The server can do indexing and caching, so I think it is almost always better to do the sorting server-side.

[jimmiedave]

Fun hunt. forked-daapd-sqlext.so is in /usr/lib/arm-linux-gnueabi/forked-daapd here ;)

I ran the suggested index drop and create, and the index (which took a rough 6 seconds to create) brought the browse-album time down to about 6 seconds on the Soundbridge M2000. Stuff loaded up and it worked as expected! Really useful.

One thing I should note, now that the By Album query loads: I wonder if it would make sense to drop non-alphanum characters out for the collation - a different issue, I realize, but the first album that shows up on the Soundbridge is "everybody dies" (by Dramarama). I've seen this before (on mt-daapd, and in completely-unrelated MP3 players (like Power Amp for Android). It'd make sense to me to have "everybody dies" to show up under E, and #1 Record by Big Star to show up under 1.

Thanks all for your attention to the index thing!

[ejurgensen]

This is one of those changes where at first it seems simple and safe, and then when you look into it it is monsters all the way. Basically, I am afraid of introducing regressions, because a lot of this is the way it is because it has been adjusted and optimized over a number of years.

Doing as you suggest @chme requires adjusting the S_* sort clauses, which are used for much more than this query, and then also adjust a bunch of the indeces, plus adjust the generic query builder. Not saying it shouldn't be done, because it seems the browse queries in general could be optimized. Just has to be done really carefully.

Also I don't know if 6 seconds is even good enough? Doesn't that feel somewhat sluggish, @jimmiedave? Another approach would be to bring out the sledgehammer: The cache.

So I guess what I am saying is that I need to look more into it.

@jimmiedave I'm not sure I understood the last part you wrote? I think forked-daapd already drops non-alpha, but isn't the reason that you get a weird order that forked-daapd does no sorting for rsp, as discussed above?

[jimmiedave]

I understand about the fear of regressions.

6 seconds is quite tolerable, especially since the Soundbridges now work, vs. fail. I'll take 6. By the time I get to (doing the math: 18000*(10/6)...) 30,000 songs (assuming linear scalability) I'll have a faster NAS or assume I need one.

When a "Songs" query loads, you can see the information rolling in "NNNN items loaded", but on no other query does that appear to happen. I note that the Songs query is a different-looking beast than any other (at least in terms of the http request).

I've been accustomed to the loading wait for a long time. Faster would be nicer, of course, but what frustrations I have with the Soundbridge are more about not having a real "back" button, than about loading time. (i.e., Soundbridge doesn't hang on to the data from the last load, and moving to the next artist album in the data tree after you've played one appears to require reloading the whole browse category and navigating through it with the remote again).

re: sorting - I see - I thought the discussion on ORDER BY differences between DAAP and RSP was still a matter of investigation. I must've missed one of @chme 's posts.

Is there something that RSP delivers that DAAP does not? Since my Soundbridges (2 functioning and one in the boneyard) are all Roku devices, they're all Apple-licensed DAAP players (unlike Pinnacle-branded units). They can play directly from the iTunes library on a Mac through DAAP, and from mt-daapd/firefly/forked-daapd through DAAP as well. If DAAP gets me ordered results, is there a straightforward (i.e. in forked-daapd or avahi config file) way of turning off RSP service and letting the devices pick up DAAP only?

[ejurgensen]

I don't know much about the capabilities of RSP, but yes, you can try starting forked-daapd with the "--mdns-no-rsp" argument and see if it works better with daap. The option is not really documented anywhere, I will admit.

[jimmiedave]

Well, that's not gonna work. Running the server with --mdns-no-rsp I can verify (using Bonjour Browser - pretty old stuff, but it works) that my music server is not advertising RSP. The Soundbridge sees the DAAP server, but can't connect.

I'm not going to press this - you probably don't need to be spending time troubleshooting this for the dozen Soundbridge guys out there.

[ejurgensen]

Improved indexing of browse queries probably applies to daap as well, so that is actually good to get some attention on.

[ejurgensen]

I've worked a bit on this, and it would be great if you are able to test the changes I have made. I think you will see much better response times. The improvements are in this branch: https://github.com/ejurgensen/forked-daapd/tree/rsp_improvements1

@chme, it would also be great if you would review the changes. I am mainly worried about regressions, so I have tested with a number of clients using your dbprofile feature. That is great for reviewing which indices get used. Still rather boring to test this: I did it by comparing (filtered) spam-level log files from tests with and without the changes to see if any requests deteriorated. There is no rush on a review, I think I will save merging this to after the next release.

[ejurgensen]

Just to add: The changes also improve certain daap requests, e.g. genre and composer. Also think I saw some improved title requests.

[jimmiedave]

Will try it in the next day or two. I assume this is a git clone and configure, make, make install process?

[jimmiedave]

I'll need what, build-essential and kernel sources installed?

[ejurgensen]

Check the INSTALL file, it has build instructions for the most popular platforms

[jimmiedave]

Build in progress: tons of 'warning(24): template error:...' messages. You want the text, or is this expected?

[jimmiedave]

OK, here's the initial report:

You'll recall we (dropped-and-re)created index idx_album a while ago.

After leaving the server pretty much alone (using it for forked-daapd with iTunes front-end, and MythTV recording) since then, the Albums, Artists, Songs, Genres wouldn't load fast enough to avoid timeout on the Soundbridge M2000 this afternoon. This is with the Buster (Debian testing) repository version of forked-daapd.

After building the development version from a git clone (per instructions in INSTALL) , Browse Albums, Artists, Songs all time out on the Soundbridge M2000. Same build/installation works as expected in iTunes (though it takes a while to load up the libraries). Occasionally, I can get Genres to load up on the new build prior to timeout.

Must note that the QNAP TS-119+ NAS I'm running it on is ALSO recording the Olympics with MythTV. This shouldn't be a heavy-loading task, since it's just spooling MPEG2 from the network tuners and recording raw to the disk. Still, I'll make a doublecheck when it's not recording the Olympics.

[ejurgensen]

Did you build from the rsp_improvements1 branch? After git clone you need to "git checkout rsp_improvements1".

Don't worry about those template warnings during build.

[jimmiedave]

Ah - oops mode. Built the right branch now. Initial startup went from:

[2018-02-15 01:01:36] [ LOG] scan: Bulk library scan completed in 231 sec [2018-02-15 01:01:47] [ LOG] lib: Library init scan completed in 243 sec (0 changes)

to

[2018-02-15 10:13:13] [ LOG] scan: Bulk library scan completed in 217 sec [2018-02-15 10:13:19] [ LOG] lib: Library init scan completed in 223 sec (0 changes)

Informally, loading the DAAP library in iTunes sped up a couple seconds - from a counted-off 11 sec to 9 sec.

iTunes interaction with playlists feels very sprightly indeed. Nice.

On the Soundbrige (an M2000 for this test): Wow.

All of the "Browse" categories pop right up - a couple-three seconds at most. The biggest one: "Songs" (18000+ of them) comes in in two phases: 1: the Soundbridge is apparently loading from the server, and 2: the Soundbridge is maybe organizing them? That may not be correct, but unlike the other queries, it happens in two (visible) phases. The first phase takes maybe 4 seconds, and the second (where the Soundbridge is counting how many entries it has) takes another 3. I imagine that phase 1 could stretch to 10 seconds before timing out, allowing for libraries several times the size of mine on slow NAS devices.

For completeness' sake: the NAS wasn't doing any TV recording while this test was being run.

This is a stellar performance improvement. You have my gratitude!

[ejurgensen]

Very happy to hear this, thanks for the feedback. I expect to merge after next release, unless @chme finds some issues that need further work.

[jimmiedave]

Tested also on M500 and got similar results. One thing noted from the M500 is that the Browse Artists, et. al. queries appear to go even FASTER than pulling in the "all albums from artist n" or "all songs from album x" (from, I am guessing, a subset of albums by artist n).

So f.e. on the M500, an all-albums query might bring in thousands of items faster than the songs from an album or albums by an artist.

Checked a minute ago on the M2000, and I'd say that (by my informal count), the By Albums, By Artists queries come in just about the same as albums-by-artist-n or album-x-by-artist-n.

As far as I've always heard, the only differences between the Soundbridges released before the M1001 or the Soundbridge Radio was the display hardware - I wouldn't expect a big speed delta between the M2000 and M500. (in fact, I'd guess the M2000 has to render the font, so I'd expect it to be incrementally slower, though not much). Both the units are connected to the server via 1Gbps wired Ethernet (the Soundbridges are, I think 100Mbps).

I realize you don't wanna make individual indices for hundreds of artists, thousands of albums, but if there's other query optimization that's gone on, might be worth a look at applying to these.

The operation of the M500 at the current speed is just fine with me - it works great, and I don't really need a change. Just reporting results since you don't have these devices to test on.

Another note on the M500 - though this is not a tested item, but instead, an impression from listening in the background to the M500 for a couple hours: I heard a couple songs drop out for a couple seconds. Sounded like the music paused and resumed (vs. playing silently through the pause). I wasn't all over it at the time, and didn't grab a log from the experience; In fact, I'm just recalling it now. This hasn't happened in the past (with mt-daapd, f.e.). I don't think I've heard this on the M2000. Will keep an ear out and try and report back if/when I hear again.

[ejurgensen]

Thanks for sharing, it is quite possible that the queries for "by artist" and "by album" are slower. I might not do anything about it, but in any case it would great if you could grab the actual requests from the log, like you did above with the RSP browse requests. Then I will add them as documentation in the code, which would make it easier in the future to test the requests.

[ejurgensen]

Alright, I have now merged the fix into master, so I will close the issue. Thanks for your interest in forked-daapd.