Repository: tikv/client-go (go)

Issue:
stale read QPS is too low when test with kv_read_timeout and max_execution_time
# Topology

Version: nightly

```sql
+------+--------------------+--------------------+--------------------------+------------------------------------------+---------------------------+---------------------+-----------+
| TYPE | INSTANCE           | STATUS_ADDRESS     | VERSION                  | GIT_HASH                                 | START_TIME                | UPTIME              | SERVER_ID |
+------+--------------------+--------------------+--------------------------+------------------------------------------+---------------------------+---------------------+-----------+
| tidb | 192.168.78.3:23400 | 192.168.78.3:23080 | 7.4.0-alpha-386-gf1067a1 | f1067a1b761d5bae74510fc715f28814a633352d | 2023-09-13T11:23:19+08:00 | 1h8m5.142420463s    | 634       |
| tidb | 192.168.78.4:23400 | 192.168.78.4:23080 | 7.4.0-alpha-386-gf1067a1 | f1067a1b761d5bae74510fc715f28814a633352d | 2023-09-13T11:23:42+08:00 | 1h7m42.142422497s   | 970       |
| tidb | 192.168.78.2:23400 | 192.168.78.2:23080 | 7.4.0-alpha-386-gf1067a1 | f1067a1b761d5bae74510fc715f28814a633352d | 2023-09-13T11:22:58+08:00 | 1h8m26.1424236s     | 559       |
| pd   | 192.168.78.3:23379 | 192.168.78.3:23379 | 7.4.0-alpha              | 58113f8d17ccec4690445dad2e47cadbacd42da3 | 2023-09-12T15:45:50+08:00 | 20h45m34.142424456s | 0         |
| pd   | 192.168.78.2:23379 | 192.168.78.2:23379 | 7.4.0-alpha              | 58113f8d17ccec4690445dad2e47cadbacd42da3 | 2023-09-12T15:45:50+08:00 | 20h45m34.142425424s | 0         |
| pd   | 192.168.78.4:23379 | 192.168.78.4:23379 | 7.4.0-alpha              | 58113f8d17ccec4690445dad2e47cadbacd42da3 | 2023-09-12T15:45:50+08:00 | 20h45m34.142426465s | 0         |
| tikv | 192.168.80.4:23360 | 192.168.80.4:23380 | 7.4.0-alpha              | 98eb383b41695b11a03e3d1ce471181f02bfc741 | 2023-09-12T15:45:52+08:00 | 20h45m32.142427254s | 0         |
| tikv | 192.168.80.3:23360 | 192.168.80.3:23380 | 7.4.0-alpha              | 98eb383b41695b11a03e3d1ce471181f02bfc741 | 2023-09-12T15:45:52+08:00 | 20h45m32.142427995s | 0         |
| tikv | 192.168.80.2:23361 | 192.168.80.2:23381 | 7.4.0-alpha              | 98eb383b41695b11a03e3d1ce471181f02bfc741 | 2023-09-12T15:45:52+08:00 | 20h45m32.142428715s | 0         |
| tikv | 192.168.80.2:23360 | 192.168.80.2:23380 | 7.4.0-alpha              | 98eb383b41695b11a03e3d1ce471181f02bfc741 | 2023-09-12T15:45:52+08:00 | 20h45m32.142429364s | 0         |
| tikv | 192.168.80.3:23361 | 192.168.80.3:23381 | 7.4.0-alpha              | 98eb383b41695b11a03e3d1ce471181f02bfc741 | 2023-09-12T15:45:52+08:00 | 20h45m32.142431041s | 0         |
| tikv | 192.168.80.4:23361 | 192.168.80.4:23381 | 7.4.0-alpha              | 98eb383b41695b11a03e3d1ce471181f02bfc741 | 2023-09-12T15:45:52+08:00 | 20h45m32.142431848s | 0         |
+------+--------------------+--------------------+--------------------------+------------------------------------------+---------------------------+---------------------+-----------+
```

# Inject network latency

Inject 1000ms network delay in all TiDB nodes to `192.168.80.2`, which deploy TiKV `192.168.80.2:23360` and `192.168.80.2:23361`

```
[root@192.168.78.2]# ping 192.168.80.2
PING 192.168.80.2 (192.168.80.2) 56(84) bytes of data.
64 bytes from 192.168.80.2: icmp_seq=1 ttl=62 time=546 ms
64 bytes from 192.168.80.2: icmp_seq=2 ttl=62 time=217 ms
64 bytes from 192.168.80.2: icmp_seq=3 ttl=62 time=145 ms
64 bytes from 192.168.80.2: icmp_seq=4 ttl=62 time=500 ms
64 bytes from 192.168.80.2: icmp_seq=5 ttl=62 time=1091 ms

[root@192.168.78.2]# ping 192.168.80.3
PING 192.168.80.3 (192.168.80.3) 56(84) bytes of data.
64 bytes from 192.168.80.3: icmp_seq=1 ttl=62 time=0.086 ms
64 bytes from 192.168.80.3: icmp_seq=2 ttl=62 time=0.079 ms
64 bytes from 192.168.80.3: icmp_seq=3 ttl=62 time=0.082 ms


[root@192.168.78.2]# ping 192.168.80.4
PING 192.168.80.4 (192.168.80.4) 56(84) bytes of data.
64 bytes from 192.168.80.4: icmp_seq=1 ttl=62 time=0.088 ms
64 bytes from 192.168.80.4: icmp_seq=2 ttl=62 time=0.072 ms
64 bytes from 192.168.80.4: icmp_seq=3 ttl=62 time=0.058 ms
```

`192.168.78.3` and `192.168.78.4` are same with upper too.

# Test

Load: stale-read request
tidb_kv_read_timeout: 100
max_execution_time: 400

```shell
sysbench --config-file=sysbench.conf mussel_minimal.lua --threads=20 --read_staleness=-10 --kv_read_timeout=100 --max_execution_time=400 --mysql-ignore-errors=all run
```

The following are related metrics, some of metrics here are not as expected:

- Too much failed query in TiDB `192.168.78.2`, which cause by execution timeout.

<img width="1425" alt="image" src="https://github.com/tikv/client-go/assets/26020263/8c6267c0-a68d-4188-b40d-4f7d67566c7e">

<img width="1431" alt="image" src="https://github.com/tikv/client-go/assets/26020263/9cc645e8-8569-4f4c-a6b6-bd65caa6ca94">

<img width="1429" alt="image" src="https://github.com/tikv/client-go/assets/26020263/f5e22871-8956-4f30-a076-17b7abeeb3e5">

<img width="2872" alt="image" src="https://github.com/tikv/client-go/assets/26020263/abf97f28-3268-48d2-b57f-f0a5844cb59e">




Pull request:
*: try follower when stale read request timeout
close #970

Do the same test in #970 

**Before this PR**

The following are related metrics, some of metrics here are not as expected:

- Too much failed query in TiDB `192.168.78.2`, which cause by execution timeout.

<img width="1425" alt="image" src="https://github.com/tikv/client-go/assets/26020263/8c6267c0-a68d-4188-b40d-4f7d67566c7e">

<img width="1431" alt="image" src="https://github.com/tikv/client-go/assets/26020263/9cc645e8-8569-4f4c-a6b6-bd65caa6ca94">

<img width="1429" alt="image" src="https://github.com/tikv/client-go/assets/26020263/f5e22871-8956-4f30-a076-17b7abeeb3e5">

<img width="2872" alt="image" src="https://github.com/tikv/client-go/assets/26020263/abf97f28-3268-48d2-b57f-f0a5844cb59e">


**This PR**

- TiDB `192.168.78.2` doesn't have any failed query which execution timeout now, and doesn't have backoff too.
- TIDB `192.168.78.2` has a low QPS because each of the stale-read queries will timeout (100ms) first and then retry to succeed, and it only has 15 connections executing requests.

<img width="1435" alt="image" src="https://github.com/tikv/client-go/assets/26020263/ee4cc88d-8dd8-4784-a360-6d9e3a60ddd4">

<img width="1435" alt="image" src="https://github.com/tikv/client-go/assets/26020263/2382f448-0b70-42e7-96e8-985a5ad51549">

<img width="1430" alt="image" src="https://github.com/tikv/client-go/assets/26020263/048d2ce9-e996-4147-9f6f-d2d0b4e3577a">


<img width="2875" alt="image" src="https://github.com/tikv/client-go/assets/26020263/1f8423b5-5c18-4f4c-b819-04372a1bf5c4">

<img width="1435" alt="image" src="https://github.com/tikv/client-go/assets/26020263/3130f565-12e5-4af0-ac13-fccc7cc9ddc7">




Patch:
diff --git a/internal/locate/region_request.go b/internal/locate/region_request.go
index 33d56cb..5b52308 100644
--- a/internal/locate/region_request.go
+++ b/internal/locate/region_request.go
@@ -735,17 +735,15 @@ func (state *accessFollower) next(bo *retry.Backoffer, selector *replicaSelector
 			logutil.Logger(bo.GetCtx()).Warn("unable to find stores with given labels",
 				zap.Uint64("region", selector.region.GetID()),
 				zap.Bool("leader-invalid", leaderInvalid),
+				zap.Bool("stale-read", state.isStaleRead),
 				zap.Any("labels", state.option.labels))
 		}
-		// If leader tried and received deadline exceeded error, return nil to upper layer to retry with default timeout.
-		if leader.deadlineErrUsingConfTimeout {
-			return nil, nil
-		}
-		if leaderInvalid {
+		if leaderInvalid || leader.deadlineErrUsingConfTimeout {
 			// In stale-read, the request will fallback to leader after the local follower failure.
 			// If the leader is also unavailable, we can fallback to the follower and use replica-read flag again,
 			// The remote follower not tried yet, and the local follower can retry without stale-read flag.
-			if state.isStaleRead {
+			// If leader tried and received deadline exceeded error, try follower.
+			if state.isStaleRead || leader.deadlineErrUsingConfTimeout {
 				selector.state = &tryFollower{
 					leaderIdx: state.leaderIdx,
 					lastIdx:   state.leaderIdx,
@@ -1519,6 +1517,7 @@ func (s *RegionRequestSender) logSendReqError(bo *retry.Backoffer, msg string, r
 		zap.Int("retry-times", retryTimes),
 		zap.Int("total-backoff-ms", bo.GetTotalSleep()),
 		zap.Int("total-backoff-times", bo.GetTotalBackoffTimes()),
+		zap.Uint64("max-exec-timeout-ms", req.Context.MaxExecutionDurationMs),
 		zap.String("total-region-errors", totalErrorStr.String()))
 }
 


Test patch:
diff --git a/internal/locate/region_request3_test.go b/internal/locate/region_request3_test.go
index 6d14fef..a079e2c 100644
--- a/internal/locate/region_request3_test.go
+++ b/internal/locate/region_request3_test.go
@@ -1255,14 +1255,9 @@ func (s *testRegionRequestToThreeStoresSuite) TestSendReqFirstTimeout() {
 			s.Nil(err)
 			s.True(IsFakeRegionError(regionErr))
 			s.Equal(1, len(s.regionRequestSender.Stats))
-			if staleRead {
-				rpcNum := s.regionRequestSender.Stats[tikvrpc.CmdGet].Count
-				s.True(rpcNum == 1 || rpcNum == 2) // 1 rpc or 2 rpc
-			} else {
-				s.Equal(int64(3), s.regionRequestSender.Stats[tikvrpc.CmdGet].Count) // 3 rpc
-				s.Equal(3, len(reqTargetAddrs))                                      // each rpc to a different store.
-			}
-			s.Equal(0, bo.GetTotalBackoffTimes()) // no backoff since fast retry.
+			s.Equal(int64(3), s.regionRequestSender.Stats[tikvrpc.CmdGet].Count) // 3 rpc
+			s.Equal(3, len(reqTargetAddrs))                                      // each rpc to a different store.
+			s.Equal(0, bo.GetTotalBackoffTimes())                                // no backoff since fast retry.
 			// warn: must rest MaxExecutionDurationMs before retry.
 			resetStats()
 			if staleRead {
@@ -1530,3 +1525,43 @@ func (s *testRegionRequestToThreeStoresSuite) TestRetryRequestSource() {
 		}
 	}
 }
+
+func (s *testRegionRequestToThreeStoresSuite) TestStaleReadTryFollowerAfterTimeout() {
+	var (
+		leaderAddr  string
+		leaderLabel []*metapb.StoreLabel
+	)
+	bo := retry.NewBackoffer(context.Background(), 10000)
+	mockRPCClient := &fnClient{fn: func(ctx context.Context, addr string, req *tikvrpc.Request, timeout time.Duration) (*tikvrpc.Response, error) {
+		if addr == leaderAddr {
+			return nil, context.DeadlineExceeded
+		}
+		return &tikvrpc.Response{Resp: &kvrpcpb.GetResponse{Value: []byte("value")}}, nil
+	}}
+	s.regionRequestSender = NewRegionRequestSender(s.cache, mockRPCClient)
+	s.regionRequestSender.RegionRequestRuntimeStats = NewRegionRequestRuntimeStats()
+	getLocFn := func() *KeyLocation {
+		loc, err := s.regionRequestSender.regionCache.LocateKey(bo, []byte("a"))
+		s.Nil(err)
+		region := s.regionRequestSender.regionCache.GetCachedRegionWithRLock(loc.Region)
+		leaderStore, _, _, _ := region.WorkStorePeer(region.getStore())
+		leaderAddr, err = s.regionRequestSender.regionCache.getStoreAddr(s.bo, region, leaderStore)
+		s.Nil(err)
+		leaderLabel = []*metapb.StoreLabel{{Key: "id", Value: strconv.FormatUint(leaderStore.StoreID(), 10)}}
+		return loc
+	}
+	req := tikvrpc.NewRequest(tikvrpc.CmdGet, &kvrpcpb.GetRequest{Key: []byte("a")}, kvrpcpb.Context{})
+	req.EnableStaleRead()
+	loc := getLocFn()
+	var ops []StoreSelectorOption
+	ops = append(ops, WithMatchLabels(leaderLabel))
+	resp, _, _, err := s.regionRequestSender.SendReqCtx(bo, req, loc.Region, time.Second, tikvrpc.TiKV, ops...)
+	s.Nil(err)
+	regionErr, err := resp.GetRegionError()
+	s.Nil(err)
+	s.Nil(regionErr)
+	s.Equal([]byte("value"), resp.Resp.(*kvrpcpb.GetResponse).Value)
+	s.Equal(1, len(s.regionRequestSender.Stats))
+	s.Equal(int64(2), s.regionRequestSender.Stats[tikvrpc.CmdGet].Count) // 2 rpc
+	s.Equal(0, bo.GetTotalBackoffTimes())                                // no backoff since fast retry.
+}