Random performance issue on etcd 3.4

[Sh4d1]

Hello,

We are running a 5 node etcd cluster:

$ etcdctl endpoint status 
etcd01, 507905ef22a349ce, 3.4.7, 3.1 GB, true, false, 785, 17694912855, 17694912855, 
etcd02, 96622104eaa8652d, 3.4.7, 3.1 GB, false, false, 785, 17694912881, 17694912880, 
ectd03, e91fce12ee84c080, 3.4.7, 3.1 GB, false, false, 785, 17694912903, 17694912903, 
etcd04, 400fc14411f50272, 3.4.7, 3.1 GB, false, false, 785, 17694912989, 17694912985, 
etcd05, 87c46f0b178dc777, 3.4.7, 3.1 GB, false, false, 785, 17694913043, 17694913028, 

And we're having some weird performance issue eg:

# etcdctl endpoint health
etcd01 is healthy: successfully committed proposal: took = 12.462058ms
etcd03 is healthy: successfully committed proposal: took = 18.826686ms
etcd02 is healthy: successfully committed proposal: took = 19.418745ms
etcd04 is healthy: successfully committed proposal: took = 24.314474ms
etcd05 is healthy: successfully committed proposal: took = 244.761598ms

# etcdctl endpoint health
etcd01 is healthy: successfully committed proposal: took = 13.505405ms
etcd03 is healthy: successfully committed proposal: took = 21.905048ms
etcd04 is healthy: successfully committed proposal: took = 22.569332ms
etcd02 is healthy: successfully committed proposal: took = 23.10597ms
etcd05 is healthy: successfully committed proposal: took = 24.182998ms

# etcdctl endpoint health
etcd05is healthy: successfully committed proposal: took = 24.854541ms
etcd01 is healthy: successfully committed proposal: took = 86.045049ms
etcd03 is healthy: successfully committed proposal: took = 171.771975ms
etcd04 is healthy: successfully committed proposal: took = 576.218846ms
etcd02 is healthy: successfully committed proposal: took = 1.06666032s

Not sure how to debug it, it looks pretty random. Feel free to ask for more info!

[xiang90]

I looks like disk I/O spikes.

[Sh4d1]

This is also what I'm thinking, I also have periodically slow read only range request. Though I can't see any problems when looking at my metrics 🤔 @xiang90 any ideas on where to look?

[Sh4d1]

Commit durations looks fine

etcd_disk_backend_commit_duration_seconds_bucket{le="0.001"} 168386
etcd_disk_backend_commit_duration_seconds_bucket{le="0.002"} 576993
etcd_disk_backend_commit_duration_seconds_bucket{le="0.004"} 757708
etcd_disk_backend_commit_duration_seconds_bucket{le="0.008"} 782904
etcd_disk_backend_commit_duration_seconds_bucket{le="0.016"} 787763
etcd_disk_backend_commit_duration_seconds_bucket{le="0.032"} 788436
etcd_disk_backend_commit_duration_seconds_bucket{le="0.064"} 788584
etcd_disk_backend_commit_duration_seconds_bucket{le="0.128"} 788953
etcd_disk_backend_commit_duration_seconds_bucket{le="0.256"} 789118
etcd_disk_backend_commit_duration_seconds_bucket{le="0.512"} 789148
etcd_disk_backend_commit_duration_seconds_bucket{le="1.024"} 789148
etcd_disk_backend_commit_duration_seconds_bucket{le="2.048"} 789148
etcd_disk_backend_commit_duration_seconds_bucket{le="4.096"} 789148
etcd_disk_backend_commit_duration_seconds_bucket{le="8.192"} 789148
etcd_disk_backend_commit_duration_seconds_bucket{le="+Inf"} 789148
etcd_disk_backend_commit_duration_seconds_sum 1461.2600709299697
etcd_disk_backend_commit_duration_seconds_count 789148

fsync looks fine as well

etcd_disk_wal_fsync_duration_seconds_bucket{le="0.001"} 9.397643e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.002"} 9.4252083e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.004"} 9.4467886e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.008"} 9.4633426e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.016"} 9.4712732e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.032"} 9.4718483e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.064"} 9.4718972e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.128"} 9.4719722e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.256"} 9.4719978e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="0.512"} 9.4719985e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="1.024"} 9.4719986e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="2.048"} 9.4719986e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="4.096"} 9.4719986e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="8.192"} 9.4719986e+07
etcd_disk_wal_fsync_duration_seconds_bucket{le="+Inf"} 9.4719986e+07
etcd_disk_wal_fsync_duration_seconds_sum 18283.75915433406
etcd_disk_wal_fsync_duration_seconds_count 9.4719986e+07

rtt seems ok too:

etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0001"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0002"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0004"} 2
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0008"} 1813
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0016"} 2275
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0032"} 2307
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0064"} 2311
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0128"} 2312
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0256"} 4610
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.0512"} 4631
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.1024"} 4634
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.2048"} 4635
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.4096"} 4635
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="0.8192"} 4636
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="1.6384"} 4636
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="3.2768"} 4636
etcd_network_peer_round_trip_time_seconds_bucket{To="400fc14411f50272",le="+Inf"} 4636
etcd_network_peer_round_trip_time_seconds_sum{To="400fc14411f50272"} 46.492993348000034
etcd_network_peer_round_trip_time_seconds_count{To="400fc14411f50272"} 4636
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0001"} 0
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0002"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0004"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0008"} 1742
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0016"} 2228
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0032"} 2276
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0064"} 2284
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0128"} 2291
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0256"} 4495
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.0512"} 4554
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.1024"} 4581
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.2048"} 4594
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.4096"} 4594
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="0.8192"} 4594
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="1.6384"} 4594
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="3.2768"} 4594
etcd_network_peer_round_trip_time_seconds_bucket{To="87c46f0b178dc777",le="+Inf"} 4594
etcd_network_peer_round_trip_time_seconds_sum{To="87c46f0b178dc777"} 49.258597341999945
etcd_network_peer_round_trip_time_seconds_count{To="87c46f0b178dc777"} 4594
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0001"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0002"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0004"} 175
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0008"} 1974
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0016"} 2246
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0032"} 2277
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0064"} 2285
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0128"} 2288
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0256"} 4533
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.0512"} 4568
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.1024"} 4582
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.2048"} 4586
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.4096"} 4587
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="0.8192"} 4588
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="1.6384"} 4588
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="3.2768"} 4588
etcd_network_peer_round_trip_time_seconds_bucket{To="96622104eaa8652d",le="+Inf"} 4588
etcd_network_peer_round_trip_time_seconds_sum{To="96622104eaa8652d"} 44.96468762199984
etcd_network_peer_round_trip_time_seconds_count{To="96622104eaa8652d"} 4588
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0001"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0002"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0004"} 1
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0008"} 1719
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0016"} 2238
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0032"} 2271
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0064"} 2278
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0128"} 2280
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0256"} 4529
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.0512"} 4558
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.1024"} 4567
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.2048"} 4573
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.4096"} 4575
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="0.8192"} 4575
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="1.6384"} 4575
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="3.2768"} 4575
etcd_network_peer_round_trip_time_seconds_bucket{To="e91fce12ee84c080",le="+Inf"} 4575
etcd_network_peer_round_trip_time_seconds_sum{To="e91fce12ee84c080"} 46.92858499100008
etcd_network_peer_round_trip_time_seconds_count{To="e91fce12ee84c080"} 4575

[Sh4d1]

we are also seeing some /health error; QGET failed etcdserver: request timed out (status code 503)

[xiang90]

Was there any leader election happening? Any warning/errors in the log?

[Sh4d1]

No election leader, and I see the spikes in latency every 5-10s on 1 node for 1-2s maybe. No errors, but I think the read only range requests are at around the same time

[xiang90]

but I think the read only range requests are at around the same time

If there is an expensive range request, it will affect latency. But etcd should log something out when that happens.

[Sh4d1]

It only logs that the request took longer than 100ms. And I think the request are not that big 🤔 I'll paste some examples tomorrow!

[xiang90]

It only logs that the request took longer than 100ms. And I think the request are not that big 🤔 I'll paste some examples tomorrow!

Probably that was what going on.

[Sh4d1]

@xiang90 I'm also seeing some high p99 grpc latency (above 2s) on for instance Range, LeaseGrant and Txn. I'm not sure which is causing which 🤔

[tangcong]

can you enable trace feature? ( set --logger=zap). you can specify --metrics=extensive to get all grpcMethod latency. can you provide all etcd metrics info and trace log? @Sh4d1

[Sh4d1]

@tangcong here are the metrics for one of the node https://gist.github.com/Sh4d1/bbfba21f3176865cf69c4533d5e39286
Do you want for the 4 other nodes too?

Can't set the logger right now, I'll do it when I can

[tangcong]

It seems that the number of connections is very large, how about the etcd server load?

process_open_fds 76494
go_goroutines 224164
etcd_server_health_failures 1900
etcd_server_heartbeat_send_failures_total 904

[Sh4d1]

Yes there is around ~ 1000 k8s api servers connected to the cluster.
The cpu load is okay 4.49, 5.18, 5.81 and cpu usage of etcd is between 200 and 600% (on 12 cores)

[tangcong]

do you also use etcd v2? What is the current cluster read and write QPS for etcd v2,v3? in the k8s, listing pods and events are expensive, in my opinion, supporting 1000 k8s cluster by one etcd cluster is very risky.

etcd_debugging_store_reads_total{action="get"} 505432
etcd_debugging_store_reads_total{action="getRecursive"} 4