ETCD getting "apply request took too long" log frequently

[MohamedShaj]

Environmental Info:
K3s Version: v1.28.4+k3s2

Node(s) CPU architecture, OS, and Version: 8vCPU with 32GB memory

Cluster Configuration: [3node master+ worker cluster]

Describe the bug:

Hi all,
I am using k3s 1.28 version with embedded etcd for the HA cluster,
i can see the too long warning logs, often , asper k3s and etcd recommendation i made /var/lib/etcd as a sperated SSD[ azure premium disk ] with 7.2k I/O [too high] but still this is coming ...
the problem is after some days like 90+ the etcd cluster became unstable and sometimes corrupted too, i suspect this slow disk was the issue, but keeping I/O and throughput high also nothing making any difference,
can anyone just explain, what may be the issue?
If any particular details are needed, let me know will try to share ASAP

Jan 10 07:55:33 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:33.433522Z","caller":"etcdserver/v3_server.go:897","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":11249020940439591963,"retry-timeout":"500ms"}
Jan 10 07:55:33 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:33.933832Z","caller":"etcdserver/v3_server.go:897","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":11249020940439591963,"retry-timeout":"500ms"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.435038Z","caller":"etcdserver/v3_server.go:897","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":11249020940439591963,"retry-timeout":"500ms"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.5922Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.658728478s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/longhorn-system/external-snapshotter-leader-driver-longhorn-io\" ","response":"range_response_count:1 size:542"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593284Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.488088s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:496"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593316Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"966.225764ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/default/strimzi-cluster-operator\" ","response":"range_response_count:1 size:501"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593519Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.488300003s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/k3s-cloud-controller-manager\" ","response":"range_response_count:1 size:505"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593385Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"375.878915ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/longhorn.io/backingimagedatasources/\" range_end:\"/registry/longhorn.io/backingimagedatasources0\" count_only:true ","response":"range_response_count:0 size:6"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593426Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.261899945s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/masterleases/10.1.0.4\" ","response":"range_response_count:1 size:128"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593355Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.371287984s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/longhorn-system/driver-longhorn-io\" ","response":"range_response_count:1 size:491"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593462Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"1.029944328s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:479"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593474Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"656.915943ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/longhorn-system/external-snapshotter-leader-driver-longhorn-io\" ","response":"range_response_count:1 size:542"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593482Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"914.91463ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/k3s-etcd\" ","response":"range_response_count:1 size:457"}
Jan 10 07:55:34 MULTI-SINGLE-VM k3s[820]: {"level":"warn","ts":"2024-01-10T07:55:34.593437Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"603.718489ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/longhorn-system/driver-longhorn-io\" ","response":"range_response_count:1 size:491"}

[brandond]

Can you provide CPU utilization and disk iops stats from this node over the time period in question? I'm not aware of anything that will cause this other than not having sufficient resources for etcd.

[brandond]

Did you put it on a separate physical disk, or just a separate partition?

If putting it on a different disk does not help, it's possible that disk IO is not your bottleneck, but instead it is cpu throttling or memory.

[MohamedShaj]

Did you put it on a separate physical disk, or just a separate partition?

If putting it on a different disk does not help, it's possible that disk IO is not your bottleneck, but instead it is cpu throttling or memory.

Separate SSD for those mentioned above,

Okay ll try to increase CPU and memory for time being to check the logs level decrease or not

[MohamedShaj]

Did you put it on a separate physical disk, or just a separate partition?

If putting it on a different disk does not help, it's possible that disk IO is not your bottleneck, but instead it is cpu throttling or memory.

And correct me if I am wrong,

These disk pressure due to IO or CPU/mem ll lead to cluster unstable right and etcd cluster to unhealthy / sometime data corruption too

[brandond]

If you are seeing data corruption, then you have other problems. This should lead to an unresponsive or unstable server node at worst.

[MohamedShaj]

If you are seeing data corruption, then you have other problems. This should lead to an unresponsive or unstable server node at worst.

Still not trouble shooted on data corruption part,

I always fix by cluster reset with recent snapshots,

I am in assumption that so the current data was corrupted or something happened so snapshots restore works,

But you are right in some worst case scenario node goes unstable and server restart works

[MohamedShaj]

If you are seeing data corruption, then you have other problems. This should lead to an unresponsive or unstable server node at worst.

After making cpu and memory high , the etcd logs has been reduced in last 4 hours i can only few logs

"caller":"etcdserver/v3_server.go:815","msg ":"waiting for ReadIndex response took too long, retrying","sent-request-id":16450664162270192921,"retry-timeout":"500ms"}

i can see the pattern after this reindex logs only few logs comings !!!

this also related to disk i/o or resource utilization ?

[kimabd]

same case for me on k8s v1.28.4,
too many messages - apply request took too long and leader changed
SSD
4 core(no more than 50% in use) and 4GB(no more than 65% in use) RAM
3 master instances

[brandond]

Look at your disk IO performance.