Speed up librespot by using flexible download strategies

[kaymes]

Users with a slower internet connection report long load times of 10 seconds or more until playback commences whereas the official Spotify client does the job in less than a second.

In PR #297 (Improve playback speed), I mentioned, that I would like to further speed up the start of playback of librespotify to make it comparable to the official client.

I'm opening this issue to discuss ideas and possibilities for speeding this up and also ask some questions I have about understanding the librespot code I would like to mess around with.

Background information:

I should probably explain a little about how librespot opens a stream.
On the lowest level, the stream gets divided in chunks of 128KB. Whenever the vorbis player attempts to do a read access, the required chunk is downloaded. If no chunk is being requested, the next missing chunk following the last one that was read from is downloaded. It is only possible to read from chunks that have been downloaded in full.

When doing a seek() over the audio stream, the vorbis code does a bisect. That is, it always checks the timestamp of the middle of the seek interval and then decides which half of the interval is the next interval until it finds the correct location.

Note: This division in 128K chunks is librespot's decision. The protocol allows for arbitrary chunk sizes to be downloaded. As an experiment, I lowered the chunk size to 10K and the load time was almost halved. However, I fear, such small chunks can easily lead to throughput errors. And there's also the possibility that Spotify starts to hate us for hammering their servers with too many small requests.

Ideas:

I have some ideas how to speed things up. I'm not necessarily planning to pursue all of them, but I reckon, ideas 1)+2) are pretty much the first step because I think they have the biggest impact and are pretty much prerequisite for the others.

1. The first and basic idea for all that follows is, that the fixed chunk size should be done away with. Instead blocks of varying size should be downloaded. This could be implemented by making the internal chunk size very small (e.g. 1KB) and then downloading a range of chunks when requesting data from the server. This allows us to implement more flexible download strategies.

2. One idea would be to start with a small number of chunks when starting to read the file and then incrementally increase the number of chunks read per request. This would cater for quick reads during seek() and at the start of playback whereas the grunt of the file is downloaded with larger chunks that are better for throughput.

3. Partially downloaded requests could be made available. If we download a range of chunks, we could make the partial range that has been received available for read which the rest is still trickling through the line.

4. The download heuristic could be made aware of whether the access is due to seek or for playback and then optimise it's strategy accordingly. E.g. during seek it doesn't make much sense to read-ahead to the next chunk because we're jumping around in a random access pattern whereas in playback mode, read-ahead is awesome.

5. Vorbis seek could be improved. Instead of doing a blind bisect, we could try to predict where the correct timestamp is. If Spotify songs are encoded with constant bitrate (are they?), it should be possible to predict a timestamp's location in the file reasonably well and jump directly to the position we're interested in (or at least to somewhere close by and then fine tune with only few further reads).

6. Vorbis' seek could be made aware of which chunks have been downloaded already. Then, the seek() could be optimised to first exploit information that has been downloaded already before requesting new chunks. This could be useful together with idea 5) if the jump prediction isn't too accurate.

7. If I saw it correctly, the connection to the spotify server is some sort of multiplexing of multiple requests. Thus, we could download multiple chunks in parallel. This might be an option if we have issues with sufficient bandwidth but long ping times.

Experiments:

I made a special built of librespot with additional log messages to see what is happening during the load phase. I manually removed log lines to only keep the ones that show how the file is loaded and accessed. The log messages are timestamped by piping them through "ts".

The test below was done on an ADSL line (18396 Kbps down link) in Sydney, Australia and it took 11 seconds to load the track. On the same connection, the official client typically starts playback for similar tasks in less than a second, rarely it takes 1-2 seconds. (times for official client are estimated).

The song I'm loading here is 5:14 minutes long and standard 160K quality is used. About the first 10-11 seconds of the song where played on my phone before librespot was selected as device, so librespot needs to search for the correct starting point before playback. (The optimisation from PR#297 which avoids seek() when playing from the beginning doesn't work here).
The song is split into 48 of the 128K chunks, numbered from 0 to 47.

What can be seen is that it takes about 1.6 seconds to download a chunk. Seven chunks are downloaded which is 896 KB of data before playback can commence. And pretty much all the time goes into downloading those chunks.

The "requesting chunk" messages are created at the first line of fetch.rs::request_chunk().
The "chunk...complete" messages are created by fetch.rs::AudioFileFetch::poll() just before the chunk is marked as complete in the bitmap.
The "reading at" lines are created by AudioFileStreaming::read() before accessing the bitmap. The position is the absolute position in the file, the chunk is the chunk number the position is in, the offset is the position inside the chunk and length is the value of the variable "len" (=requested length to read but potentially truncated at chunk boundaries).

What can be seen is, that at first, the header of the file is examined (bunch of reads in chunk 0). Then, the vorbis seek starts its bisect and reads in blocks 46, 23, 11, 5, 2, 1, 0, 1 until it finds what it is looking for.

It can also be seen, that the code requests follow-up blocks. However, their download seems to get cancelled when another block is requested. I don't know what the performance penalty for requesting and cancelling a block is.

I also repeated this test for a built with a block size of 10KB. A chunk downloads in about 0.3 seconds and the total time to load the file went was about 6 seconds. I'm not showing the detailed log here since I don't think it adds much value.

16:46:04.720474 INFO:librespot_playback::player: Loading track "Das Boot" with Spotify URI "spotify:track:0yMIs70Fr4pd8f4KV6jmHC"
16:46:04.721564 DEBUG:librespot_audio::fetch: Downloading file 7b55430940cc657a5d78e22f3e0fda74f4ddb3ec
16:46:04.721812 TRACE:librespot_audio::fetch: requesting chunk 0
16:46:05.133794 DEBUG:librespot_audio::fetch: reading at postion 144 (chunk 0 offset 144 length  4)
16:46:06.989312 TRACE:librespot_audio::fetch: chunk 0 / 48 complete
16:46:06.989882 TRACE:librespot_audio::fetch: requesting chunk 1
16:46:06.990071 DEBUG:librespot_audio::fetch: reading at postion 148 (chunk 0 offset 148 length  4)
16:46:06.990245 DEBUG:librespot_audio::fetch: reading at postion 152 (chunk 0 offset 152 length  4)
16:46:06.990389 DEBUG:librespot_audio::fetch: reading at postion 156 (chunk 0 offset 156 length  4)
16:46:06.991221 DEBUG:librespot_audio::fetch: reading at postion 167 (chunk 0 offset 167 length  27)
16:46:06.991332 DEBUG:librespot_audio::fetch: reading at postion 194 (chunk 0 offset 194 length  1)
16:46:06.991446 DEBUG:librespot_audio::fetch: reading at postion 195 (chunk 0 offset 195 length  30)
16:46:06.993144 DEBUG:librespot_audio::fetch: reading at postion 225 (chunk 0 offset 225 length  27)
16:46:06.993329 DEBUG:librespot_audio::fetch: reading at postion 252 (chunk 0 offset 252 length  18)
16:46:06.993478 DEBUG:librespot_audio::fetch: reading at postion 270 (chunk 0 offset 270 length  4241)
16:46:07.043253 DEBUG:librespot_audio::fetch: reading at postion 167 (chunk 0 offset 167 length  27)
16:46:07.043378 DEBUG:librespot_audio::fetch: reading at postion 194 (chunk 0 offset 194 length  1)
16:46:07.043404 DEBUG:librespot_audio::fetch: reading at postion 195 (chunk 0 offset 195 length  30)
16:46:07.043452 TRACE:librespot_audio::fetch: requesting chunk 47
16:46:07.043492 DEBUG:librespot_audio::fetch: reading at postion 6051264 (chunk 46 offset 21952 length  27)
16:46:07.043511 TRACE:librespot_audio::fetch: requesting chunk 46
16:46:08.655732 TRACE:librespot_audio::fetch: chunk 46 / 48 complete
16:46:08.655878 TRACE:librespot_audio::fetch: requesting chunk 47
16:46:08.655936 DEBUG:librespot_audio::fetch: reading at postion 6051291 (chunk 46 offset 21979 length  1024)
16:46:08.656032 DEBUG:librespot_audio::fetch: reading at postion 6052315 (chunk 46 offset 23003 length  1024)
16:46:08.656328 DEBUG:librespot_audio::fetch: reading at postion 6052657 (chunk 46 offset 23345 length  23)
16:46:08.656392 DEBUG:librespot_audio::fetch: reading at postion 6052680 (chunk 46 offset 23368 length  4147)
16:46:08.657021 DEBUG:librespot_audio::fetch: reading at postion 3025715 (chunk 23 offset 11059 length  27)
16:46:08.657076 TRACE:librespot_audio::fetch: requesting chunk 23
16:46:09.987398 TRACE:librespot_audio::fetch: chunk 23 / 48 complete
16:46:09.987545 TRACE:librespot_audio::fetch: requesting chunk 24
16:46:09.987586 DEBUG:librespot_audio::fetch: reading at postion 3025742 (chunk 23 offset 11086 length  1024)
16:46:09.987775 DEBUG:librespot_audio::fetch: reading at postion 3026363 (chunk 23 offset 11707 length  31)
16:46:09.987806 DEBUG:librespot_audio::fetch: reading at postion 3026394 (chunk 23 offset 11738 length  4320)
16:46:09.988499 DEBUG:librespot_audio::fetch: reading at postion 1512941 (chunk 11 offset 71149 length  27)
16:46:09.988563 TRACE:librespot_audio::fetch: requesting chunk 11
16:46:11.489907 TRACE:librespot_audio::fetch: chunk 11 / 48 complete
16:46:11.490104 DEBUG:librespot_audio::fetch: reading at postion 1512968 (chunk 11 offset 71176 length  1024)
16:46:11.490154 DEBUG:librespot_audio::fetch: reading at postion 1513992 (chunk 11 offset 72200 length  1024)
16:46:11.490344 DEBUG:librespot_audio::fetch: reading at postion 1515016 (chunk 11 offset 73224 length  1024)
16:46:11.490583 DEBUG:librespot_audio::fetch: reading at postion 1515528 (chunk 11 offset 73736 length  25)
16:46:11.490629 DEBUG:librespot_audio::fetch: reading at postion 1515553 (chunk 11 offset 73761 length  4172)
16:46:11.490738 TRACE:librespot_audio::fetch: requesting chunk 12
16:46:11.491218 TRACE:librespot_audio::fetch: requesting chunk 5
16:46:12.942223 TRACE:librespot_audio::fetch: chunk 5 / 48 complete
16:46:12.942440 TRACE:librespot_audio::fetch: requesting chunk 6
16:46:12.942518 DEBUG:librespot_audio::fetch: reading at postion 756581 (chunk 5 offset 101221 length  1024)
16:46:12.942676 DEBUG:librespot_audio::fetch: reading at postion 757605 (chunk 5 offset 102245 length  1024)
16:46:12.943092 DEBUG:librespot_audio::fetch: reading at postion 757891 (chunk 5 offset 102531 length  22)
16:46:12.943203 DEBUG:librespot_audio::fetch: reading at postion 757913 (chunk 5 offset 102553 length  4384)
16:46:12.944330 DEBUG:librespot_audio::fetch: reading at postion 378360 (chunk 2 offset 116216 length  27)
16:46:12.944375 TRACE:librespot_audio::fetch: requesting chunk 2
16:46:14.456140 TRACE:librespot_audio::fetch: chunk 2 / 48 complete
16:46:14.456622 TRACE:librespot_audio::fetch: requesting chunk 3
16:46:14.456811 DEBUG:librespot_audio::fetch: reading at postion 378387 (chunk 2 offset 116243 length  1024)
16:46:14.457342 DEBUG:librespot_audio::fetch: reading at postion 379411 (chunk 2 offset 117267 length  1024)
16:46:14.458197 DEBUG:librespot_audio::fetch: reading at postion 380435 (chunk 2 offset 118291 length  1024)
16:46:14.458949 DEBUG:librespot_audio::fetch: reading at postion 381459 (chunk 2 offset 119315 length  1024)
16:46:14.459958 DEBUG:librespot_audio::fetch: reading at postion 381685 (chunk 2 offset 119541 length  18)
16:46:14.460219 DEBUG:librespot_audio::fetch: reading at postion 381703 (chunk 2 offset 119559 length  4431)
16:46:14.461515 DEBUG:librespot_audio::fetch: reading at postion 189263 (chunk 1 offset 58191 length  27)
16:46:14.461587 TRACE:librespot_audio::fetch: requesting chunk 1
16:46:15.717791 TRACE:librespot_audio::fetch: chunk 1 / 48 complete
16:46:15.718019 TRACE:librespot_audio::fetch: requesting chunk 3
16:46:15.718057 DEBUG:librespot_audio::fetch: reading at postion 189290 (chunk 1 offset 58218 length  1024)
16:46:15.718196 DEBUG:librespot_audio::fetch: reading at postion 190314 (chunk 1 offset 59242 length  1024)
16:46:15.718505 DEBUG:librespot_audio::fetch: reading at postion 190893 (chunk 1 offset 59821 length  20)
16:46:15.718700 DEBUG:librespot_audio::fetch: reading at postion 190913 (chunk 1 offset 59841 length  4080)
16:46:15.719533 DEBUG:librespot_audio::fetch: reading at postion 94715 (chunk 0 offset 94715 length  27)
16:46:15.719802 DEBUG:librespot_audio::fetch: reading at postion 94742 (chunk 0 offset 94742 length  1024)
16:46:15.719994 DEBUG:librespot_audio::fetch: reading at postion 95766 (chunk 0 offset 95766 length  1024)
16:46:15.720118 DEBUG:librespot_audio::fetch: reading at postion 96790 (chunk 0 offset 96790 length  1024)
16:46:15.720355 DEBUG:librespot_audio::fetch: reading at postion 97814 (chunk 0 offset 97814 length  1024)
16:46:15.720690 DEBUG:librespot_audio::fetch: reading at postion 97861 (chunk 0 offset 97861 length  22)
16:46:15.720761 DEBUG:librespot_audio::fetch: reading at postion 97883 (chunk 0 offset 97883 length  4351)
16:46:15.721565 DEBUG:librespot_audio::fetch: reading at postion 141989 (chunk 1 offset 10917 length  27)
16:46:15.721677 DEBUG:librespot_audio::fetch: reading at postion 142016 (chunk 1 offset 10944 length  1024)
16:46:15.721736 DEBUG:librespot_audio::fetch: reading at postion 143040 (chunk 1 offset 11968 length  1024)
16:46:15.721923 DEBUG:librespot_audio::fetch: reading at postion 144064 (chunk 1 offset 12992 length  1024)
16:46:15.722196 DEBUG:librespot_audio::fetch: reading at postion 144169 (chunk 1 offset 13097 length  20)
16:46:15.722219 DEBUG:librespot_audio::fetch: reading at postion 144189 (chunk 1 offset 13117 length  4141)
16:46:15.722918 DEBUG:librespot_audio::fetch: reading at postion 165626 (chunk 1 offset 34554 length  27)
16:46:15.723012 DEBUG:librespot_audio::fetch: reading at postion 165653 (chunk 1 offset 34581 length  1024)
16:46:15.723104 DEBUG:librespot_audio::fetch: reading at postion 166677 (chunk 1 offset 35605 length  1024)
16:46:15.723302 DEBUG:librespot_audio::fetch: reading at postion 167701 (chunk 1 offset 36629 length  1024)
16:46:15.723455 DEBUG:librespot_audio::fetch: reading at postion 168725 (chunk 1 offset 37653 length  1024)
16:46:15.723699 DEBUG:librespot_audio::fetch: reading at postion 169749 (chunk 1 offset 38677 length  1024)
16:46:15.723842 DEBUG:librespot_audio::fetch: reading at postion 169911 (chunk 1 offset 38839 length  22)
16:46:15.723883 DEBUG:librespot_audio::fetch: reading at postion 169933 (chunk 1 offset 38861 length  4303)
16:46:15.724541 DEBUG:librespot_audio::fetch: reading at postion 153807 (chunk 1 offset 22735 length  27)
16:46:15.724634 DEBUG:librespot_audio::fetch: reading at postion 153834 (chunk 1 offset 22762 length  1024)
16:46:15.724703 DEBUG:librespot_audio::fetch: reading at postion 154858 (chunk 1 offset 23786 length  1024)
16:46:15.724868 DEBUG:librespot_audio::fetch: reading at postion 155882 (chunk 1 offset 24810 length  1024)
16:46:15.725018 DEBUG:librespot_audio::fetch: reading at postion 156906 (chunk 1 offset 25834 length  15)
16:46:15.725047 DEBUG:librespot_audio::fetch: reading at postion 156921 (chunk 1 offset 25849 length  26)
16:46:15.725087 DEBUG:librespot_audio::fetch: reading at postion 156947 (chunk 1 offset 25875 length  4290)
16:46:15.725816 DEBUG:librespot_audio::fetch: reading at postion 159716 (chunk 1 offset 28644 length  27)
16:46:15.725838 DEBUG:librespot_audio::fetch: reading at postion 159743 (chunk 1 offset 28671 length  1024)
16:46:15.725896 DEBUG:librespot_audio::fetch: reading at postion 160767 (chunk 1 offset 29695 length  1024)
16:46:15.726139 DEBUG:librespot_audio::fetch: reading at postion 161264 (chunk 1 offset 30192 length  22)
16:46:15.726161 DEBUG:librespot_audio::fetch: reading at postion 161286 (chunk 1 offset 30214 length  4331)
16:46:15.726828 DEBUG:librespot_audio::fetch: reading at postion 162671 (chunk 1 offset 31599 length  27)
16:46:15.726849 DEBUG:librespot_audio::fetch: reading at postion 162698 (chunk 1 offset 31626 length  1024)
16:46:15.726917 DEBUG:librespot_audio::fetch: reading at postion 163722 (chunk 1 offset 32650 length  1024)
16:46:15.727070 DEBUG:librespot_audio::fetch: reading at postion 164746 (chunk 1 offset 33674 length  1024)
16:46:15.727314 DEBUG:librespot_audio::fetch: reading at postion 165644 (chunk 1 offset 34572 length  22)
16:46:15.727358 DEBUG:librespot_audio::fetch: reading at postion 165666 (chunk 1 offset 34594 length  4218)
16:46:15.727967 INFO:librespot_playback::player: Track "Das Boot" loaded

[kaymes]

I just did some digging about the chunks that are requested but not reported as completed in the log I posted above. What happens is, that those chunks are still transmitted to the client. However, AudioFileStreaming isn't expecting them any more, so the data isn't stored and must be downloaded a second time.

Thus, we get a double penalty: the second block (that we actually want) is only received after the first block (which we don't need) has been transmitted. In addition, the data of the first block is discarded which means we need to download it a second time later on.

Thus, the example above actually loads 15 chunks (1920KB - almost 2MB!) before playback can commence.

[sashahilton00]

Great work digging in to the inner workings, honestly have never examined it that in depth, surprising how much data is wasted during loads.

The first and basic idea for all that follows is, that the fixed chunk size should be done away with. Instead blocks of varying size should be downloaded. This could be implemented by making the internal chunk size very small (e.g. 1KB) and then downloading a range of chunks when requesting data from the server. This allows us to implement more flexible download strategies.

This indirectly relates to the transition to CDN for file delivery. we have a few things left to work out, but chunks are requested using the Content-Range header, meaning we can specify arbitrary chunk sizes.

the vorbis code does a bisect

This is indeed suboptimal. We should look at predicting chunks when trying to seek.

Vorbis seek could be improved. Instead of doing a blind bisect, we could try to predict where the correct timestamp is. If Spotify songs are encoded with constant bitrate (are they?)

Agree with regards to predicting timestamps. unfortunately Spotify uses VBR, which makes things slightly more challenging. Still, it should be possible even then to create a better solution to bisect, whereby one does something like ((seek_position_seconds / track_duration_seconds) * (total_file_size_bytes)) +/- (1024 * track_duration_seconds) (where 1024 = 1KB) or similar as a means to guess the correct chunk range based on average bitrate, which should(?) work for most songs that are just a few mins(?) long.

I just did some digging about the chunks that are requested but not reported as completed in the log I posted above. What happens is, that those chunks are still transmitted to the client.

This is to be expected. Mercury is very much fire and forget, whereby the server responds later with the response to your original request. I don't believe there's a way to cancel mercury requests once sent, hence we should focus on optimising the calculation for requesting chunks to minimise likelihood of requesting the wrong chunk and the number of requests.

The test below was done on an ADSL line (18396 Kbps down link) in Sydney, Australia and it took 11 seconds to load the track. On the same connection, the official client typically starts playback for similar tasks in less than a second, rarely it takes 1-2 seconds.

It might be worth examining the non-compliant header Spotify uses in their files. it's possible that they use that to add some data that might offer insight into the file contents that would aid in chunk prediction, which in turn increases loading speed. Particularly, I'm wondering if there is some sort of average bitrate info + variance of bitrate that one could use to influence how large one made the chunk request whilst seeking, though I suspect that this is not the case.

[sashahilton00]

This Bisection Search is very good compared to the alternatives (a linear scan of the whole file), often taking just a couple of reads to locate the correct location in a file gigabytes in size, but the truly obsessive can out-perform the bisection on average, by using the local bitrate to pick a better target than the half way point used in a bisection search (Secant method).

Similar to this, though would have to look at whether it's compatible with streaming file chunks, from a practicality standpoint.

https://wiki.xiph.org/GranulePosAndSeeking#Bisection_Search

[plietar]

The OGG files have a proprietary header at the start of the file that librespot skips because libogg and lewton fail to decode it.
I suspect it could be some metadata that helps perform efficient seeking, although that’s just an intuition, I never seriously looked into it.

[kaymes]

I've done some work on an overhaul of how files are downloaded. The download code can now handle completely arbitrary download ranges and also deal with multiple requests in parallel. Note, that parallel requests still mean, that the data comes back in sequence, but it saves on round trip time if multiple requests can be in flight. The code also makes data available as soon as it's there which means the player can use partial responses.

Starting a file from the beginning is almost instantaneous - as soon as the first data comes in, playback can commence.

For seek(), the code currently loads 16Kb ranges. Loading and bisect search on the same song as in my initial post takes 3.3 seconds which is quite an improvement given that it took 11 seconds before. I think, that this is about as good as it gets with using bisects. Any improvement over that would need changes to the search algorithm in some form.

The code then uses larger ranges to download the bulk of the file.

The code is still a bit rough at the moment and requires some cleanup. Also, it is prone to buffer-underruns shortly after playback when bulk-download doesn't come up to speed quick enough because I haven't put a proper heuristic in yet.

Once I've cleaned things up a bit, I'll start a pull-request so people can test it.
Effectively, this would cover ideas 1-3 from my initial post.

Nb: does anyone know an alternative for RangeSet in the range_map crate (http://jneem.github.io/range-map/range_map/struct.RangeSet.html)? I'm using it at the moment to keep track of which parts of the file are available, but the API of RangeSet doesn't appear to be thought through (or designed for another purpose) which makes things rather clumsy.
Basically, I need an object that allows me to store integer ranges and merges them where appropriate. Then I need to do things such as form unions and intersections or set-differences between them.
I know, it's not too hard to write from scratch, but I rather use someone else's implementation if possible.

[willstott101]

Hows this going @kaymes? This is a great write up and is 100% worth pursuing. If you'd like to open a draft PR, it could be worth getting some more eyes on it before you get a chance to tidy up

I must admit I get a bit impatient when seeking with librespot and I'd be happy to poke my nose in here and try to help :)

[kaymes]

It was going quite well until I got busy with other things and forgot about this.

I just had a look at the state of the code, merged it with the current dev branch (was a bit messy after all this time) and also managed to find the bug that was stopping the show. I'll put up a pull request now for others to test.

[kaymes]

PR #393 implements items 1-4 of my list of ideas above. (technically, we''re not really doing 2, we're doing something better instead). That's as far as I see it feasible to do at this stage. Please test it and provide feedback.