What is my Roon core doing all the time filling my log?

Support
1

Roon Core Machine

Windows 10, 8GB,
Gigabyte BRIX GB-BACE-3160 Celeron-J3160 Barebone

Networking Gear & Setup Details

Not of interest

Connected Audio Devices

Not of Interest

Number of Tracks in Library

57654 tracks

Description of Issue

Please look at the log files of my Roon core. It is always busy and produces tons of this messages in the log. What is going on there?

09/29 07:34:38 Info: [stats] 6674mb Virtual, 1148mb Physical, 792mb Managed, 2889 Handles, 175 Threads
09/29 07:34:53 Info: [stats] 6682mb Virtual, 1148mb Physical, 794mb Managed, 2901 Handles, 177 Threads
09/29 07:34:53 Trace: [library] endmutation in 47ms
09/29 07:34:57 Trace: [library] endmutation in 53ms
09/29 07:35:08 Info: [stats] 6674mb Virtual, 1148mb Physical, 792mb Managed, 2901 Handles, 175 Threads
09/29 07:35:22 Trace: [library] endmutation in 18ms
09/29 07:35:23 Info: [stats] 6690mb Virtual, 1148mb Physical, 793mb Managed, 2915 Handles, 179 Threads
09/29 07:35:30 Trace: [library] endmutation in 52ms
09/29 07:35:38 Info: [stats] 6682mb Virtual, 1148mb Physical, 792mb Managed, 2915 Handles, 177 Threads
09/29 07:35:53 Info: [stats] 6710mb Virtual, 1148mb Physical, 793mb Managed, 2955 Handles, 184 Threads
09/29 07:36:08 Info: [stats] 6694mb Virtual, 1083mb Physical, 792mb Managed, 2951 Handles, 180 Threads
09/29 07:36:15 Trace: [library] endmutation in 16ms
09/29 07:36:23 Info: [stats] 6702mb Virtual, 1083mb Physical, 793mb Managed, 2978 Handles, 182 Threads
09/29 07:36:31 Trace: [library] endmutation in 46ms
09/29 07:36:38 Info: [stats] 6670mb Virtual, 1083mb Physical, 792mb Managed, 2952 Handles, 174 Threads
09/29 07:36:53 Info: [stats] 6710mb Virtual, 1146mb Physical, 790mb Managed, 2819 Handles, 184 Threads
09/29 07:37:00 Trace: [library] endmutation in 18ms
09/29 07:37:06 Trace: [library] endmutation in 53ms
09/29 07:37:08 Info: [stats] 6678mb Virtual, 1146mb Physical, 788mb Managed, 2806 Handles, 176 Threads
09/29 07:37:23 Info: [stats] 6710mb Virtual, 1146mb Physical, 789mb Managed, 2885 Handles, 184 Threads
09/29 07:37:38 Info: [stats] 6670mb Virtual, 1147mb Physical, 792mb Managed, 2849 Handles, 174 Threads
09/29 07:37:53 Info: [stats] 6690mb Virtual, 1147mb Physical, 793mb Managed, 2888 Handles, 179 Threads
09/29 07:37:56 Trace: [library] endmutation in 62ms
09/29 07:38:08 Info: [stats] 6670mb Virtual, 1147mb Physical, 792mb Managed, 2876 Handles, 174 Threads
09/29 07:38:23 Info: [stats] 6726mb Virtual, 1147mb Physical, 793mb Managed, 2956 Handles, 188 Threads
09/29 07:38:34 Debug: [easyhttp] [822] POST to https://swim.roonlabs.net/1/session/f9dba170f8ef4725b0d77f27248e9acf/ping returned after 635 ms, status code: 200
09/29 07:38:38 Info: [stats] 6690mb Virtual, 1147mb Physical, 792mb Managed, 2934 Handles, 179 Threads
09/29 07:38:53 Info: [stats] 6698mb Virtual, 1147mb Physical, 792mb Managed, 2936 Handles, 180 Threads
09/29 07:39:08 Info: [stats] 6670mb Virtual, 1147mb Physical, 792mb Managed, 2922 Handles, 174 Threads
09/29 07:39:09 Trace: [broker/accounts] [heartbeat] now=29.09.2022 05:39:08 nextauthrefresh=29.09.2022 06:09:55 nextmachineallocate=29.09.2022 08:09:08
09/29 07:39:23 Info: [stats] 6702mb Virtual, 1147mb Physical, 793mb Managed, 2957 Handles, 182 Threads
09/29 07:39:38 Info: [stats] 6674mb Virtual, 1147mb Physical, 792mb Managed, 2937 Handles, 175 Threads
09/29 07:39:53 Info: [stats] 6690mb Virtual, 1147mb Physical, 793mb Managed, 2962 Handles, 179 Threads
09/29 07:40:08 Info: [stats] 6678mb Virtual, 1147mb Physical, 792mb Managed, 2954 Handles, 176 Threads
09/29 07:40:23 Info: [stats] 6746mb Virtual, 1147mb Physical, 793mb Managed, 3052 Handles, 193 Threads
09/29 07:40:38 Info: [stats] 6682mb Virtual, 1148mb Physical, 796mb Managed, 2991 Handles, 177 Threads
09/29 07:40:50 Trace: [library] endmutation in 16ms
09/29 07:40:53 Info: [stats] 6698mb Virtual, 1148mb Physical, 797mb Managed, 3033 Handles, 181 Threads
09/29 07:41:08 Info: [stats] 6674mb Virtual, 1148mb Physical, 796mb Managed, 3017 Handles, 175 Threads
09/29 07:41:21 Trace: [library] endmutation in 45ms
09/29 07:41:23 Info: [stats] 6698mb Virtual, 1148mb Physical, 797mb Managed, 3052 Handles, 181 Threads
09/29 07:41:38 Info: [stats] 6686mb Virtual, 1148mb Physical, 788mb Managed, 2800 Handles, 178 Threads
09/29 07:41:52 Trace: [library] endmutation in 18ms
09/29 07:41:53 Info: [stats] 6690mb Virtual, 1148mb Physical, 788mb Managed, 2805 Handles, 179 Threads
09/29 07:42:04 Trace: [library] endmutation in 17ms
09/29 07:42:08 Info: [stats] 6690mb Virtual, 1148mb Physical, 788mb Managed, 2805 Handles, 179 Threads
09/29 07:42:23 Info: [stats] 6694mb Virtual, 1148mb Physical, 788mb Managed, 2834 Handles, 180 Threads
09/29 07:42:38 Info: [stats] 6694mb Virtual, 1148mb Physical, 788mb Managed, 2834 Handles, 180 Threads
09/29 07:42:54 Info: [stats] 6686mb Virtual, 1148mb Physical, 790mb Managed, 2836 Handles, 178 Threads
09/29 07:43:09 Info: [stats] 6678mb Virtual, 1148mb Physical, 788mb Managed, 2836 Handles, 176 Threads
09/29 07:43:24 Info: [stats] 6718mb Virtual, 1148mb Physical, 789mb Managed, 2883 Handles, 186 Threads
09/29 07:43:30 Trace: [library] endmutation in 52ms
09/29 07:43:39 Info: [stats] 6682mb Virtual, 1148mb Physical, 792mb Managed, 2861 Handles, 177 Threads
09/29 07:43:54 Info: [stats] 6690mb Virtual, 1148mb Physical, 794mb Managed, 2875 Handles, 179 Threads
09/29 07:44:09 Trace: [library] endmutation in 51ms
09/29 07:44:09 Info: [stats] 6682mb Virtual, 1148mb Physical, 792mb Managed, 2875 Handles, 177 Threads
09/29 07:44:09 Trace: [broker/accounts] [heartbeat] now=29.09.2022 05:44:08 nextauthrefresh=29.09.2022 06:09:55 nextmachineallocate=29.09.2022 08:09:08
09/29 07:44:19 Trace: [library] endmutation in 46ms
09/29 07:44:24 Info: [stats] 6702mb Virtual, 1148mb Physical, 792mb Managed, 2911 Handles, 182 Threads
09/29 07:44:39 Info: [stats] 6682mb Virtual, 1148mb Physical, 792mb Managed, 2897 Handles, 177 Threads
09/29 07:44:39 Trace: [library] endmutation in 17ms
09/29 07:44:54 Info: [stats] 6690mb Virtual, 1148mb Physical, 792mb Managed, 2903 Handles, 179 Threads
09/29 07:44:54 Trace: [library] endmutation in 18ms
09/29 07:44:57 Trace: [library] endmutation in 43ms
09/29 07:45:01 Trace: [library] endmutation in 54ms
09/29 07:45:09 Info: [stats] 6682mb Virtual, 1148mb Physical, 792mb Managed, 2900 Handles, 177 Threads
09/29 07:45:24 Info: [stats] 6698mb Virtual, 1148mb Physical, 792mb Managed, 2920 Handles, 181 Threads
09/29 07:45:39 Info: [stats] 6674mb Virtual, 1148mb Physical, 792mb Managed, 2902 Handles, 175 Threads
09/29 07:45:45 Trace: [realtime] fetching time from NTP server
09/29 07:45:45 Trace: [realtime] Got time from NTP: 29.09.2022 05:45:44 UTC (3873419144248ms)
09/29 07:45:45 Trace: [realtime] Updated clock skew to -00:00:01.4024432 (-1402,4432ms)
09/29 07:45:54 Info: [stats] 6699mb Virtual, 1149mb Physical, 792mb Managed, 2943 Handles, 181 Threads
09/29 07:46:08 Trace: [library] endmutation in 43ms
09/29 07:46:09 Info: [stats] 6691mb Virtual, 1149mb Physical, 787mb Managed, 2804 Handles, 179 Threads

Best DrCWO

4

Hi @DrCWO,

Unless there is a specific problem we’re trying to address, it’s not the kind of thing we’d bring to development for an answer.

Please do let us know if you’re having issues though!

Wes

6

My issue is that caused by this huge load caused by things I don‘t understand I often get the message Qobuz is slow and my music playback stops.
This is especially true if I start searching for a track while playing music.

I felt it got better with v2.0 so I will continue observing the issue and will get back to you if I know more.

Best DrCWO

2 Likes
7

That’s a line of text every few seconds, which does not constitute a huge load. Any OS itself logs more than that

8

Not getting any load on CPU or Memory as that appears to be much better after 2.0 but that particular message, whilst not occurring what you could call repeatedly, actually seems to be happening to me a little more frequently under 2.0 when searching whilst playing music.

9

The log output you shared is completely normal, and relatively trivial in comparison to other log files. For example, if you stream the log output on a Mac (using the Console app) you’ll see that it produces around 200 lines per second. Roon’s output is minimal in comparison.

10

You are right, creating a log line does not waist CPU time.
These lines seem to be the result of a statistic research and occurred during heavy CPU load. That‘s why I posted.

I like to understand why those statistics has to be computed every few seconds causing CPU load…

11

The Info: [stats] line, which reports memory allocation statistics, repeats every 15 seconds, not just during heavy load. And yes, this will increase CPU load, but by a totally trivial amount.

1 Like
12

Do you also know what the mutation log entry means?

13

The fact your running core on a celeron which is not to Roons minimum spec might be part of your issues with Qobuz or it might not. I take it you core is hardwired and the endpoints are also hardwired. What’s your signal path showing for processing speed are you using any DSP? Have you tried changing DNS server to Google or Cloudflare or just your ISP perhaps your being rooted to a far off CDN.

14

No. But that line makes a regular appearance in my logs too, so I wouldn’t worry about that one either.

15

You might find this article useful as it explains the difference between different levels of logging. As you’ll see, ‘Trace’, ‘Info’ and ‘Debug’ report the normal operations of a program (with varying degrees of detail). ‘Warn’ indicates a possible problem, though one that is likely to be resolved. ‘Error’ and ‘Fatal’ report issues that are more serious, i.e. something that has stopped the program from operating as it should.

1 Like
16

I also thought abut that but had no trouble in the past with this cheap device :blush:
And indeed I also run SRC to 96kHz, 4xFIR DRC for room correction and XO. But the signal path normally shows a spreed between 2x and 3x so did not care too much.
DNS is a PiHole (cache) to 1.1.1.1 and 300Mbit on a TV + Internet cable.
Getting this message I can access Qobuz without any problem via browser and App.

17

I would check what the processing speed is when you get the slow message again to see if it’s related. Streaming from qobuz at higher res will take a hit on processing speed.

18

If I enciunter the issue below 1 :sleepy:
My guess is that the debase operation occurring during search kills the playback process…

19

Less than half a Nucleus. Not a good idea for a 60,000 track library.

https://www.cpubenchmark.net/compare/2772vs2879/Intel-Celeron-J3160-vs-Intel-i3-7100U

AJ

20

I know that you are right. It worked fine for a long time and I just wonder if this is an issue with the new Roon version.
Maybe the best would be to get a stronger CPU :blush:

1 Like
21

More Ram won’t go a miss either.

22

Seems not to be an issue. As I use this box only for Roon 5.6 of 8GB are displayed as used in win10 task manager :+1:t2:

23

It really helps speed things up did on my Rock when I went from 8 to 16 and I have a similar sized library to yours.

1 Like