Store heartbeat cannot be consumed, heartbeat storm in big cluster

[nolouch]

Development Task

Once PD has a very large pressure, the store heartbeat latency may be high caused by the heavy lock competition. but currently, the retry mechanism is not very reasonable. it will retry 10 times, but every retry round may increase the pressure. on the other hand. the newstore_heartbeat will produce with 10s intervals, which into a vicious circle.

Repreduce

add a fail point sleep(4s) in pd server when handle the store_heartbeat, run cluster:

tiup playground v7.1.0  --tiflash=0 --pd.binpath=./pd-server

we can see:

and the logs like:

[2023/07/24 17:14:37.755 +08:00] [ERROR] [util.rs:462] ["request failed, retry"] [err_code=KV:Pd:Grpc] [err="Grpc(RpcFailure(RpcStatus { code: 4-DEADLINE_EXCEEDED, message: \"Deadline Exceeded\", details: [] }))"]
[2023/07/24 17:14:38.025 +08:00] [INFO] [util.rs:604] ["connecting to PD endpoint"] [endpoints=http://127.0.0.1:2379]
[2023/07/24 17:14:38.026 +08:00] [INFO] [util.rs:604] ["connecting to PD endpoint"] [endpoints=http://127.0.0.1:2379]
[2023/07/24 17:14:38.027 +08:00] [INFO] [util.rs:769] ["connected to PD member"] [endpoints=http://127.0.0.1:2379]
[2023/07/24 17:14:38.027 +08:00] [INFO] [util.rs:225] ["heartbeat sender and receiver are stale, refreshing ..."]
[2023/07/24 17:14:38.027 +08:00] [INFO] [util.rs:238] ["buckets sender and receiver are stale, refreshing ..."]
[2023/07/24 17:14:38.027 +08:00] [INFO] [util.rs:266] ["update pd client"] [via=] [leader=http://127.0.0.1:2379] [prev_via=] [prev_leader=http://127.0.0.1:2379]
[2023/07/24 17:14:38.027 +08:00] [INFO] [util.rs:400] ["trying to update PD client done"] [spend=2.380167ms]
...

if there are many stores, this increases the pressure in pd side and may cause OOM issue.

Others

the user have a large cluster, there is 200 store, and we found many goroutine locks in the store heartbeat.and details goroutine will like this:

goroutine 7557968 [semacquire, 14 minutes]:
sync.runtime_SemacquireMutex(0x3404c50?, 0x0?, 0xc03afc8e40?)
	/usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0003c0000)
	/usr/local/go/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
	/usr/local/go/src/sync/mutex.go:90
sync.(*RWMutex).Lock(0xc0dc562b00?)
	/usr/local/go/src/sync/rwmutex.go:147 +0x36
github.com/tikv/pd/server/cluster.(*RaftCluster).HandleStoreHeartbeat(0xc0003c0000, 0xc064e16280)
	/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/pd/server/cluster/cluster.go:669 +0x6e
github.com/tikv/pd/server.(*GrpcServer).StoreHeartbeat(0xc001f4a118, {0x340b958?, 0xc0e864ba70?}, 0xc0f29cc7c0)
	/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/pd/server/grpc_service.go:604 +0x26f
github.com/pingcap/kvproto/pkg/pdpb._PD_StoreHeartbeat_Handler.func1({0x340b958, 0xc0e864ba70}, {0x26d2cc0?, 0xc0f29cc7c0})
	/go/pkg/mod/github.com/pingcap/kvproto@v0.0.0-20220510035547-0e2f26c0a46a/pkg/pdpb/pdpb.pb.go:7467 +0x7b
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1({0x340b958?, 0xc0e864ba70?}, {0x26d2cc0?, 0xc0f29cc7c0?})
	/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.0.1-0.20190118093823-f849b5445de4/chain.go:31 +0x89
github.com/grpc-ecosystem/go-grpc-prometheus.(*ServerMetrics).UnaryServerInterceptor.func1({0x340b958, 0xc0e864ba70}, {0x26d2cc0, 0xc0f29cc7c0}, 0x24f7640?, 0xc0a46906e0)
	/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-prometheus@v1.2.0/server_metrics.go:107 +0x87
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1({0x340b958?, 0xc0e864ba70?}, {0x26d2cc0?, 0xc0f29cc7c0?})
	/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.0.1-0.20190118093823-f849b5445de4/chain.go:34 +0x6f
go.etcd.io/etcd/etcdserver/api/v3rpc.newUnaryInterceptor.func1({0x340b958, 0xc0e864ba70}, {0x26d2cc0?, 0xc0f29cc7c0}, 0x0?, 0xc0a46906e0)
	/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20191023171146-3cf2f69b5738/etcdserver/api/v3rpc/interceptor.go:64 +0x1b6
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1({0x340b958?, 0xc0e864ba70?}, {0x26d2cc0?, 0xc0f29cc7c0?})
	/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.0.1-0.20190118093823-f849b5445de4/chain.go:34 +0x6f
go.etcd.io/etcd/etcdserver/api/v3rpc.newLogUnaryInterceptor.func1({0x340b958, 0xc0e864ba70}, {0x26d2cc0, 0xc0f29cc7c0}, 0xc0ebb75da0, 0xc0a46906e0)
	/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20191023171146-3cf2f69b5738/etcdserver/api/v3rpc/interceptor.go:71 +0xc3
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1({0x340b958, 0xc0e864ba70}, {0x26d2cc0, 0xc0f29cc7c0}, 0xc0ebb75da0, 0xc0e8d451b8)
	/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.0.1-0.20190118093823-f849b5445de4/chain.go:39 +0x1a3
github.com/pingcap/kvproto/pkg/pdpb._PD_StoreHeartbeat_Handler({0x274f6c0?, 0xc001f4a118}, {0x340b958, 0xc0e864ba70}, 0xc0a135c540, 0xc0006fc6f0)
	/go/pkg/mod/github.com/pingcap/kvproto@v0.0.0-20220510035547-0e2f26c0a46a/pkg/pdpb/pdpb.pb.go:7469 +0x138
google.golang.org/grpc.(*Server).processUnaryRPC(0xc001581080, {0x3418060, 0xc098e90780}, 0xc065221e00, 0xc0022fd470, 0x43cc048, 0x0)
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1024 +0xd2f
google.golang.org/grpc.(*Server).handleStream(0xc001581080, {0x3418060, 0xc098e90780}, 0xc065221e00, 0x0)
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1313 +0xa16
google.golang.org/grpc.(*Server).serveStreams.func1.1()
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:722 +0x98
created by google.golang.org/grpc.(*Server).serveStreams.func1
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:720 +0xea