Disclaimers
This long wall of text is really aimed at presenting three questions and hoping to get them addressed in a constructive and productive way (=improved Roon user experience):
“What can Roon Labs do to improve the experience?”
“What can Roon Labs do to help me improve the experience?”
“What can I do to improve the experience?”
I’m not really looking for a discussion, although others might benefit from it - I seek answers and improvements. Therefore, this is mainly targeted to the developers who may have the answers and improvements in their hands. Any workarounds or known details from the larger community are, of course, very much welcome!
This is purely from my subjective point of view and does not imply wrong or right: this is just how I feel about this from my use case perspectives. Your’s can (and likely should) be different. I run Roon on an oldish Linux box and use almost exclusively Android devices for Roon Remote. It may or may not be related to this issue, but happens to otherwise work for my needs pretty well. (Further details may be found from my old support requests).
Introduction
Roon provides great value to my music listening and that can’t be over-stated, but if there is one thing that consistently tries to diminish that value and drives me mad, it has to be this log entry (or rather what it represents):
Debug: [query] Sooloos.Broker.Music.LibraryTrack: 3920 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=LibraryTrack)
Overall, the actual number of dirty items varies per entry (as seem to vary the number of entries per “rebuild”?), but whenever I start seeing those in the log, I know that my active music listening session is ruined and essentially over (or quite frustrating).
Whenever those dreaded entries appear in the log I can expect the following (I used to see these and wonder why, until I found an essentially 100% correlation between these and the log entries mentioned above):
- one CPU core is at 100%
- tagging a single track can take minutes
- accessing albums etc. can also take minutes
- queued tracks may have 10…120+ second delays in starting
- UI element animations and actions are delayed by tens of seconds
- same log entry is logged multiple times
- this typically happens when I’m actively listening
- it may last from 5 minutes to hours
As you can imagine, having an hour to spend on listening to new music, liking and tagging the tracks, looking at album/artist details, etc. is quickly spent cursing when all actions start to take minutes while I can’t do anything else but wait.
YES, I NEED BETTER HARDWARE - but I think there is more to it than that.
The Issue
In my very limited understanding and guess work, all of this is a result of some house keeping action on caches in roonserver that requires a CPU heavy optimization to reduce some back end load. Unfortunately, this house keeping action seems to require exclusive access to the internal database, resulting in all other DB access blocking while the house keeping works.
Being a relatively heavy operation, its impact is greatly amplified by low spec hardware and the result is a relatively bad user experience.
I am fairly convinced that this behavior correlates strongly with one or more of the following activities of my “active” listening (which consists mostly of these):
- first play of a new track in the library
- liking a track
- liking an album/artist
- tagging a track/album
Hardware
Of course, the first entry more or less reveals the “root” cause of these problems: my hardware (old i5) is not enough for roonserver with my library size (ca. 70,000 tracks). However, while a hardware upgrade is already planned, it can only go so far, and reducing bottlenecks on lower end hardware will certainly benefit everybody (to various degrees).
In the extreme end, which I’m nowhere near, improving the software may allow it to scale much further, other issues permitting. So, I think there is at least some value in addressing the issue(s) also on the software side.
Blocking access?
While many of the database access restrictions likely can’t be removed, I think some of them could be reviewed and maybe reconsidered.
The most obvious one is the DB access related to starting the playback of a queued track: is it really required to be able to start the playback or could the DB access/update be queued to be done in the background while the track is already playing? This is a balancing act between playback (user experience), presenting correct up-to-date information about the track (also user experience), and having correct information for tracks in the DB (“play started at …”). Only Roon Labs knows why they need to access the DB before start of each track even if it causes delays. Doing it to check for permission sounds a bit excessive.
As for other use cases, only the user knows for sure whether they require correct up-to-date data or not. An example from my tag management: sometimes I want to check what the track’s tags are (so I would have to wait for the DB access) and at times I simply want to set the tags regardless of what they may have been. Managing tags set for tracks/albums is different from managing what tags exist: first might be done for each track in a library whereas the second might only happen rarely (though I’m not going to anyone to not play with their tags). So, there may be room for improvements regarding tagging of playing (or other) tracks.
As for blocking access on UI elements, I simply can’t understand it and would wish for some sort of an change. A practical example is selecting multiple tracks from a list on my Android tablet Remote: when I long press a track, normally, in some fraction of a second that track is selected, highlighted, and the multiple selection menu and graphical elements appear. However, when the back end is busy, that behavior changes: once the long press is “accepted”, the Remote is likely waiting on back end, but I as user only see what appears to be an interrupted long press (like if my finger moved). So I try again, and again, and again, get frustrated trying, and after some 30-60 seconds the DB access was served, and all of my multiple long press selections go through and the UI updates to show my multiple selections. Absolutely annoying!
Timing
There are two timing related issues in the larger context: doing the heavy blocking activity when the user is active, and on the other hand, reducing the impact of the blocking action.
Let’s look at the logs from my past two days (edited for “brevity” - sorry, I felt the multiple entries contain information that is somehow relevant):
02/23 22:50:18 Sooloos.Broker.Music.LibraryTrack: 2092 dirty
02/23 22:50:19 Sooloos.Broker.Music.LibraryTrack: 2092 dirty
02/23 22:50:39 Sooloos.Broker.Music.LibraryTrack: 11988 dirty
02/23 22:50:40 Sooloos.Broker.Music.LibraryTrack: 11988 dirty
02/23 22:51:00 Sooloos.Broker.Music.LibraryTrack: 12043 dirty
02/23 22:51:01 Sooloos.Broker.Music.LibraryTrack: 12043 dirty
02/23 22:52:02 Sooloos.Broker.Music.LibraryTrack: 7794 dirty
02/23 22:52:03 Sooloos.Broker.Music.LibraryTrack: 7794 dirty
... lots of similar lines removed ...
02/24 00:19:02 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:19:03 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:19:04 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:35:06 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:35:07 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:35:07 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:39:31 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:39:32 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:39:32 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:50:51 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:50:52 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 00:50:53 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
... lots of similar lines removed ...
02/24 01:16:06 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 01:16:07 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 01:16:08 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
... stopped, slept, woke up, started listening & tagging ...
02/24 08:58:01 Sooloos.Broker.Music.LibraryTrack: 9098 dirty
02/24 08:58:01 Sooloos.Broker.Music.LibraryTrack: 9098 dirty
02/24 08:58:02 Sooloos.Broker.Music.LibraryTrack: 9098 dirty
02/24 08:58:42 Sooloos.Broker.Music.LibraryTrack: 9098 dirty
02/24 09:00:38 Sooloos.Broker.Music.LibraryTrack: 10451 dirty
02/24 09:00:39 Sooloos.Broker.Music.LibraryTrack: 10451 dirty
02/24 09:00:40 Sooloos.Broker.Music.LibraryTrack: 10451 dirty
02/24 09:01:20 Sooloos.Broker.Music.LibraryTrack: 10451 dirty
... lots of similar lines removed ...
02/24 11:04:11 Sooloos.Broker.Music.LibraryTrack: 2173 dirty
02/24 11:04:12 Sooloos.Broker.Music.LibraryTrack: 2173 dirty
02/24 11:04:13 Sooloos.Broker.Music.LibraryTrack: 2173 dirty
02/24 11:04:52 Sooloos.Broker.Music.LibraryTrack: 2173 dirty
02/24 11:05:32 Sooloos.Broker.Music.LibraryTrack: 2173 dirty
02/24 11:07:29 Sooloos.Broker.Music.LibraryTrack: 3101 dirty
02/24 11:07:29 Sooloos.Broker.Music.LibraryTrack: 3101 dirty
02/24 11:07:30 Sooloos.Broker.Music.LibraryTrack: 3101 dirty
02/24 11:08:10 Sooloos.Broker.Music.LibraryTrack: 3101 dirty
02/24 11:08:49 Sooloos.Broker.Music.LibraryTrack: 3101 dirty
... stopped actively tagging and listened to another queue ...
... started tagging; lots of similar lines removed ...
02/24 23:46:55 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 23:46:56 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 23:46:57 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 23:47:42 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 23:48:22 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 23:48:23 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/24 23:48:24 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
... stopped, slept, woke up, started listening & tagging ...
02/25 08:27:10 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 08:29:43 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 08:42:45 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 08:43:51 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 09:08:30 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 09:13:20 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 09:59:17 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
... lots of similar lines removed ...
02/25 10:46:15 Sooloos.Broker.Music.LibraryTrack: 7630 dirty
02/25 10:47:01 Sooloos.Broker.Music.LibraryTrack: 2405 dirty
02/25 10:47:43 Sooloos.Broker.Music.LibraryTrack: 3601 dirty
02/25 10:48:31 Sooloos.Broker.Music.LibraryTrack: 6452 dirty
02/25 10:49:22 Sooloos.Broker.Music.LibraryTrack: 9676 dirty
02/25 10:50:05 Sooloos.Broker.Music.LibraryTrack: 2287 dirty
02/25 10:50:49 Sooloos.Broker.Music.LibraryTrack: 3102 dirty
02/25 10:51:35 Sooloos.Broker.Music.LibraryTrack: 6220 dirty
02/25 10:52:33 Sooloos.Broker.Music.LibraryTrack: 2609 dirty
02/25 10:53:49 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
02/25 10:56:44 Sooloos.Broker.Music.LibraryTrack: 3920 dirty
If this is some cache related house keeping, then I’m wondering why it happens only when I’m actively liking and tagging tracks (pretty much every track that plays, so on average every 4 minutes or so). Could it be done when I’m not awake or not listening to anything?
If it is related to my activity, then how can liking and tagging a track every four minutes require an i5 to run one core 100% for hours?
Why do the same numbers keep appearing/repeating? Why do the same(?) items keep getting dirty? What is the point of repeatedly doing the same thing(?) again and again? The repeat lines do not look like a regularly intervalled heartbeat: I hope they are are steps from some internal algorithm instead of actually doing the query multiple times!
If these operations do have to run as soon as I’ve happened to trigger them, then could the impact at least be controlled a bit? The log entry says that it is trying to avoid an item-by-item sorting by rebuilding a query, so could the query size be controlled, too? Instead of doing a heavy 10,000 item query, maybe do 10 queries of 1,000 tracks each? If possible, it would increase the granularity, allowing for more frequent DB access for other activities and shorter locking periods. Of course, this does increase back end load, but maybe there is a happy medium for the minimum and maximum “batch” sizes, which could be dynamically tuned based on hardware performance?
Could some of these similar operations be relaxed, delayed, or even outright dropped?
What could Roon do to improve this?
There are all kinds of things Roon might be able to fix regarding this:
- look for possible bugs related to internal work flows (trigger, clean up, …)
- decouple UI elements from DB access
- increase granularity of operations to keep their impact in check
- possibly delay or reduce some cache updates
- tolerate eventual consistency where possible without confusing the user
What could Roon do to help users improve this?
The most obvious help comes from increasing awareness and improving related documentation. Options include:
- what user actions trigger these operations
- what user choices impact the scale of these operations (=make them worse)
- provide tools for users to more effectively control the impact of their choices and actions (eg. controlling queue/bookmark/playlist size if relevant)
What could users do to improve this?
In addition to the most obvious and already documented “get better hardware”, users could (once they have the tools and knowledge):
- adapt usage patterns to reduce overall impact
- use provided tools and settings to limit the impact
- report performance anomalies when recognized
The End
THANK YOU FOR READING IT ALL! My apologizies to those who feel robbed of valuable time. Go play some music that resonates with your soul. 