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.

[rmelilloii]

Hello hello!
I have a similar issue. I've even created a monitoring/alerting for the "etcd sync status" as I use the k3s embedded etcd.

It occurs even on my new cluster that has nothing yet running on it.
Is there anything to be done? Or should I just NOT run the embedded version so I have more control/visibility?

VMs (3 nodes)
VCPU: 32
RAM: 128 GB
DISK LOCAL (SSD): 600 GB

Kubernetes
Version: v1.25.9+k3s1
OS: Ubuntu 24.04 LTS
Container Runtime: containerd://1.6.19-k3s1

Log example:

k3s[1215]: {"level":"warn","ts":"2024-07-03T13:44:03.921Z","caller":"etcdserver/util.go:166","msg":"apply request took too long","took":"143.243043ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/mutatingwebhookconfigurations/\" range_end:\"/registry/mutatingwebhookconfigurations0\" count_only:true ","response":"range_response_count:0 size:9"}

Thanks!

[brandond]

As discussed above, slow apply indicates slow or too busy disk. Running 3 nodes on top of a single SSD may be too much for it to keep up with. 143ms isn't terrible, but it's above the threshold expected by etcd.

[rmelilloii]

We have 3 big dedicated master nodes. It just doesn’t make sense that is related with the Host VMs. Or am I missing something? Thanks.

…

On Wed, 3 Jul 2024 at 17:34, Brad Davidson ***@***.***> wrote: As discussed above, slow apply indicates slow or too busy disk. Running 3 nodes on top of a single SSD may be too much for it to keep up with. 143ms isn't terrible, but it's above the threshold expected by etcd. — Reply to this email directly, view it on GitHub <#9207 (reply in thread)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AG3HX5C7SGHYPRVGVAFJZULZKQR2HAVCNFSM6AAAAABBWZ4RBSVHI2DSMVQWIX3LMV43SRDJONRXK43TNFXW4Q3PNVWWK3TUHM4TSNJQGUYDQ> . You are receiving this because you commented.Message ID: ***@***.***>

[rmelilloii]

Hello, good morning and happy Tuesday! I will assume that there is nothing to do based on this scenario:
dedicate k3s masters on dedicated VMs + k3s with embedded etcd (if it goes out of sync, it goes...)

I will keep my monitoring and keep an eye for k3s changes that allow more control for the embedded DB options.

Apart from that, I suppose I can go for the "non-embedded" options, so I can have full control.

Thanks.