Nomad servers memory leak and all allocations restarts after "nomad system gc"

[beninghton]

Nomad version

Nomad v1.6.0
BuildDate 2023-07-18T18:51:11Z
Revision 87d411f

Operating system and Environment details

Fedora release 35 (Thirty Five)

Issue

We have 3 master nodes cluster with 2 CPU, 4 RAM each. We have 30 client nodes.
The resourses was enough before, but we started to see memory leak - during a week the RAM is exausted on each of the node.
We started to see it on 1.5.6 version, we did not face this before this 1.5.6.
Recently we updated 1.5.6 to 1.6.0 hoping that this problem will dissapear.
You can see on 07/20 is our update time for new 1.6.0 version:

But a week passed, and all 3 servers were almost out of RAM.
We didn't find anything related in logs, except some raft error messages (log files in the attachments), so we decided to run "nomad system gc" on server-1 hoping that some resources will be freed.
But after that, we lost connection to the server-1 and some client nodes started to fail heartbeats and allocations on them were restarted. We did not see this behaviour before 1.5.6 version. It's unacceptable.

Reproduction steps

"nomad system gc" in exausted resoures situation.

Expected Result

Free some RAM, cluster not restarts allocations.

Actual Result

During freeing RAM, cluster fails client node heartbeats and restarts allocations.
We think all this is related to:
#17973
#17974
Because the node server-1 on which we run "nomad system gc" was out of resources and stopped to respond to the cluster.

But we can't find the reason of memory leak.
Please advise what we can do to avoid it.

Nomad Server logs for last 24h

"nomad system gc" was run at was run at 2023-07-26T04:34:00 on server-1. After that we lost connection to the server for a while.
server1.log
server2-leader.log
server3.log

Nomad Client logs for last 24h

Multiple clients disconnected, here's log of one of them:
client1.log

[jrasell]

Hi @beninghton and thanks for raising this issue.

In order to try and identify any potential memory leak, we would need some additional profiling information. It would also be useful to understand what type of workload you are running and a rough idea of the cluster activity. In order to grab profiling data the following steps can be used, ideally gathering a couple of intervals to show changes:

• Set enable_debug = true on one of the servers
• ssh onto that instance
• hit :4646/debug/pprof/heap and :4646/debug/pprof/goroutine (note: without any leading v1). That hits the underlying pprof interface directly, bypassing any possible Nomad RPC forwarding.

"nomad system gc" on server-1 hoping that some resources will be freed. But after that, we lost connection to the server-1

This seems coincidental timing as that command will always be forwarded onto the Nomad leader. Once the leader receives the request, it will build a list of resources for deletion and then propagate this via Raft to other Nomad servers in the cluster.

In the logs on the Nomad servers I noticed the following example line showing up a number of times.

worker: timeout waiting for Raft index required by eval: worker_id=70140a75-4f08-b029-30c2-730f3d7a5387 eval=6d2006f3-d448-8b81-c33c-27288c110b63 index=22358888 timeout=5s

This would indicate Raft is struggling to keep up with the cluster activity. Do you have any disk IO monitoring on the Nomad servers along with any monitoring of the Raft subsystem?

The client logs include the line "node registration complete" numerous times, which suggests the clients are having to re-register themselves continually which is not expected behaviour. The logs unfortunately to not indicate what might be causing this behaviour but this could potentially be due to the Nomad client changing its configuration with device, driver, or meta changes.

[tgross]

@jrasell leaving a note that @beninghton has #17973 #17974 open as well. I agree that this smells a lot to me like the cluster is having Raft issues (ref https://developer.hashicorp.com/nomad/docs/operations/monitoring-nomad#key-performance-indicators would be a good place to look too). @beninghton I'm going to cross-reference from those issues over to here so that we don't have multiple Nomad Engineers trying to debug what looks to be the same problem; hopefully we'll be able to close them all out together. 😀

[beninghton]

This seems coincidental timing as that command will always be forwarded onto the Nomad leader. Once the leader receives the request, it will build a list of resources for deletion and then propagate this via Raft to other Nomad servers in the cluster.

The GC command definitely generated high cpu/mem/disk load on non-leader server-1, and it stopped to respond by ssh, but the leader was server-2, and server-2 was fine(load ~90% but responsive).
I'm sure that it's not coincidental timing because it happened twice (we had the same issue before, just did not open the ticket on github). During next few hours after the GC comand was run the memory eventually decreased to normal values.

This would indicate Raft is struggling to keep up with the cluster activity. Do you have any disk IO monitoring on the Nomad servers along with any monitoring of the Raft subsystem?

Yes, we monitor cpu/mem/net/disk via node_exporter installed on the servers. And we also monitor the Raft system and have corresponding Grafana dashboards, but we don't know how to correctly interpret what we see.
We see that during that memory leak I/O writes to disk and Raft apply count was increased accordingly.
I can show you some graphs for last 7d:



The peaks down on 26th - it's the time I ran GC and created this issue after that.
Please just tell if you need more information and I will be glad to provide it.

The client logs include the line "node registration complete" numerous times, which suggests the clients are having to re-register themselves continually which is not expected behaviour. The logs unfortunately to not indicate what might be causing this behaviour but this could potentially be due to the Nomad client changing its configuration with device, driver, or meta changes.
It would also be useful to understand what type of workload you are running and a rough idea of the cluster activity.

We have gpu workloads in nomad, we use "nvidia" runtime for most of our jobs.
And we also actively work with meta. We have a meta parser job running on each node, parsing it every 30s on each node (via api sock) and updating its meta.
So you say one of root causes of the problem might be meta changes? How can we know it for sure? It's not possible right now to just disable parsing/updating it, but we can try to decrease the interval.

hit :4646/debug/pprof/heap and :4646/debug/pprof/goroutine (note: without any leading v1). That hits the underlying pprof interface directly, bypassing any possible Nomad RPC forwarding.

@jrasell I've enabled the debug, restarted nomad servers to apply the new config.
After that I started to gather heap with ~2-3h interval and gathered 3 times from each of the server. Please find the files attached in the archive.
debug.zip

Please also find debug logs from all 3 servers for last 6h:
server-1.log
server-2.log
server-3.log

[jrasell]

The GC command definitely generated high cpu/mem/disk load on non-leader server-1, and it stopped to respond by ssh, but the leader was server-2, and server-2 was fine(load ~90% but responsive).
I'm sure that it's not coincidental timing because it happened twice (we had the same issue before, just did not open the ticket on github). During next few hours after the GC comand was run the memory eventually decreased to normal values.

Yes, I should have clarified that I meant the command is not ran immediately on the server it is triggered against, but is forwarded to the leader. The GC will impact all servers as it will enact Raft transactions as well as memory management when removing old data.

Please just tell if you need more information and I will be glad to provide it.

The graphs are interesting thank you and generally show unhealthiness in the Raft subsystem; the commit times continually spiking in the 2-6s range is certainly something to monitor and a be concerned about. Could you clarify what metric the "Raft Apply Count" is based on?

And we also actively work with meta. We have a meta parser job running on each node, parsing it every 30s on each node (via api sock) and updating its meta.
So you say one of root causes of the problem might be meta changes? How can we know it for sure? It's not possible right now to just disable parsing/updating it, but we can try to decrease the interval.

Do you have the ability to share this or expand on what changes the job is looking for and making on each run?

When a Nomad client changes it's meta and re-registers with the Nomad servers, the Raft object is updated. Nomad will also create an evaluation per allocation that is on the client, and per system job within the datacenter. In a cluster of 30 clients, each updating their meta every 30s, this means we are doing this every ~1s. Even if these evals are noops, they must be processed by the scheduler and the eval objects persisted in state until it is GC'd. It might be possible to lower the value of the server.eval_gc_threshold configuration value to ensure evals are GC'd quicker and put less pressure on the server memory.

The heap data also shows that the node updates are consistently accounting for the majority of work:

      flat  flat%   sum%        cum   cum%
  140.01MB 29.07% 29.07%   254.54MB 52.85%  github.com/hashicorp/go-immutable-radix.(*Txn).insert
  128.52MB 26.68% 55.75%   128.52MB 26.68%  github.com/hashicorp/go-immutable-radix.(*Txn).writeNode

[beninghton]

The graphs are interesting thank you and generally show unhealthiness in the Raft subsystem; the commit times continually spiking in the 2-6s range is certainly something to monitor and a be concerned about. Could you clarify what metric the "Raft Apply Count" is based on?

"Raft Apply Count" is based on "nomad_raft_apply" metric.
The graph query is increase(nomad_raft_apply{env="$env"}[$__rate_interval])

Do you have the ability to share this or expand on what changes the job is looking for and making on each run?

We have a system job on each node containing GPU (it's ~15 nodes).
The code of the job is in a loop and every 30s it goes to its node api via socket, then parses its allocations and Meta. We place GPU parameters such as total gpu mem and utilization as host Meta. The job also parses some values locally using nvidia-smi, then updates Meta on its host. So the meta data is updated quite frequently because the gpu data is constantly changed and we want it to be actual in host meta.

When a Nomad client changes it's meta and re-registers with the Nomad servers, the Raft object is updated. Nomad will also create an evaluation per allocation that is on the client, and per system job within the datacenter. In a cluster of 30 clients, each updating their meta every 30s, this means we are doing this every ~1s. Even if these evals are noops, they must be processed by the scheduler and the eval objects persisted in state until it is GC'd. It might be possible to lower the value of the server.eval_gc_threshold configuration value to ensure evals are GC'd quicker and put less pressure on the server memory.

But the server.eval_gc_threshold default is 1h, how it happens then that we have a memory leak during 1 week? And it's not cleaned ever until we manually run "nomad system gc". Do you think it will change something if we set "eval_gc_threshold" to 30min?
So you say that the current architecture is "the Raft object is updated on every meta". I guess it means that we shoudn't update meta frequently? It was not obvious and means that meta is less usable that we thought initially.
But anyway, it does not explain why we have memory leak, I guess it's some bug?