Memory usage increasing drastically during library rescan

Roon Core Machine

Intel(R) Core™ i7-7700 CPU @ 3.60GHz, Windows 10 Pro 64bit version 21H1

Number of Tracks in Library

323,000 tracks

Description of Issue

After changing import settings to use IMPORTDATE tag when present, this triggered a library rescan which took more than 24 hours. During this time roon memory usage got very high periodically and I could see in the log stats like shown below:

10/31 12:36:32 Info: [stats] 27312mb Virtual, 18316mb Physical, 20780mb Managed, 3580 Handles, 148 Threads

Isn’t it excessive to reach 18GB RAM usage during operation? Under normal operation roon memory usage is below 4GB with my library fully loaded and after restarting the RoonServer, memory usage seemed to get back to normal…

Here are the complete logs of that date:

Roon Server logs Adrian_Matala

Thanks!

When redefining the import settings of such a large database, the system practically starts from scratch. If it does not want to lose the old information, the old and the new must be kept in the main memory at the same time, practically double consumption. Only when everything has been checked again and written to the database can it be released again in memory for memory optimization.

Thanks for the explanation, but double consumption would practically mean around 8GB in my case… After a fresh start, RoonServer is using around 3.5GB RAM and after a few hours of normal use it goes up closer to 4GB:

11/03 21:41:38 Info: [stats] 8666mb Virtual, 3594mb Physical, 3132mb Managed, 2392 Handles, 134 Threads

In case of a rescan the memory usage was around 18GB which is roughly 4.5 times the normal size. This seems quite excessive to me, especially that it kept on increasing over the hours and I needed to restart the server to clear it up… I actually don’t know how high it would have gone to the end of the rescan because I had to restart RoonServer halfway through as my PC was not responding properly anymore.

If you can read the log data, there will be lines with Fatal (practically crash), Error ( heavy error) or Warn (something is stuck here)

Otherwise wait until the support takes up the topic.

Thanks, I can only see a lot of “endmutation” messages in the logs while memory usage keeps on increasing, but no Fatal or Error messages.

10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 11ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 11ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 13ms
10/31 12:32:58 Trace: [library] endmutation in 13ms
10/31 12:32:58 Trace: [library] endmutation in 14ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 14ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:32:58 Trace: [library] endmutation in 11ms
10/31 12:32:58 Trace: [library] endmutation in 12ms
10/31 12:33:04 Trace: [broker/accounts] [heartbeat] now=31/10/2021 11:33:05 nextauthrefresh=31/10/2021 12:18:05 nextmachineallocate=31/10/2021 12:03:03
10/31 12:33:04 Info: [stats] 24220mb Virtual, 17893mb Physical, 17502mb Managed, 3531 Handles, 175 Threads
10/31 12:33:05 Trace: [library] endmutation in 11ms
10/31 12:33:05 Trace: [library] endmutation in 125ms
10/31 12:33:05 Trace: [library] endmutation in 122ms
10/31 12:33:05 Trace: [library] endmutation in 242ms
10/31 12:33:05 Trace: [library] endmutation in 126ms
10/31 12:33:06 Trace: [library] endmutation in 125ms
10/31 12:33:06 Trace: [library] endmutation in 110ms
10/31 12:33:06 Trace: [library] endmutation in 99ms
10/31 12:33:06 Trace: [library] endmutation in 86ms
10/31 12:33:06 Trace: [library] endmutation in 29ms
10/31 12:33:06 Trace: [library] endmutation in 31ms
10/31 12:33:06 Trace: [library] endmutation in 29ms

I could see some similar posts which suggests that this means roon is stuck, but it’s not clear why… a restart seems to clear the problem, just like in my case, but that’s not a proper fix for me:

https://community.roonlabs.com/t/roon-seemingly-stuck-in-applying-library-settings/76332

Anyway, I have uploaded the full logs in my initial post and I am hoping support will have a look at them and come up with further insight.

1 Like

No updates on this? Is there any more info I can provide to have feedback from support?

Am mentioned, full logs are available here:

https://www.dropbox.com/s/6hs0olkhz5z1v04/Logs_amatala_2021-10-31.zip?dl=0

Thanks!

I wish you and the team a restful weekend and in the new week creative power also for these protocols.

Is the scan actually ready yet? I get with my large database every 2 days around 100,000 music titles further.

My scan finishes within a day once I restart the server. So if the RoonServer gets stuck and starts over-allocating memory, all I have to do is restart it and the scan will continue and complete normally within a few hours, but I was hoping for a proper fix as this looks like a nasty bug which should be addressed properly.

Hi @Adrian_Matala ,

Apologies it took some time to get back to you here, and thank you for letting us know those details of the issue.

Please be aware that since you have 320k tracks in your library, applying a new import date setting might take a while and this is expected behavior as Roon needs to go through each database entry.

Can you please confirm, does this memory problem occur when Roon is not applying any changes to the Database, or only when making the tag changes?

We are also seeing quite a few tags with strange names, can you please confirm if these are actual tags and how you created them? I have provided a few examples below:

10/31 13:21:46 Info: GetOrCreateUserTag: there is an existing tag called +01:12:00
10/31 13:21:46 Info: GetOrCreateUserTag: there is an existing tag called +02:27:00
10/31 13:21:46 Info: GetOrCreateUserTag: there is an existing tag called +01:29:00
10/31 13:21:46 Info: GetOrCreateUserTag: there is an existing tag called +03:22:00
10/31 13:21:46 Info: GetOrCreateUserTag: there is an existing tag called +02:45:00
10/31 13:21:46 Info: GetOrCreateUserTag: there is an existing tag called +01:41:00

Thanks!

Hi @noris ,

Thanks for your response. So far I have encountered this issue twice, both times while applying new import settings. First I have changed from using file modification time to file creation time, and later on I have added an IMPORTDATE TAG to my files and enabled the option to use it when present.
In both cases, the scan ran for several hours until it got stuck and stopped progressing. After stopping and restarting Roon Server, the scan picked up from where it had left and completed eventually. I know applying the new settings will take quite some time for my library, but normally it should be able to complete without having to restart the server.

As for those strange TAGs, those contain album duration and are present in ROONALBUMTAG in all my files. Those allow me to filter albums by duration, in order to be able to choose an album that fits my current listening slot… I could not find another way of achieving that functionality in Roon (sorting and filtering full albums by duration).

1 Like

That’s quite an interesting use of tags :sweat_smile:

Does it sound like this is the case then?

Does the system works as expected until those (many) tag changes?

Hi @noris

The memory problem only seems to occur while doing a full library re-scan. That’s when the scan runs for many hours and after a while I am seeing those “Trace: [library] endmutation” messages I mentioned before in the log and the scan seems stuck in a loop with memory usage ever increasing. After a restart of the server, the scan continues normally.

When only adding / modifying a few albums, it all goes fine and also during normal use I never encountered any problem.
At this time I didn’t have to change any other settings which would trigger a full re-scan and I am trying to avoid that as much as possible, so I didn’t encounter any memory issue in the past few weeks.

1 Like