high i/o cause "etcdserver: requested lease not found" #17305

yitian108 · 2024-01-23T07:18:31Z

yitian108
Jan 23, 2024

Here is the steps that to simulate high I/O operations:

Generate a 1GB file.

dd if=/dev/urandom of=testfile bs=1M count=1000

Copy the file multiple times.

for i in {1..10}; do cp testfile testfile_$i; done

Perform I/O intensive operations.
```
cat testfile_*
```
Run the shell script.

for i in {1..100000}
do
etcdctl  --endpoints=xxx.xxx.xx.xxx:12535 put "t$i" "This value from the key: $i"
sleep 0.01
done

Then the service that depends on the etcd server xxx.xxx.xx.xxx:12535 will report "etcdserver: requested lease not found".
The following log snippet from etcd server like this:
{"level":"warn","ts":"2024-01-23T11:40:45.194+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} {"level":"warn","ts":"2024-01-23T11:40:45.695+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} {"level":"warn","ts":"2024-01-23T11:40:46.196+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} {"level":"warn","ts":"2024-01-23T11:40:46.696+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} {"level":"warn","ts":"2024-01-23T11:40:47.197+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} {"level":"warn","ts":"2024-01-23T11:40:47.697+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} {"level":"warn","ts":"2024-01-23T11:40:48.194+0800","caller":"wal/wal.go:802","msg":"slow fdatasync","took":"3.584506237s","expected-duration":"1s"} {"level":"warn","ts":"2024-01-23T11:40:48.198+0800","caller":"etcdserver/v3_server.go:815","msg":"waiting for ReadIndex response took too long, retrying","sent-request-id":4822947328307020133,"retry-timeout":"500ms"} ... {"level":"warn","ts":"2024-01-23T11:42:20.521+0800","caller":"etcdserver/server.go:1130","msg":"failed to revoke lease","lease-id":"42ee8d0ac21d438a","error":"etcdserver: request timed out"} {"level":"warn","ts":"2024-01-23T11:42:20.521+0800","caller":"etcdserver/server.go:1130","msg":"failed to revoke lease","lease-id":"42ee8d0ac21d6178","error":"etcdserver: request timed out"} {"level":"warn","ts":"2024-01-23T11:42:20.521+0800","caller":"etcdserver/server.go:1130","msg":"failed to revoke lease","lease-id":"42ee8d0ac21d5b9e","error":"etcdserver: request timed out"} ... {"level":"warn","ts":"2024-01-23T11:45:18.150+0800","caller":"etcdserver/util.go:166","msg":"apply request took too long","took":"630.894281ms","expected-duration":"100ms","prefix":"","request":"header:<ID:4822947328307021375 > lease_grant:<ttl:15-second id:42ee8d0ac228c63e>","response":"size:41"} {"level":"info","ts":"2024-01-23T11:45:18.150+0800","caller":"etcdserver/server.go:2363","msg":"saved snapshot","snapshot-index":622784} {"level":"info","ts":"2024-01-23T11:45:18.151+0800","caller":"etcdserver/server.go:2393","msg":"compacted Raft logs","compact-index":617784} {"level":"info","ts":"2024-01-23T11:45:18.151+0800","caller":"etcdserver/server.go:2363","msg":"saved snapshot","snapshot-index":622565} {"level":"warn","ts":"2024-01-23T11:45:18.151+0800","caller":"etcdserver/util.go:123","msg":"failed to apply request","took":"9.719µs","request":"header:<ID:4822947328307021427 > lease_revoke:<id:42ee8d0ac21d602d>","response":"size:29","error":"lease not found"}

So, I want to know how to avoid the error as title shows even if in the high I/O environment.

Below I picked some grafana monitor graphs that the high I/O cases.

jmhbnz · 2024-01-24T05:39:00Z

jmhbnz
Jan 24, 2024
Maintainer

Hey @yitian108 - Thanks for your question. Your metrics graph for disk shows WAL fsync reaching 500ms and DB fsync reaching over 1.5 seconds,

Because etcd writes data to disk and persists proposals on disk, its performance depends on disk performance. Although etcd is not particularly I/O intensive, it requires a low latency block device for optimal performance and stability. Because etcd’s consensus protocol depends on persistently storing metadata to a log (WAL), etcd is sensitive to disk-write latency. Slow disks and disk activity from other processes can cause long fsync latencies.

Those latencies can cause etcd to miss heartbeats, not commit new proposals to the disk on time, and ultimately experience request timeouts and temporary leader loss. High write latencies also lead to an flow on impacts like Kubernetes API slowness, which affects cluster performance.

I would suggest running etcd on better hardware to ensure you can keep your fsync latencies under 10ms ideally. To measure those numbers, you can use a benchmarking tool, such as fio.

3 replies

yitian108 Jan 24, 2024
Author

Hi @jmhbnz - Thank you for your reply. The slow speed of the disk did indeed affected the performance of etcd or the whole cluster. However, there may be limitations in changing the hardware to address the issue..

Or, can we set some parameters such as heartbeat-interval or election-timeout etc to reduce the frequence of the issue?

Or, can we set priority of etcd process via ionice command?

I have also attached results showing the disk performance generated by the fio command.

fio -output=/tmp/100S100W -name=100S100W -filename=/dev/sda -ioengine=sync -direct=1 -blocksize=2M -size=10GB -rw=write -iodepth=8 -numjobs=1

100S100W: (g=0): rw=write, bs=2M-2M/2M-2M/2M-2M, ioengine=sync, iodepth=8
fio-2.1.10
Starting 1 process

100S100W: (groupid=0, jobs=1): err= 0: pid=28035: Wed Jan 24 15:48:36 2024
  write: io=10240MB, bw=92854KB/s, iops=45, runt=112927msec
    clat (msec): min=3, max=180, avg=21.90, stdev= 8.95
     lat (msec): min=3, max=180, avg=22.05, stdev= 8.95
    clat percentiles (msec):
     |  1.00th=[    9],  5.00th=[   11], 10.00th=[   12], 20.00th=[   16],
     | 30.00th=[   18], 40.00th=[   20], 50.00th=[   22], 60.00th=[   24],
     | 70.00th=[   24], 80.00th=[   27], 90.00th=[   32], 95.00th=[   38],
     | 99.00th=[   48], 99.50th=[   55], 99.90th=[   89], 99.95th=[  118],
     | 99.99th=[  180]
    bw (KB  /s): min=55890, max=121663, per=100.00%, avg=93029.65, stdev=10644.77
    lat (msec) : 4=0.02%, 10=3.30%, 20=39.69%, 50=56.29%, 100=0.61%
    lat (msec) : 250=0.10%
  cpu          : usr=0.72%, sys=0.67%, ctx=5155, majf=0, minf=31
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=5120/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):
  WRITE: io=10240MB, aggrb=92854KB/s, minb=92854KB/s, maxb=92854KB/s, mint=112927msec, maxt=112927msec

Disk stats (read/write):
  sda: ios=1280/43312, merge=0/4675, ticks=36251/607920, in_queue=644035, util=99.13%

fio -output=/tmp/100R100W -name=100R100W -filename=/dev/sda -ioengine=sync -direct=1 -blocksize=2M -size=10GB -rw=randwrite -iodepth=8 -numjobs=1

100R100W: (g=0): rw=randwrite, bs=2M-2M/2M-2M/2M-2M, ioengine=sync, iodepth=8
fio-2.1.10
Starting 1 process

100R100W: (groupid=0, jobs=1): err= 0: pid=7346: Wed Jan 24 15:44:05 2024
  write: io=10240MB, bw=89027KB/s, iops=43, runt=117782msec
    clat (msec): min=5, max=242, avg=22.85, stdev=10.66
     lat (msec): min=5, max=242, avg=22.99, stdev=10.66
    clat percentiles (msec):
     |  1.00th=[    8],  5.00th=[   11], 10.00th=[   13], 20.00th=[   16],
     | 30.00th=[   18], 40.00th=[   20], 50.00th=[   22], 60.00th=[   24],
     | 70.00th=[   26], 80.00th=[   29], 90.00th=[   36], 95.00th=[   40],
     | 99.00th=[   52], 99.50th=[   65], 99.90th=[  125], 99.95th=[  147],
     | 99.99th=[  243]
    bw (KB  /s): min=52203, max=109065, per=100.00%, avg=89174.93, stdev=8076.44
    lat (msec) : 10=4.86%, 20=37.30%, 50=56.56%, 100=1.09%, 250=0.18%
  cpu          : usr=0.68%, sys=0.66%, ctx=5162, majf=0, minf=29
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=5120/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):
  WRITE: io=10240MB, aggrb=89026KB/s, minb=89026KB/s, maxb=89026KB/s, mint=117782msec, maxt=117782msec

Disk stats (read/write):
  sda: ios=6293/43996, merge=11/6128, ticks=125416/695750, in_queue=828705, util=99.37%

fio --filename=/tmp/test_read -direct=1 -rw=read -bs=1m -size=1G -numjobs=4 -runtime=10 -group_reporting -name=mytest

mytest: (g=0): rw=read, bs=1M-1M/1M-1M/1M-1M, ioengine=sync, iodepth=1
...
fio-2.1.10
Starting 4 processes
mytest: Laying out IO file(s) (1 file(s) / 1024MB)
Jobs: 4 (f=4): [RRRR] [81.8% done] [986.2MB/0KB/0KB /s] [986/0/0 iops] [eta 00m:02s]
mytest: (groupid=0, jobs=4): err= 0: pid=16096: Wed Jan 24 16:23:04 2024
  read : io=4096.0MB, bw=508154KB/s, iops=496, runt=  8254msec
    clat (usec): min=429, max=88500, avg=8050.60, stdev=10041.53
     lat (usec): min=430, max=88500, avg=8050.86, stdev=10041.57
    clat percentiles (usec):
     |  1.00th=[  532],  5.00th=[ 1176], 10.00th=[ 1368], 20.00th=[ 1384],
     | 30.00th=[ 1384], 40.00th=[ 1416], 50.00th=[ 2512], 60.00th=[ 6560],
     | 70.00th=[ 9920], 80.00th=[14144], 90.00th=[21888], 95.00th=[27264],
     | 99.00th=[42752], 99.50th=[58112], 99.90th=[83456], 99.95th=[85504],
     | 99.99th=[88576]
    bw (KB  /s): min=52203, max=674491, per=23.44%, avg=119113.05, stdev=139147.67
    lat (usec) : 500=0.78%, 750=0.61%, 1000=0.27%
    lat (msec) : 2=44.75%, 4=6.69%, 10=17.02%, 20=18.33%, 50=10.74%
    lat (msec) : 100=0.81%
  cpu          : usr=0.11%, sys=1.37%, ctx=4147, majf=0, minf=1140
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=4096/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: io=4096.0MB, aggrb=508154KB/s, minb=508154KB/s, maxb=508154KB/s, mint=8254msec, maxt=8254msec

Disk stats (read/write):
    dm-0: ios=20818/644, merge=0/0, ticks=141923/12252, in_queue=154128, util=100.00%, aggrios=21530/266, aggrmerge=17/430, aggrticks=142572/5430, aggrin_queue=147987, aggrutil=100.00%
  sda: ios=21530/266, merge=17/430, ticks=142572/5430, in_queue=147987, util=100.00%

fio -filename=/dev/sda -direct=1 -iodepth 1 -thread -rw=randrw -rwmixread=70 -ioengine=psync -bs=1m -size=1G -numjobs=10 -runtime=60 -group_reporting -name=mytest -ioscheduler=noop

mytest: (g=0): rw=randrw, bs=16K-16K/16K-16K/16K-16K, ioengine=psync, iodepth=1
...
fio-2.1.10
Starting 10 threads
Jobs: 10 (f=10): [mmmmmmmmmm] [0.0% done] [67KB/0KB/0KB /s] [4/0/0 iops] [eta 01d:19h:23m:36s]
mytest: (groupid=0, jobs=10): err= 0: pid=7875: Wed Jan 24 16:35:39 2024
  read : io=3472.0KB, bw=56818B/s, iops=3, runt= 62573msec
    clat (msec): min=1841, max=3358, avg=2284.40, stdev=224.21
     lat (msec): min=1841, max=3358, avg=2284.40, stdev=224.21
    clat percentiles (msec):
     |  1.00th=[ 1909],  5.00th=[ 1975], 10.00th=[ 2057], 20.00th=[ 2114],
     | 30.00th=[ 2212], 40.00th=[ 2212], 50.00th=[ 2245], 60.00th=[ 2278],
     | 70.00th=[ 2311], 80.00th=[ 2409], 90.00th=[ 2540], 95.00th=[ 2737],
     | 99.00th=[ 3294], 99.50th=[ 3359], 99.90th=[ 3359], 99.95th=[ 3359],
     | 99.99th=[ 3359]
    bw (KB  /s): min=    4, max=    8, per=11.95%, avg= 6.57, stdev= 0.74
  write: io=819200B, bw=13091B/s, iops=0, runt= 62573msec
    clat (msec): min=2111, max=3444, avg=2353.32, stdev=225.87
     lat (msec): min=2111, max=3444, avg=2353.33, stdev=225.87
    clat percentiles (msec):
     |  1.00th=[ 2114],  5.00th=[ 2114], 10.00th=[ 2147], 20.00th=[ 2180],
     | 30.00th=[ 2212], 40.00th=[ 2278], 50.00th=[ 2311], 60.00th=[ 2343],
     | 70.00th=[ 2376], 80.00th=[ 2507], 90.00th=[ 2540], 95.00th=[ 2638],
     | 99.00th=[ 3458], 99.50th=[ 3458], 99.90th=[ 3458], 99.95th=[ 3458],
     | 99.99th=[ 3458]
    bw (KB  /s): min=    4, max=    7, per=52.83%, avg= 6.34, stdev= 0.63
    lat (msec) : 2000=4.49%, >=2000=95.51%
  cpu          : usr=0.00%, sys=0.00%, ctx=302, majf=1, minf=25
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=217/w=50/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: io=3472KB, aggrb=55KB/s, minb=55KB/s, maxb=55KB/s, mint=62573msec, maxt=62573msec
  WRITE: io=800KB, aggrb=12KB/s, minb=12KB/s, maxb=12KB/s, mint=62573msec, maxt=62573msec

Disk stats (read/write):
  sda: ios=216641/281, merge=7216/447, ticks=511790583/732680, in_queue=513330960, util=100.00%

Note: the 3rd and 4th testing, only set size=1G since 10G would take too long.

jmhbnz Jan 25, 2024
Maintainer

Thanks for the update @yitian108 - based on the fio results it looks as though you are running etcd on sata mechanical spinning disks or older slow ssd storage. Ultimately the issues your encountering come down to disk performance and the solution will be to run etcd on better hardware, refer: https://etcd.io/docs/v3.5/op-guide/hardware/#disks

You can potentially try setting io priorities for etcd though this may not resolve the issue https://etcd.io/docs/v3.5/tuning/#disk.

Tuning the time parameters will help prevent unnecessary leader elections in the cluster but does just mask the underlying performance issue and may not help with the readindex issue you reported https://etcd.io/docs/v3.5/tuning/#time-parameters

yitian108 Jan 25, 2024
Author

Thank you @jmhbnz , your suggestion for a constructive and well-founded approach to the issue is appreciated. However, since we are currently unable to change the disk, some colleagues have proposed an alternative solution. Their proposal suggests storing key-value data directly in memory, similar to the etcd v2 edition. This way, the impact of disk I/O on the etcd server would be minimized. However, There are concerns that this approach may revert to the etcd (v2) version.

What are your thoughts on using memory as a storage medium? It might lead to lower availability for the etcd cluster.

HuangQAQ · 2024-03-25T10:21:31Z

HuangQAQ
Mar 25, 2024

@yitian108 Has this issue been resolved? I have the same issue

1 reply

yitian108 Mar 26, 2024
Author

No, not yet.

@jmhbnz , setting aside disk performance issues, can the problem be solely resolved through improvements in the etcd software?

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

high i/o cause "etcdserver: requested lease not found" #17305

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments 4 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

high i/o cause "etcdserver: requested lease not found" #17305

yitian108 Jan 23, 2024

Replies: 2 comments · 4 replies

jmhbnz Jan 24, 2024 Maintainer

yitian108 Jan 24, 2024 Author

jmhbnz Jan 25, 2024 Maintainer

yitian108 Jan 25, 2024 Author

HuangQAQ Mar 25, 2024

yitian108 Mar 26, 2024 Author

yitian108
Jan 23, 2024

Replies: 2 comments 4 replies

jmhbnz
Jan 24, 2024
Maintainer

yitian108 Jan 24, 2024
Author

jmhbnz Jan 25, 2024
Maintainer

yitian108 Jan 25, 2024
Author

HuangQAQ
Mar 25, 2024

yitian108 Mar 26, 2024
Author