High IOPS on K3s Agent Causes Node to Become Unavailable

[gaecfov]

Environmental Info:
K3s Version:
k3s version v1.31.1+k3s1 (452dbbc)
go version go1.22.6

Node(s) CPU architecture, OS, and Version:
Linux je-k3s-test-node-05 5.10.134-17.2.al8.x86_64 #1 SMP Fri Aug 9 15:49:42 CST 2024 x86_64 x86_64 x86_64 GNU/Linux

Cluster Configuration:
1 servers，6 agents

Describe the bug:

• Using iotop on the affected agent nodes, it was observed that the k3s-agent process generates a significant amount of read IO.
• This spike in IO activity coincides with the node becoming unavailable.

Steps To Reproduce:

1. Deploy a K3s cluster with multiple agent nodes.
2. Monitor the agent nodes for a period of time under normal workload.
3. Observe random occurrences of high IOPS on one of the agent nodes, leading to node unavailability.

Additional context / logs:

Timestamp: Thu Dec 5 02:03:09 PM CST 2024
Total DISK READ : 68.16 M/s | Total DISK WRITE : 122.51 K/s
Actual DISK READ: 20.26 M/s | Actual DISK WRITE: 747.97 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
b' 54680 be/4 root 9.31 M/s 0.00 B/s 0.00 % 47.29 % node_exporter --web.listen-address=:9101'
b' 1702 be/4 root 42.12 M/s 0.00 B/s 0.00 % 42.09 % k3s agent'
b' 1665 be/4 root 0.00 B/s 0.00 B/s 0.00 % 13.10 % containerd'
b' 1316 be/4 root 15.81 M/s 0.00 B/s 0.00 % 12.45 % k3s agent'
b' 1654 be/4 root 838.24 K/s 0.00 B/s 0.00 % 11.52 % containerd'

What factors are involved in the io of k3s to disk? Has anyone encountered this problem?

[brandond]

What do you mean by unavailable? Is the os crashing? Is it thrashing swap memory? Is it pulling images? You'll need to figure out what it's actually doing. The agent doesn't do much other than run pods.

[gaecfov]

What I mean is that when IOPS is overloaded, the agent shows as NotReady. The monitoring system indicates that both CPU and memory usage are close to 100%. At this point, it is no longer possible to log in to the operating system, so I am not sure if it is caused by pulling images.

Dec  5 14:09:17 k3s[1148]: I1205 14:09:17.625718    1148 pod_startup_latency_tracker.go:104] "Observed pod startup duration" pod="oms/oms-nginx-beta-977cd9887-hbtpn" podStartSLOduration=1.8712444000000001 podStartE2EDuration="3.625703511s" podCreationTimestamp="2024-12-05 14:09:14 +0800 CST" firstStartedPulling="2024-12-05 14:09:14.8015754 +0800 CST m=+80348.492247940" lastFinishedPulling="2024-12-05 14:09:16.556034511 +0800 CST m=+80350.246707051" observedRunningTime="2024-12-05 14:09:17.625427202 +0800 CST m=+80351.316099764" watchObservedRunningTime="2024-12-05 14:09:17.625703511 +0800 CST m=+80351.316376072"
Dec  5 14:13:08 k3s[1148]: E1205 14:13:08.829281    1148 kubelet.go:2512] "Housekeeping took longer than expected" err="housekeeping took too long" expected="1s" actual="3.596s"
Dec  5 14:13:12 k3s[1148]: E1205 14:13:12.142896    1148 kubelet.go:2512] "Housekeeping took longer than expected" err="housekeeping took too long" expected="1s" actual="1.154s"
Dec  5 14:13:24 k3s[1148]: E1205 14:13:22.430771    1148 kubelet.go:2512] "Housekeeping took longer than expected" err="housekeeping took too long" expected="1s" actual="1.222s"
Dec  5 14:13:49 k3s[1148]: E1205 14:13:48.832000    1148 health_controller.go:178] Metrics Controller heartbeat missed
Dec  5 14:14:08 k3s[1148]: E1205 14:13:50.012568    1148 health_controller.go:178] Metrics Controller heartbeat missed
Dec  5 14:14:08 k3s[1148]: E1205 14:13:50.012612    1148 health_controller.go:178] Metrics Controller heartbeat missed
Dec  5 14:14:58 k3s[1148]: W1205 14:14:37.550367    1148 transport.go:356] Unable to cancel request for *otelhttp.Transport
Dec  5 14:15:35 k3s[1148]: E1205 14:15:00.116465    1148 health_controller.go:178] Metrics Controller heartbeat missed
Dec  5 14:15:54 k3s[1148]: E1205 14:15:49.534992    1148 server.go:309] "Unable to authenticate the request due to an error" err="context canceled"
Dec  5 14:16:49 k3s[1148]: E1205 14:16:44.456055    1148 server.go:309] "Unable to authenticate the request due to an error" err="context canceled"
Dec  5 14:17:48 k3s[1148]: time="2024-12-05T14:17:38+08:00" level=error msg="Error writing ping" error="websocket: write timeout"
Dec  5 14:18:05 k3s[1148]: E1205 14:16:35.248177    1148 health_controller.go:142] Network Policy Controller heartbeat missed
Dec  5 14:18:05 k3s[1148]: E1205 14:16:21.857270    1148 webhook.go:154] Failed to make webhook authenticator request: webhook call failed: context deadline exceeded
Dec  5 14:18:39 k3s[1148]: E1205 14:17:57.541626    1148 log.go:32] "ListContainers with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="&ContainerFilter{Id:,State:nil,PodSandboxId:,LabelSelector:map[string]string{},}"
Dec  5 14:18:39 k3s[1148]: E1205 14:17:57.924671    1148 log.go:32] "ListContainerStats with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="&ContainerStatsFilter{Id:,PodSandboxId:,LabelSelector:map[string]string{},}"
Dec  5 14:19:07 k3s[1148]: I1205 14:18:37.128872    1148 log.go:245] http: TLS handshake error from 172.16.16.1:50601: write tcp 172.16.32.12:10250->172.16.16.1:50601: write: broken pipe
Dec  5 14:19:07 k3s[1148]: E1205 14:18:37.644923    1148 health_controller.go:178] Metrics Controller heartbeat missed
Dec  5 14:19:07 k3s[1148]: E1205 14:17:28.238027    1148 log.go:32] "ListContainerStats with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="&ContainerStatsFilter{Id:,PodSandboxId:,LabelSelector:map[string]string{},}"
Dec  5 14:20:05 k3s[1148]: W1205 14:19:09.448906    1148 reflector.go:484] object-"oms"/"kube-root-ca.crt": watch of *v1.ConfigMap ended with: an error on the server ("unable to decode an event from the watch stream: http2: client connection lost") has prevented the request from succeeding
Dec  5 14:20:05 k3s[1148]: E1205 14:19:16.930738    1148 container_log_manager.go:197] "Failed to rotate container logs" err="failed to list containers: rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Dec  5 14:20:05 k3s[1148]: W1205 14:18:50.436892    1148 reflector.go:484] k8s.io/[email protected]/tools/cache/reflector.go:243: watch of *v1.Node ended with: an error on the server ("unable to decode an event from the watch stream: http2: client connection lost") has prevented the request from succeeding
Dec  5 14:20:05 k3s[1148]: W1205 14:19:17.344186    1148 reflector.go:484] k8s.io/[email protected]/tools/cache/reflector.go:243: watch of *v1.RuntimeClass ended with: an error on the server ("unable to decode an event from the watch stream: http2: client connection lost") has prevented the request from succeeding
Dec  5 14:20:05 k3s[1148]: W1205 14:19:03.144712    1148 reflector.go:484] k8s.io/[email protected]/tools/cache/reflector.go:243: watch of *v1.Endpoints ended with: an error on the server ("unable to decode an event from the watch stream: http2: client connection lost") has prevented the request from succeeding
Dec  5 14:20:05 k3s[1148]: I1205 14:19:23.934122    1148 log.go:245] http: TLS handshake error from 172.16.16.1:42457: write tcp 172.16.32.12:10250->172.16.16.1:42457: write: broken pipe
Dec  5 14:20:05 k3s[1148]: E1205 14:19:24.841342    1148 server.go:309] "Unable to authenticate the request due to an error" err="context canceled"
Dec  5 14:20:05 k3s[1148]: E1205 14:19:24.239177    1148 resource_metrics.go:161] "Error getting summary for resourceMetric prometheus endpoint" err="failed to list pod stats: failed to list all container stats: rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Dec  5 14:20:05 k3s[1148]: E1205 14:19:27.148860    1148 health_controller.go:142] Network Policy Controller heartbeat missed
Dec  5 14:22:51 k3s[1148]: time="2024-12-05T14:19:31+08:00" level=error msg="Error syncing connections" error="i/o timeout"
Dec  5 14:22:51 k3s[1148]: E1205 14:19:52.540037    1148 health_controller.go:178] Metrics Controller heartbeat missed
Dec  5 14:22:51 k3s[1148]: E1205 14:19:25.833052    1148 log.go:32] "ListImages with filter from image service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="nil"
Dec  5 14:22:51 k3s[1148]: E1205 14:19:33.332042    1148 log.go:32] "ContainerStatus from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="05eb015134856837020b09fb6641b9fed0af3323715a5969e4c3c7ab34a34beb"
Dec  5 14:22:51 k3s[1148]: E1205 14:18:48.229365    1148 log.go:32] "ListContainers with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="&ContainerFilter{Id:,State:&ContainerStateValue{State:CONTAINER_RUNNING,},PodSandboxId:,LabelSelector:map[string]string{},}"
Dec  5 14:22:51 k3s[1148]: E1205 14:19:04.332296    1148 log.go:32] "ListPodSandbox with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="nil"
Dec  5 14:22:51 k3s[1148]: I1205 14:19:51.056246    1148 log.go:245] http: TLS handshake error from 172.16.16.1:16528: write tcp 172.16.32.12:10250->172.16.16.1:16528: write: broken pipe
Dec  5 14:22:51 k3s[1148]: W1205 14:20:43.158841    1148 reflector.go:484] k8s.io/[email protected]/tools/cache/reflector.go:243: watch of *v1.Service ended with: an error on the server ("unable to decode an event from the watch stream: http2: client connection lost") has prevented the request from succeeding
Dec  5 14:22:51 k3s[1148]: E1205 14:20:53.551273    1148 log.go:32] "Status from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Dec  5 14:34:08 systemd: systemd-journald.service: State 'stop-sigabrt' timed out. Terminating.
Dec  5 14:34:27 systemd: systemd-journald.service: State 'stop-sigterm' timed out. Killing.
Dec  5 14:34:33 systemd: systemd-journald.service: Killing process 537 (systemd-journal) with signal SIGKILL.
Dec  5 14:22:51 k3s[1148]: E1205 14:19:33.332042    1148 log.go:32] "ContainerStatus from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="05eb015134856837020b09fb6641b9fed0af3323715a5969e4c3c7ab34a34beb"
Dec  5 14:22:51 k3s[1148]: E1205 14:18:48.229365    1148 log.go:32] "ListContainers with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="&ContainerFilter{Id:,State:&ContainerStateValue{State:CONTAINER_RUNNING,},PodSandboxId:,LabelSelector:map[string]string{},}"
Dec  5 14:22:51 k3s[1148]: E1205 14:19:04.332296    1148 log.go:32] "ListPodSandbox with filter from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" filter="nil"
Dec  5 14:22:51 k3s[1148]: I1205 14:19:51.056246    1148 log.go:245] http: TLS handshake error from 172.16.16.1:16528: write tcp 172.16.32.12:10250->172.16.16.1:16528: write: broken pipe
Dec  5 14:22:51 k3s[1148]: W1205 14:20:43.158841    1148 reflector.go:484] k8s.io/[email protected]/tools/cache/reflector.go:243: watch of *v1.Service ended with: an error on the server ("unable to decode an event from the watch stream: http2: client connection lost") has prevented the request from succeeding
Dec  5 14:22:51 k3s[1148]: E1205 14:20:53.551273    1148 log.go:32] "Status from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded"

[brandond]

Well yes, if the node is unreachable it will show in the cluster as not ready. That is what not ready means. The node is not communicating with the cluster. Could be because you stopped k3s, could be because the whole node has tanked and locked up.

In this case given you have 100% memory utilization followed by 100% cpu utilization and high disk IO, I suspect you're running with swap enabled and have deployed a workload with no resource limits that is using all available resources and pushing the node into thrashing the swap memory.

Don't do that.

[gaecfov]

Thank you very much, I need to check if there are any resource constrained workloads first