node_exporter uses excessive CPU on a ThunderX2 host

[djeverett]

Host operating system: output of uname -a

Linux rhel-8-2-aarch64-gpu-1 4.18.0-193.14.2.el8_2.aarch64 #1 SMP Wed Jul 29 19:46:42 UTC 2020 aarch64 aarch64 aarch64 GNU/Linux

node_exporter version: output of node_exporter --version

1.0.1

node_exporter command line flags

--collector.systemd --collector.textfile --collector.textfile.directory=/var/lib/node_exporter --collector.filesystem --collector.filesystem.ignored-fs-types='^(autofs|binfmt_misc|bpf|cgroup2?|configfs|debugfs|devpts|devtmpfs|fuse..*|fusectl|hugetlbfs|iso9660|mqueue|nfs|nsfs|overlay|proc|procfs|pstore|rpc_pipefs|securityfs|selinuxfs|squashfs|sysfs|tracefs|tmpfs)$' --collector.filesystem.ignored-mount-points='^/(dev|proc|run|sys)($|/)' --web.listen-address=0.0.0.0:9100

Are you running node_exporter in Docker?

No

What did you do that produced an error?

On a ThunderX2 machine, run node_exporter and top. The run curl localhost:9100/metrics and watch for node_exporter in top

The output of lscpu on this host is:

Architecture:        aarch64
Byte Order:          Little Endian
CPU(s):              256
On-line CPU(s) list: 0-255
Thread(s) per core:  4
Core(s) per socket:  32
Socket(s):           2
NUMA node(s):        2
Vendor ID:           Cavium
Model:               2
Model name:          ThunderX2 99xx
Stepping:            0x1
CPU max MHz:         2500.0000
CPU min MHz:         1000.0000
BogoMIPS:            400.00
L1d cache:           32K
L1i cache:           32K
L2 cache:            256K
L3 cache:            32768K
NUMA node0 CPU(s):   0-127
NUMA node1 CPU(s):   128-255
Flags:               fp asimd evtstrm aes pmull sha1 sha2 crc32 atomics cpuid asimdrdm

What did you expect to see?

%CPU for node_exporter is a few percent.

What did you see instead?

CPU usage goes up to more than 1200%.

[uniemimu]

The cpu (-freq) collector(s) parallelize a lot, which can cause a sudden burst of threads accessing related kernel functionality pretty much at the same time. Could you try running node_exporter without the cpu* collectors to see if the issue is in those?

[djeverett]

Thanks for the response. I can confirm that the excessive CPU load is not seen if node_exporter is started with --no-collector.cpufreq. We are not actually using the cpufreq metrics, so disabling the collector is an appropriate solution for us.

[uniemimu]

A long time ago I recall suggesting not to do frequency querying for hyperthreaded cores. The frequency for those is always the same as for the physical core, so one could as well just copy the information from the related physical core value. That would on some CPUs reduce the thread burden by 50% and as such it would be a valid optimization. But I fear that is probably not quite a sufficient remedy.

Perhaps limiting the thread count to something much lower than the physical core count is the way to go. Or the related kernel side functionality should be investigated to find out what exactly is so problematic when many threads try to read the frequency information at the same time.

Last but not least I would like to emphasize that reading the frequency information with as many threads as possible is problematic also in the sense that on some hardware architectures it has a rather significant impact on the result, basically exhibiting a CS case of observer effect. Starting as many threads as there are cores just to read the frequency information "fast" will on certain high-core architectures immediately kick the cores out from any kind of turbo-frequencies they might have used, basically rendering the information that is read, rather useless. You'll never see those turbo frequencies reported with node_exporter, even if they in fact are getting used. I could also imagine overall CPU-frequencies going up (but not as far as to turbo) during the period of reading the information, if spinlocks are getting congested (which could explain the perceived excessive CPU usage). But of the latter, I do not have proof. For the lack of turbo-frequencies getting reported, that I know and have witnessed for sure on high core count machines.

@SuperQ please take note

[SuperQ]

The problem with limiting threads is it will cause the scrape to be slow and just defer the problem.

Remember, these are not OS threads, these are goroutines. If you want to limit the core time of the node_exporter, it's easier to use GOMAXPROCS or cgroup controls.

[uniemimu]

I can verify that this can be an issue also for certain high core count Xeons running short-ish scrape intervals, and the workaround is disabling of cpufreq collector.

I haven't seen any issues with low core count nodes.

[discordianfish]

Can y'all confirm this happens with both the cpu and the cpufreq collector?

Given that more people report this now, we need to do something about this. I suspect there is some kernel issue that we're triggering. We're saying:

	// Execute the parsing of each CPU in parallel.
	// This is done because the kernel intentionally delays access to each CPU by
	// 50 milliseconds to avoid DDoSing possibly expensive functions.

• https://github.com/prometheus/procfs/blob/master/sysfs/system_cpu.go#L164
  Have we confirmed that this is the case? Maybe the kernel delays it precisely because rapid querying this endpoint results in the problems we're saying.

[SuperQ]

IIRC, @rtreffer found the explicit 50ms delay in the kernel code.

[uniemimu]

Can y'all confirm this happens with both the cpu and the cpufreq collector?

For us disabling cpufreq-collector was sufficient to bring the load down and the nagging from the fellow maintaining one particular cluster ceased with that. We do still run the cpu-collector.

[SuperQ]

Thanks, I'm guessing this would be solved with GOMAXPROCS=1 as well.

[discordianfish]

@uniemimu Can you try setting GOMAXPROCS=1, enable the cpufreq collector and see if you still see the issue?

[SuperQ]

For reference, the original issue about cpufreq taking too long is here: #1086

[uniemimu]

@uniemimu Can you try setting GOMAXPROCS=1, enable the cpufreq collector and see if you still see the issue?

It is better, and doesn't get out of control anymore in a 96 core machine. However on an idling machine you can still easily tell that cpufreq is running, the 1m load went from 0.5 to 1.5 or like that. Compare with the default GOMAXPROCS the system becomes rather unstable and logging in with ssh is very sluggish, with the user quickly going for "sudo kill -9 pidof node_exporter". Load averages are in the hundreds then.

[SuperQ]

Any chance we could get access to one of these systems to do some tracing? Unfortunately, I have no such hardware to test with.

[uniemimu]

Any chance we could get access to one of these systems to do some tracing? Unfortunately, I have no such hardware to test with.

From my side I can't unfortunately give access to these. But I did a perf-trace:

 42.43% swapper
     99.72% [kernel.kallsyms]

 18.80% node_exporter
     82.58% [kernel.kallsyms]
     17.23% node_exporter

 14.47% kubelet
     62.91% kubelet
     36.19% [kernel.kallsyms]

  6.66% containerd-shim
     61.98% [kernel.kallsyms]
     36.74% containerd-shim-runc-v2
      1.27% [vdso]

  3.37% containerd
     68.11% containerd
     31.02% [kernel.kallsyms]

  1.20% alertmanager
     55.03% alertmanager
     43.07% [kernel.kallsyms]
      1.21% [vdso]

  1.06% weaver
     58.93% weaver
     37.85% [kernel.kallsyms]
      2.67% [unknown]

I only allowed it to run for a while with the default GOMAXPROCS, system load had climbed to around 10 when I started tracing. It would have climbed to hundreds within an hour. The issue is at the kernel side obviously, where exactly is another thing. I was running 5.8.0-41-generic kernel during the trace, but 5.9.0 is no better.

[SuperQ]

What would be useful is a Go pprof CPU profile.

• Startup node_exporter (on any port you want)
• go tool pprof -seconds 60 "http://${target}:${port}/debug/pprof/profile"
• Scrape the test node_exporter.
• Save the profile (i.e. ${HOME}/pprof/pprof.node_exporter.samples.cpu.001.pb.gz)

The pprof tool will gather data for as long as you specify -seconds.

[uniemimu]

Meanwhile I took a look at kernel.map which I happened to find, and the thing node_exporter is reaching for in the kernel points to osq_lock. Which to me makes perfect sense, I was expecting it to be fighting over a (spin)lock down there, for some reason or the other.

[uniemimu]

pprof_tree.txt

[eero-t]

@SuperQ With >4/5 of the "node_exporter" CPU cycles going to kernel per-CPU spinlock spinning on Xeon, I think that "strace" is enough to debug the issue, and that it can be done on any machine.

See if there are any syscalls that might require kernel internal spinlocks (when you enable just cpufreq collector), and reduce the number of those that would scale up with the number of host CPUs.

[eero-t]

Looking at the kernel osq_lock history: https://github.com/torvalds/linux/commits/master/kernel/locking/osq_lock.c
There haven't been any recent performance changes, so kernel version doesn't matter as long as it's from 2018 or later.

[SuperQ]

Alright, I guess we need to trace which exact thing is causing the spinlock race, and put some kind of concurrency wrapper around it.

[cgwalters]

So the core tension here seems to be the kernel is trying intentionally to limit userspace frequency here for good reason, vs node_exporter not wanting to block. But isn't explicitly just using one asynchronous goroutine here sufficient?

[discordianfish]

@cgwalters That's still a bit unclear. We don't think it can be explained in this case by just intentional throttling but nobody had yet time to dive deeper into that issue. We tried with GOMAXPROCS=1 but using one goroutine might be worth a try.

[SuperQ]

I have published node_exporter v1.5.0 which now defaults GOMAXPROCS to 1.

We have also converted a couple of the collectors from reading files to netlink. This should improve the performance greatly.

Although for one of these, you will need to use the flag --collector.netclass.netlink to enable it.

[britcey]

I've had enough issues on my large physical hosts that I'm thinking cpufreq should be disabled by default (do we have any sense of how widely used those metrics are?).

A sample:

48 CPUs (2 sockets, 12 cores per, 2 threads per). node_exporter 1.3.1 with GOMAXPROCS=1 set via systemd override (I can share how much worse it looked before setting that).

Those queries are

avg_over_time(node_load1{instance="$instance"}[$__interval])

and

rate(process_cpu_seconds_total{instance="$instance", job="node"}[$__rate_interval])

You can see when I disabled the cpufreq collector on the 26th. All the little load spikes went away (there are still some spikes from real work). A nice drop in the CPU utilization as well.

Installing 1.5.0 today yielded even better results with the CPU. I briefly re-enabled cpufreq on 1.5.0 - still an issue.

cpufreq is probably only an issue on these sorts of large hosts but it seems common enough on those that it should not be enabled by default.

This looks to be an issue on about 20% of my hosts - i.e., all of the large ones.

[SuperQ]

It would be useful to get a pprof CPU profile when the problem is happening.

Load average is not really a useful metric, as it doesn't really reflect any real world problem.

[britcey]

Load average is not really a useful metric, as it doesn't really reflect any real world problem.

Agreed, but it's what got my users complaining. The CPU utilization is real (not huge, but real).

Let me scare up a suitable test host and get that pprof profile.

[britcey]

pprof.node_exporter.samples.cpu.001.pb.gz

This is from the same machine that's shown in the graph. node_exporter 1.5.0, only --web.listen-address & --collector.textfile.directory specified.

It was just a single scrape - let me know if you want one with repeated scrapes (my poll interval is 10s).

[SuperQ]

Hmm, that pprof file is only showing 80ms of CPU time over 60s. Even if it's just one scrape over 10s, that's only 0.8% average CPU use. I don't see much we can improve on there. Most of the time is spent in syscalls, which we don't have a lot of control over, that's up to the kernel.

[britcey]

Could there be a cumulative issue that shows up after repeated scrapes? You can see from the graph that CPU utilization is cut by more than half when cpufreq was disabled in production, which seems significant.

It'll also be 2 scrapes in 10 seconds, since there are two pollers.

[SuperQ]

Could there be a cumulative issue that shows up after repeated scrapes

Not likely. This code is very simple and basically no different to other collectors.

The only issue that I can see, which is specific to cpufreq, is there is something wrong with the Kernel access to the data.

[britcey]

This is interesting:

I've got a group with a few dozen hosts with the same workload (OpenStack host nodes), but about half are AMD-based and the others Xeon-based - all of the Xeon-based hosts show elevated CPU consumption by node_exporter (~ 8%, with a couple significantly higher).

None of the AMD-based ones do (~ 1.2%).

(they're all running 1.5.0).

Edit:

It's a bit more complicated, as the Xeon-based hosts are still running 1.3.1. I'll talk to the group next week and see if they can get to 1.5.0 across the board so we can do an apples-to-apples comparison.

[eero-t]

@britcey How many cores and hyperthreads your Xeon and AMD hosts have?

(I'm asking because freq info is per core, so that affects how much overhead querying them has.)

[eero-t]

It's a bit more complicated, as the Xeon-based hosts are still running 1.3.1. I'll talk to the group next week and see if they can get to 1.5.0 across the board so we can do an apples-to-apples comparison.

@britcey The relevant change is GOMAXPROCS=1. You can do that with pod spec env var without upgrading node_exporter.

As to 1.5.0 instances, new --collector.netclass.netlink option is not the default, so you could try whether that has any impact.

[eero-t]

Load average is not really a useful metric, as it doesn't really reflect any real world problem.

IMHO list of run queue wait wait list size is more useful metric than CPU frequency, which is basically a (strongly biased) random number gauge, as its value can change hundreds of times per second, but node_exporter is not polling it at a frequency that would catch those changes (for obvious reasons).

The only issue that I can see, which is specific to cpufreq, is there is something wrong with the Kernel access to the data.

When its done from threads reading that for all cores at same time, it's lock contention.

While core frequency may have once (in last century) been a kernel variable you can just read, nowadays frequency is controlled by firmware, and kernel needs to use MSR registers to query current frequency for given core:

• https://github.com/torvalds/linux/blob/master/drivers/cpufreq/acpi-cpufreq.c#L84

Accessing core MSR reqisters requires locks and waits. See:

• https://github.com/torvalds/linux/blob/master/arch/x86/lib/msr-smp.c#L36
• https://github.com/torvalds/linux/blob/master/kernel/smp.c#L720

[britcey]

@britcey How many cores and hyperthreads your Xeon and AMD hosts have?

Two models of Xeon:
CPU(s): 40
Thread(s) per core: 2
Core(s) per socket: 20
Socket(s): 1

CPU(s): 96
Thread(s) per core: 2
Core(s) per socket: 24
Socket(s): 2

AMD:
CPU(s): 64
Thread(s) per core: 2
Core(s) per socket: 32
Socket(s): 1

@britcey The relevant change is GOMAXPROCS=1. You can do that with pod spec env var without upgrading node_exporter.

I had a further CPU reduction going from 1.3.1 w/ GOMAXPROCS=1 to 1.5.0 but just getting GOMAXPROCS would indeed be a better comparison - I'll see what they say.

[britcey]

FYI, I haven't forgotten this, just waiting on another group to upgrade node_exporter to 1.5.0 so we can compare their AMD & Xeon hosts.

[lyveng]

@SuperQ We are facing a similar issue and we have a reproducible test case. We use similar hardware:
CPU(s): 96
Thread(s) per core: 2
Core(s) per socket: 24
Socket(s): 2

This problem doesn't seem to affect all workloads. Specifically it affected the performance of a certain java workload. We tried running stress-ng with cpufreq collector enabled and disabled and noticed that it did not have any noticeable impact. But for the java workload the impact was massive:

1. throughput dropped by 10%
2. mean latency increased by 25%
3. tail latencies doubled, i.e., increased by 100%

The primary observation is that the run queue length(seen in output of vmstat) seems to almost drop to 0 every 5 to 10 seconds. The cpu utilisation also drops almost to 0 during this time. We did JFR profiling for the same workload with and without cpufreq enabled in node exporter. The cpu utilisation was spikey here as well

java workload cpu utilisation when cpufreq collector is enabled

java workload cpu uilisation when cpufreq collector is disabled

stress-ng output when cpufreq collector is enabled

# stress-ng --taskset 0-95 -c 96 --cpu-method all --metrics-brief -t 30
stress-ng: info:  [2376019] dispatching hogs: 96 cpu
stress-ng: info:  [2376019] successful run completed in 30.03s
stress-ng: info:  [2376019] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s
stress-ng: info:  [2376019]                           (secs)    (secs)    (secs)   (real time) (usr+sys time)
stress-ng: info:  [2376019] cpu             2044289     30.00   2841.41      1.38     68136.33         719.11

stress-ng output when cpufreq collector is disabled

# stress-ng --taskset 0-95 -c 96 --cpu-method all --metrics-brief -t 30
stress-ng: info:  [2378142] dispatching hogs: 96 cpu
stress-ng: info:  [2378142] successful run completed in 30.03s
stress-ng: info:  [2378142] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s
stress-ng: info:  [2378142]                           (secs)    (secs)    (secs)   (real time) (usr+sys time)
stress-ng: info:  [2378142] cpu             2033389     30.00   2850.53      1.09     67773.24         713.06
# stress-ng --taskset 0-95 -c 96 --cpu-method all --metrics-brief -t 30
stress-ng: info:  [2378627] dispatching hogs: 96 cpu
stress-ng: info:  [2378627] successful run completed in 30.03s
stress-ng: info:  [2378627] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s
stress-ng: info:  [2378627]                           (secs)    (secs)    (secs)   (real time) (usr+sys time)
stress-ng: info:  [2378627] cpu             2054517     30.00   2835.17      1.87     68475.13         724.18

We also generated flamegraph with and without cpufreq collector enabled

1. flamegraph with cpufreq collector enabled -
2. flamegraph with cpufreq collector disabled -
   

From both these flamegraphs, the function osq_lock seems to be have been held for almost same time ~14.9% in both cases

We also ran the bpf tool klockstat with and without cpufreq collector enabled

1. cpufreq collector enabled - lock_analysis_cpufreq_java.log
2. cpufreq collector disabled - lock_analysis_wo_cpufreq_java.log

The specific lines of interest in the klockstat output when cpufreq collector is enabled is

                                  Caller   Avg Spin  Count   Max spin Total spin
           b'kernfs_dop_revalidate+0x33'     255479 833203 18446744071814924592 212866659508
           b'kernfs_dop_revalidate+0x33'     196896 416598 18446744071812460639 82026580458
           b'kernfs_iop_permission+0x29'     249223 1249808 18446744071811711629 311481831642
           b'kernfs_iop_permission+0x29'     244866 416594 18446744071810605667 102009733672
              b'kernfs_iop_getattr+0x28'     175374 416592 18446744071807082659 73059481320

It looks like the max spin and total spin are crossing the limits of u64.

So these functions(kernfs_dop_revalidate, kerfs_iop_permission, kernfs_iop_getattr) have mutexes where the threads are blocking and these functions in-turn are calling osq_lock which is a spinlock. The primary difference between cpufreq enabled and disabled is acquiring these mutexes seems to take a lot of time when cpufreq collector is enabled. Unfortunately the flamegraph doesn't has the stack between java and these functions as unknown. I'm already using perf-map-agent scripts to generate the flame graph and symbols for the application code seems to work fine.
I tried to use the fileslower bpf tool to see opening of which files is blocking on these mutexes. But in both cases(cpufreq enabled and disabled), the java process was accessing only cgroup related files and the max latency was only 10-15ms.

I tried writing a bpftrace program to record files that are opened using the openat2 syscall and is taking more than a certain threshold like 50ms. But getting some errors in the program. I'll try to get it running

@SuperQ We can have a joint debugging session to root cause this if required. We would not be able to give access to the systems since they are behind a vpn. As of now we have disabled cpufreq collector in our systems.

[SuperQ]

@lyveng What version of node_exporter was used in your testing?

[lyveng]

Node Exporter - v1.4.1
Kubernetes - 1.22.12
Kernel - 5.10.0-21-amd64
OS - Debian 11.6

I also checked the Lock instances tab of JFR dumps in Java mission control. There were no major differences between java's locks between the 2 dumps. I think this is because JFR records only concurrency primitives native to java like synchronized keyword.

[lyveng]

Node Exporter is allocated the following resources:

node-expoter: 
  resources:
      limits:
        cpu: 100m
        memory: 512Mi
      requests:
        cpu: 100m
        memory: 128Mi
kube-rbac-proxy: 
    resources:
      limits:
        cpu: 20m
        memory: 40Mi
      requests:
        cpu: 10m
        memory: 20Mi

We install node-exporter using kube-prometheus stack.

[SuperQ]

@lyveng That version is too old. As noted above, 1.5.0 from November 2022 includes changes that should make this problem go away.

Also, I don't recommend setting CPU limits on the node_exporter, rather, using the new version that sets GOMAXPROCS to 1.

[lyveng]

Setting GOMAXPROCS to 1 in node exporter 1.4.1 fixed the issue temporarily although I didn't run it for a longer period to validate. I went through #2500 to understand how the application threads get blocked because of the kernel bug. So it doesn't seem to be related to cpufreq except for the fact that one goroutine per core is spawned(coderef) which causes heavy concurrent access of the sysfs on systems with large number of cpus.

We are using linux kernel 5.10. I'm trying to figure out if the commit 289caf5d8f6c61c6d2b7fd752a7f483cd153f182 that seems to be fixing this race condition(as per comment) is present in our kernel or not.

Also is there any other reason why this ticket is kept open? Just asking to see if there are any other bugs to look out for.

[SuperQ]

We left this open as we were waiting for confirmation that the issue is fixed enough. Also in case there were additional mitigations or fixes that would more permanently solve this.

If everyone is happy with the GOMAXPROCS workaround, we can call this solved.

Ping @britcey

[kucharskim]

@SuperQ which version of Node Exporter should have this problem fixed?

[SuperQ]

@kucharskim Please do not at-mention me asking about things that are answered several times in this issue. That is rude, and especially bad that you have failed to read the thread here. If you continue to do this you will be banned.

[SuperQ]

Since this has been fixed, and have not gotten any additional reports, I am closing this.