Shorten PD cluster recovery duration after leader is killed
- Dominant language
- Go
- Stars
- 1.2k
- Forks
- 783
- Avg merge
- 5d 21h
- Merged PRs (30d)
- 36
Description
## Feature Request
### Describe your feature request related problem
PD cluster takes 7 seconds to recovery after leader is killed, which affect stability of some TSO dependent services (e.g. RawKV API V2) a lot.

Compared with raft in PD, it takes less than 500ms to elect a new leader (see the fragment of `pd.log` following):
```
[2022/06/07 17:25:24.586 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:25.586 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rp
c error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:25.587 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:923] ["332b61ab9add1284 is starting a new election at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:729] ["332b61ab9add1284 became pre-candidate at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgPreVoteResp from 332b61ab9add1284 at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgPreVote request to 2542b30eb3b11037 at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgPreVote request to 77a5bf7c8623332e at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [node.go:331] ["raft.node: 332b61ab9add1284 lost leader 2542b30eb3b11037 at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgPreVoteResp from 77a5bf7c8623332e at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:1302] ["332b61ab9add1284 has received 2 MsgPreVoteResp votes and 0 vote rejections"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:713] ["332b61ab9add1284 became candidate at term 26"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgVoteResp from 332b61ab9add1284 at term 26"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgVote request to 2542b30eb3b11037 at term 26"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgVote request to 77a5bf7c8623332e at term 26"]
[2022/06/07 17:25:25.924 +08:00] [WARN] [stream.go:224] ["lost TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [local-member-id=332b61ab9add1284] [remote-peer-id=2542b30eb3b11037]
[2022/06/07 17:25:25.925 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgVoteResp from 77a5bf7c8623332e at term 26"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [raft.go:1302] ["332b61ab9add1284 has received 2 MsgVoteResp votes and 0 vote rejections"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [raft.go:765] ["332b61ab9add1284 became leader at term 26"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [node.go:325] ["raft.node: 332b61ab9add1284 elected leader 332b61ab9add1284 at term 26"]
```
#### Cluster Setup
Version: v6.1.0-alpha
```
pd-server --version
Release Version: v6.1.0
Edition: Community
Git Commit Hash: 1c3aa15fde044b86c1a7432248d292d8ee4c6bb3
Git Branch: heads/refs/tags/v6.1.0
UTC Build Time: 2022-06-01 07:58:10
```
Cluster deployed by TiUP, 4 x 32C64G + cloud SSD, 3 x pd-server (deployed together with tikv-server), 4 x tikv-server
Configs:
```
server_configs:
tikv:
log.level: "info"
log.file.max-size: 1024
log.file.max-backups: 30
storage.api-version: 2
storage.enable-ttl: true
pd:
election-interval: 1s
lease: 1
tick-interval: 200ms
```
#### Testcase
kill -9 pd-server (old PD leader, on 10.2.103.183, at 2022/06/07 16:30:33)
#### pd.log on 10.2.103.96, the new leader
```
[2022/06/07 17:25:24.586 +08:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=332b61ab9add1284] [remote-peer-id=2542b30eb3b11037] [error="unexpected EOF"]
[2022/06/07 17:25:24.586 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:25.586 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rp
c error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:25.587 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:923] ["332b61ab9add1284 is starting a new election at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:729] ["332b61ab9add1284 became pre-candidate at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgPreVoteResp from 332b61ab9add1284 at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgPreVote request to 2542b30eb3b11037 at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgPreVote request to 77a5bf7c8623332e at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [node.go:331] ["raft.node: 332b61ab9add1284 lost leader 2542b30eb3b11037 at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgPreVoteResp from 77a5bf7c8623332e at term 25"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:1302] ["332b61ab9add1284 has received 2 MsgPreVoteResp votes and 0 vote rejections"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:713] ["332b61ab9add1284 became candidate at term 26"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgVoteResp from 332b61ab9add1284 at term 26"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgVote request to 2542b30eb3b11037 at term 26"]
[2022/06/07 17:25:25.921 +08:00] [INFO] [raft.go:811] ["332b61ab9add1284 [logterm: 25, index: 304748] sent MsgVote request to 77a5bf7c8623332e at term 26"]
[2022/06/07 17:25:25.924 +08:00] [WARN] [stream.go:224] ["lost TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [local-member-id=332b61ab9add1284] [remote-peer-id=2542b30eb3b11037]
[2022/06/07 17:25:25.925 +08:00] [INFO] [raft.go:824] ["332b61ab9add1284 received MsgVoteResp from 77a5bf7c8623332e at term 26"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [raft.go:1302] ["332b61ab9add1284 has received 2 MsgVoteResp votes and 0 vote rejections"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [raft.go:765] ["332b61ab9add1284 became leader at term 26"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [node.go:325] ["raft.node: 332b61ab9add1284 elected leader 332b61ab9add1284 at term 26"]
[2022/06/07 17:25:25.925 +08:00] [WARN] [util.go:144] ["apply request took too long"] [took=679.122256ms] [expected-duration=100ms] [prefix="read-only range "] [request="key:\"/pd/7104227152570178304/config\" "] [response=] [error="etcdserver: leader changed"]
[2022/06/07 17:25:25.925 +08:00] [INFO] [trace.go:145] ["trace[1513228056] range"] [detail="{range_begin:/pd/7104227152570178304/config; range_end:; }"] [duration=679.202463ms] [start=2022/06/07 17:25:25.246 +08:00] [end=2022/06/07 17:25:25.925 +08:00] [steps="[\"trace[1513228056] 'agreement among raft nodes before linearized reading' (duration: 679.121716ms)\"]"]
[2022/06/07 17:25:25.926 +08:00] [WARN] [cluster_util.go:315] ["failed to reach the peer URL"] [address=http://10.2.103.183:2380/version] [remote-member-id=2542b30eb3b11037] [error="Get \"http://10.2.103.183:2380/version\": dial tcp 10.2.103.183:2380: connect: connection refused"]
[2022/06/07 17:25:25.926 +08:00] [WARN] [cluster_util.go:168] ["failed to get version"] [remote-member-id=2542b30eb3b11037] [error="Get \"http://10.2.103.183:2380/version\": dial tcp 10.2.103.183:2380: connect: connection refused"]
[2022/06/07 17:25:26.586 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:27.011 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:27.587 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:27.911 +08:00] [ERROR] [middleware.go:150] ["request failed"] [error="[PD:http:ErrSendRequest]Get \"http://10.2.103.183:2379/pd/api/v1/stores\": dial tcp 10.2.103.183:2379: connect: connection refused: Get \"http://10.2.103.183:2379/pd/api/v1/stores\": dial tcp 10.2.103.183:2379: connect: connection refused"]
[2022/06/07 17:25:28.127 +08:00] [WARN] [stream.go:193] ["lost TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [local-member-id=332b61ab9add1284] [remote-peer-id=2542b30eb3b11037]
[2022/06/07 17:25:28.588 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:29.296 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:29.588 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:29.914 +08:00] [ERROR] [middleware.go:150] ["request failed"] [error="[PD:http:ErrSendRequest]Get \"http://10.2.103.183:2379/pd/api/v1/stores\": dial tcp 10.2.103.183:2379: connect: connection refused: Get \"http://10.2.103.183:2379/pd/api/v1/stores\": dial tcp 10.2.103.183:2379: connect: connection refused"]
[2022/06/07 17:25:29.928 +08:00] [WARN] [cluster_util.go:315] ["failed to reach the peer URL"] [address=http://10.2.103.183:2380/version] [remote-member-id=2542b30eb3b11037] [error="Get \"http://10.2.103.183:2380/version\": dial tcp 10.2.103.183:2380: connect: connection refused"]
[2022/06/07 17:25:29.928 +08:00] [WARN] [cluster_util.go:168] ["failed to get version"] [remote-member-id=2542b30eb3b11037] [error="Get \"http://10.2.103.183:2380/version\": dial tcp 10.2.103.183:2380: connect: connection refused"]
[2022/06/07 17:25:30.589 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:31.590 +08:00] [ERROR] [client.go:162] ["server failed to establish sync stream with leader"] [server=pd-10.2.103.96-2379] [leader=pd-10.2.103.183-2379] [error="[PD:grpc:ErrGRPCCreateStream]rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\""]
[2022/06/07 17:25:31.916 +08:00] [ERROR] [middleware.go:150] ["request failed"] [error="[PD:http:ErrSendRequest]Get \"http://10.2.103.183:2379/pd/api/v1/stores\": dial tcp 10.2.103.183:2379: connect: connection refused: Get \"http://10.2.103.183:2379/pd/api/v1/stores\": dial tcp 10.2.103.183:2379: connect: connection refused"]
[2022/06/07 17:25:32.045 +08:00] [INFO] [leadership.go:211] ["current leadership is deleted"] [leader-key=/pd/7104227152570178304/leader] [purpose="pd leader election"]
[2022/06/07 17:25:32.305 +08:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {10.2.103.183:2379 0 }. Err :connection error: desc = \"transport: Error while dialing dial tcp 10.2.103.183:2379: connect: connection refused\". Reconnecting..."]
[2022/06/07 17:25:32.591 +08:00] [INFO] [server.go:1308] ["pd leader has changed, try to re-campaign a pd leader"]
[2022/06/07 17:25:32.591 +08:00] [INFO] [server.go:1326] ["start to campaign pd leader"] [campaign-pd-leader-name=pd-10.2.103.96-2379]
[2022/06/07 17:25:32.593 +08:00] [INFO] [lease.go:65] ["lease granted"] [lease-id=1334333490478998537] [lease-timeout=1] [purpose="pd leader election"]
[2022/06/07 17:25:32.596 +08:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":7352027829541167754,\"member_id\":3687148109598364292,\"revision\":304342,\"raft_term\":26},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":304342}}}}]}"]
[2022/06/07 17:25:32.597 +08:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7104227152570178304/leader] [purpose="pd leader election"]
[2022/06/07 17:25:32.597 +08:00] [INFO] [server.go:1352] ["campaign pd leader ok"] [campaign-pd-leader-name=pd-10.2.103.96-2379]
[2022/06/07 17:25:32.597 +08:00] [INFO] [server.go:1359] ["initializing the global TSO allocator"]
[2022/06/07 17:25:32.597 +08:00] [INFO] [lease.go:135] ["start lease keep alive worker"] [interval=333.333333ms] [purpose="pd leader election"]
[2022/06/07 17:25:32.599 +08:00] [INFO] [tso.go:221] ["sync and save timestamp"] [last=2022/06/07 17:25:24.584 +08:00] [save=2022/06/07 17:25:35.598 +08:00] [next=2022/06/07 17:25:32.598 +08:00]
[2022/06/07 17:25:32.601 +08:00] [INFO] [server.go:1470] ["server enable region storage"]
[2022/06/07 17:25:32.610 +08:00] [INFO] [cluster.go:352] ["load stores"] [count=4] [cost=7.498824ms]
[2022/06/07 17:25:32.610 +08:00] [INFO] [cluster.go:363] ["load regions"] [count=1684] [cost=1.617µs]
[2022/06/07 17:25:32.613 +08:00] [INFO] [coordinator.go:318] ["coordinator starts to collect cluster information"]
[2022/06/07 17:25:32.615 +08:00] [INFO] [store_config.go:192] ["sync the store config successful"] [store-address=10.2.103.103:20180] [store-config="{\n \"coprocessor\": {\n \"region-max-size\": \"144MiB\",\n \"region-split-size\": \"96MiB\",\n \"region-max-keys\": 1440000,\n \"region-split-keys\": 960000,\n \"enable-region-bucket\": false,\n
\"region-bucket-size\": \"96MiB\"\n }\n}"]
[2022/06/07 17:25:32.616 +08:00] [INFO] [id.go:122] ["idAllocator allocates a new id"] [alloc-id=143000]
[2022/06/07 17:25:32.616 +08:00] [INFO] [util.go:77] ["load cluster version"] [cluster-version=6.1.0-alpha]
[2022/06/07 17:25:32.616 +08:00] [INFO] [server.go:1410] ["PD cluster leader is ready to serve"] [pd-leader-name=pd-10.2.103.96-2379]
```
#### Clinic metrics & logs
https://clinic.pingcap.com.cn/portal/#/orgs/117/clusters/7104227152570178304
### Describe the feature you'd like
Shorten recovery duration to less than 3 seconds after PD leader is killed.
### Describe alternatives you've considered
### Teachability, Documentation, Adoption, Migration Strategy
Contributor guide
Assessment
This issue has not been assessed yet.