kubernetes: etcdserver: read-only range request took too long with etcd 3.2.24

@dotbalo, Have you any problems with your cluster? I think not, if not, then which problem you try to solve and what do you here?

If you just see several records of “slow requests” that not a problem. If you see that many times per day, see cluster freeze, slow requests for 1s+ you have REAL PROBLEM.

I mean: You don’t understand what you are doing. You don’t try to read how to measure drive performance. You come here and ask “Are my disk too slow?”. You have a normal SOHO SSD disk, it’s enough for etcd.

Current issue does not have direct relationship with disk io.

That’s a internal etcd problem, and/or K8s key-value design issue, which can cause slow range requests, and can cause because of slow write IO.

I also see that messages sometimes, but that cause nothing and will not.

@ArchiFleKs It says of 354842 total operations, 228127 took less than or equal to .002 seconds, 348658 took less than or equal to .004 seconds,where the 348658 number includes those that took less than .002 seconds as well. There are a very small portion (85 to be exact) of disk backend commits taking over 128ms. I’m not well enough calibrated to say for sure if those number are out of healthy range or not, but they don’t look particularly alarming. The wal: sync duration of 2.067539108s, expected less than 1s line from the original report does, however, look quite alarming and suggests high disk IO latency. How about your etcd_disk_wal_fsync_duration_seconds_bucket metric, @ArchiFleKs? Does that show anything?

3.4.3 same errors.

Beginning to occur hourly now. Seems to be continuously restarting kube-controller-manager and kube-scheduler.

My kubernetes cluster is v1.13.5 and etcd is v3.3.10. Then I have the same error, but my etcd cluster uses an SSD hard drive. The read and write speed is as follows:

[k8s-user@k8s-master01 etcd]$ sudo dd if=/dev/zero of=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 2.14125 s, 1.2 GB/s
[k8s-user@k8s-master01 etcd]$ sudo dd if=/dev/zero of=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 3.47247 s, 755 MB/s
[k8s-user@k8s-master01 etcd]$ sudo dd if=/dev/zero of=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 3.5717 s, 734 MB/s
[k8s-user@k8s-master01 etcd]$ sudo dd if=/dev/zero of=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 3.58915 s, 730 MB/s
[k8s-user@k8s-master01 etcd]$ sudo dd of=/dev/zero if=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 0.503606 s, 5.2 GB/s
[k8s-user@k8s-master01 etcd]$ sudo dd of=/dev/zero if=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 0.614005 s, 4.3 GB/s
[k8s-user@k8s-master01 etcd]$ sudo dd of=/dev/zero if=testspeed bs=5M count=500
500+0 records in
500+0 records out
2621440000 bytes (2.6 GB) copied, 0.522527 s, 5.0 GB/s

error logs:

Apr 29 12:11:10 k8s-master01 etcd: read-only range request "key:\"/registry/daemonsets\" range_end:\"/registry/daemonsett\" count_only:true " with result "range_response_count:0 size:8" took too long (333.471477ms) to execute
Apr 29 12:11:14 k8s-master01 etcd: read-only range request "key:\"/registry/configmaps\" range_end:\"/registry/configmapt\" count_only:true " with result "range_response_count:0 size:8" took too long (221.436047ms) to execute
Apr 29 12:11:17 k8s-master01 etcd: read-only range request "key:\"/registry/configmaps\" range_end:\"/registry/configmapt\" count_only:true " with result "range_response_count:0 size:8" took too long (640.252868ms) to execute
Apr 29 12:11:21 k8s-master01 etcd: read-only range request "key:\"/registry/deployments\" range_end:\"/registry/deploymentt\" count_only:true " with result "range_response_count:0 size:8" took too long (179.700872ms) to execute
Apr 29 12:11:21 k8s-master01 etcd: read-only range request "key:\"/registry/secrets/kube-system/metrics-server-token-sccgm\" " with result "range_response_count:1 size:2761" took too long (184.019088ms) to execute
Apr 29 12:11:21 k8s-master01 etcd: read-only range request "key:\"/registry/services/specs\" range_end:\"/registry/services/spect\" count_only:true " with result "range_response_count:0 size:8" took too long (120.62712ms) to execute
Apr 29 12:11:21 k8s-master01 etcd: read-only range request "key:\"/registry/statefulsets\" range_end:\"/registry/statefulsett\" count_only:true " with result "range_response_count:0 size:8" took too long (158.092446ms) to execute

Is my disk too slow?

3.4.3 same errors…

to quote myself where I already quoted myself:

this really seems to be related to poor disk performance for etcd.
apparently this only works with ssd like performance.

to quote myself: really try to test with higher performance ssds/storage. my problems went away once the storage was fast enough. even when you do not put etcd under heavy load it generates enough traffic on it’s own. so please try to test with faster (meaning: more iops) storage first. I guess most common cloud instances like mentioned here do not deliver the required performance.

so please state your sustained SSD Performance in IOPS.

I would advice to not use some desktop SSDs because these tend to not be able to deliver sustained IOPS for a long time.

HTH

Any solutions for this etcd issue?

Is there a setting that can be changed in order to increase this limit? Currently it’s impossible to create Kubernetes cluster on top of HDD’s, which is really strange.

I doubt this is your issue, but for me this turned out to be related to an increase in memory consumption for the k8s master nodes. When I switched to a VM with 8GB of RAM instead of 4GB, all my problems went away and everything worked perfectly.

Again, probably not your issue, but just in case, I had to share.

/remove-lifecycle-stale

I’m getting this also for reasons I haven’t been able to understand, and my kubernetes api-server is crashing as a result. Could use some help.

So, do we know whether the root cause is the etcd version or slow disks? This thread seems to have contradictory responses.

I think this is caused by the slow disk or high network latency. I also had this warning before. Then I changed the data directory of etcd to a high-performance SSD storage, and there was almost no warning of “took too long”. Here is the monitor diagram for my etcd:

And My cluster version:

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.5", GitCommit:"2166946f41b36dea2c4626f90a77706f426cdea2", GitTreeState:"clean", BuildDate:"2019-03-25T15:26:52Z", GoVersion:"go1.11.5", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.5", GitCommit:"2166946f41b36dea2c4626f90a77706f426cdea2", GitTreeState:"clean", BuildDate:"2019-03-25T15:19:22Z", GoVersion:"go1.11.5", Compiler:"gc", Platform:"linux/amd64"}

etcd version:

$ etcd -version
etcd Version: 3.3.9
Git SHA: fca8add78
Go Version: go1.10.3
Go OS/Arch: linux/amd64

So I think it is caused by slow disk , not VERSION.

@ArchiFleKs looks like there was one fsync that took between 2.048-4.096 seconds an two that took between 0.512-1.024 seconds. This would result in messages like the one you saw (“wal: sync duration of 2.067539108s, expected less than 1s” error"). https://github.com/etcd-io/etcd/blob/e8b940f268a80c14f7082589f60cbfd3de531d12/wal/wal.go#L572 both tallies this metric and logs the message.

If you’re seeing the log message at higher rates than the metric suggests, that might require further investigation, but the log message does appear to correctly telling us that there was excessively high disk latency.