OwnTone getting stuck when trying to open a large library with Apple Music #1817
Comments
|
I'm not sure what is going on here. The log isn't showing much, expect maybe some artwork scaling. Can you attach gdb to the process to find out what owntone is doing? Something like this:
Hopefully this reveals what those threads are stuck doing. |
|
Thanks! I’m actually doing this for the first time, so thanks for the detailed steps. Here is what I found out. Those were the processes consuming CPU time:
So I examined 4410 and 4420, which were: worker (3): httpd (13): Does this help? I also want to mention that the system is a VM running with libvirt/qemu. I’m using the “Enable shared memory” option, so I can mount my music library using virtiofs. If you suspect that this might have something to do with the issue I’m seeing, I’m happy to set up a bare metal system. |
|
Yes, it helps, but unfortunately doesn't pinpoint the cause. It shows that the worker thread is busy extracting and rescaling embedded artwork from 101 Califone - Giving Away the Bride.mp3, but I'm not sure if it's stuck on that particular file. The last call is ffmpeg's avcodec_send_packet() allocating memory, so if that is somehow spinning then memory consumption will explode, which would explain the OOM killer. When you watch the process, do you then see the memory consumption keep going up? If you interrupt again with gdb, is the thread then still working on the same file? The gdb dump indicates the httpd thread isn't doing anything, and that's as it should be, since cpu intensive stuff should only be in the worker threads. However, your htop screenshot says thread 4420 is pretty busy, so that's odd if its the httpd thread. Are you sure that's the case? I think you can get htop to show the thread names directly with Setup (F2) > Display > Show custom thread names |
The yellow area in htop’s mem graph is actually going up steadily, but not the process’s memory consumption, at least not significantly (video attached below). However, at the same time, kern.log is filling rapidly with these messages until the disk is eventually full:
I tried it again today, and this time it was stuck on another file. I then attached the debugger and made another backtrace. I detached the debugger again, let it run for a few seconds, reattached the debugger, and did another backtrace. It was sitting at the same file. While I did this, the kern.log messages I pasted above had already started to appear.
That worked. There is indeed some significant CPU usage on websocket and httpd: 
Here’s a video that shows how the situation unfolds: Screen.Recording.2024-10-02.at.23.01.06.mp4It might make sense to test this without the virtualization layer in between, just to narrow things down. Let me know your thoughts! |
|
Great investigation, but unfortunately I am even more confused now. Seems something is eating memory, apparently not owntone directly, but something that owntone is triggering? The httpd thread being busy is puzzling, and even more so the websocket thread, since when you connect with Apple Music there are no websockets involved at all. I also have no idea why kern.log goes bananas. I'm not sure how to interpret the kernel log output you shared, but the internet tells me anon is memory consumption, and if that's 256 mb (or 258 like htop says) then it seems a tad high but not problematic.
Yes, that would be a good idea. Also just due to the fact that I'm at a loss about the above, so won't be able to help you fix it. |
|
Yeah, it's really weird. I'll see if I can reproduce the issue on a native, vanilla Ubuntu system. That will hopefully give us a better idea of what's going on. However, I won't get a chance to do this until likely end of October. I'll be in touch then! |
|
I tested this on a dedicated Ubuntu 24.04 system and there the process was also killed: However, it seems that the following service override (added to I didn’t try lower values, but VIRT in htop is around 1400M and RES is around 400M. I’m not sure which value is the one to look at, but I figured it won’t hurt to give it some headroom either way. I then went back to my virtualized Ubuntu 22.04 system, added |
|
Was it still working? Seems it isn't a leak, but I have no idea why the image conversion would then require so much mem. |
|
Yes, it successfully scanned all artworks and has been stable over the past 2 days. I didn’t mention this earlier, but without the MemoryMax option, I was also encountering crashes when browsing the library via the web UI or via the Remote app on iOS, or also sometimes just randomly while playing tracks from the local library. These also seem to be fixed by increasing MemoryMax. I realized that the standard systemd unit that comes with OwnTone has MemoryMax set to 256M. Apparently that’s not enough for large libraries. systemd reports that it’s using 1.7G on my system: For my use case, it’s acceptable to leave MemoryMax at 2G. However, if you’re interested in analyzing this further, I’m here to help and can run further tests. Otherwise I suggest I resolve this issue, but maybe we could add a hint to the troubleshooting section at https://github.com/owntone/owntone-server/blob/master/docs/library.md. What do you think? |
|
Idk, adding a doc workaround is last resort. OwnTone is supposed to be pretty light-weight, and that's hardly what you are seeing. Just now, I tested myself with Apple Music and my somewhat smaller library (just 2k songs), and memory consumption peaked at only 25MB. I hope you can help with some more testing:
|
|
I’m happy to try these steps in the next couple of days. Will report back! |
|
Here is the file: owntone.massif.zip Before I logged in to the fresh macOS account and started Apple Music, I let OwnTone settle (finish library scanning, smart playlists, Spotify, etc.) Also, for the record, I changed Here is a screenshot I took after quitting Apple Music (after letting it run for 10 minutes) and right before hitting Ctrl+C on the OwnTone process: 
Let me know if this is helpful. |
|
Thanks for testing, pretty interesting. It confirms that there is no memory leak, so that's good to get confirmed. Memory consumption peaks at 182MB, which is pretty high, but strangely still quite far from the 2G you had to set as max. The report below shows the allocation. It confirms that it's the artwork processing that's using it. The report also indicates that only some of the artwork requests are memory heavy, so I think I will try to make a version of OwnTone with special logging/handling of those requests. So that would be the next thing I would ask you to test. Btw, good that you included the sizes of the cache db's. They are pretty large, especially that 1.3 GB artwork cache. However, that in itself isn't necessarily a problem. If my math is right, it's just 13KB per track, so really not too bad. And the internet says sqlite can support large databases. As I recall, when Apple Music loads the library the first time, it requests artwork for every single track in your library. That's of course wildly ineffective for a 100k library. But I can't do much about that. |
Interesting findings. Regarding the memory usage, I just checked my main OwnTone server and it’s currently using 1.8G according to systemd: Seeing that it was started at 6:30 in the morning didn’t make sense to me—I clearly did not do that myself. So I checked the logs and saw that it was in fact restarted because it exceeded the 2G: I did not rescan the library on the main server with Apple Music within in the past 3 days. So I’m suspecting that there’s another cause for the high memory consumption. Usually, I don’t use Apple Music to listen to music at all, and instead control OwnTone via Home Assistant or the iTunes Remote app on iOS (and have OwnTone stream to multiple AirPlay speakers in the house). While the artwork generation may have room for optimization according to the report, it might not be the issue for the excessive memory consumption. Would it help to start the OwnTone with the valgrind command and leave it running for hours/days while I’m using it like I normally do?
Yes, happy to test this!
Yes, it does that, but it’s not a big issue since browsing and playback works while it’s still fetching the artworks. |
Yes, I agree. There's a big step from the artwork 200MB to that 2GB limit.
Yes, if you can live with the poor performance. If Valgrind/massif could say what's eating those GB's it would be a breakthrough. But before you try that, I thought of a simple test you could try, which is to just disable caching by changing the config setting When you make this test, I suggest you temporarily also set the |
|
I’ve set Once library scanning and Spotify scanning had completed, the memory usage was at ~25 MB. This matches the value I get with caching enabled. I then started playback on a large playlist via the iTunes Remote app. Memory usage got to ~50 MB, which is also not significantly different from the value I see when cache is enabled. So I will leave it running over the next hours (or days) to see if the RAM usage increases over time (with cache disabled). By the way, the documentation still includes the deprecated |
|
Quick update: After 1.5h, it grew to 180 MB. |
|
More numbers: 10h — 262M I’ll restart OwnTone with valgrind now, hoping to collect some useful insights. |
|
Interesting. Growing numbers indicate a memleak so maybe I was wrong to exclude that. Will be very good to see what Valgrind/massif says. |
|
After restarting OwnTone with valgrind yesterday, memory consumption didn’t grow excessively. I’m a bit puzzled what’s different now, but I’ll anyway attach the massif file. When I just stopped the process, the memory usage was at 213M (after 20h runtime). So clearly not what I was seeing in my previous test where it was at 968M after 21h. owntone2_cache_disabled.massif.zip I’ll give it another go with caching enabled (even though my test from Nov 12 had caching disabled). When I get a chance next week, I’ll also see if I can pinpoint certain usage patterns that drive up memory consumption. |
|
Yes, quite strange. The massif report is just showing 10-20MB mem usage at the end, ref the below. I wonder how that translates to those 213MB. Guess there is something I don't understand about memory statistics. |
Platform:
Steps to reproduce:
It will take a while to load, but will eventually show the full library.
However, this is where it gets stuck:
At the same time on the server:
Note that I added the following override to the OwnTone unit file:
Without this, the OwnTone process was killed when trying to open the OwnTone library in Apple Music:
Is there anything I can tweak on my system? Or is this something that needs to be optimized in OwnTone?
Thanks!
The text was updated successfully, but these errors were encountered: