4.0.5版本执行select触发tikvRPC backoffer.maxSleep

tidbtest3 · 2020 年9 月 10 日 09:07

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

【TiDB 版本】：v4.0.5
【问题描述】：
这个帖子沟通了很久，为避免产生信息误导，重新编辑下问题

1.升级v4.0.5之后执行sql
select * from xxx limit 1之后tidb.log中产生大量warning（多个表查询稳定触发，但非全部表）
[WARN] [region_request.go:407] [“receive a grpc cancel signal from remote”] [error=“rpc error: code = Canceled desc = context canceled”]

并触发tikvRPC backoffer.maxSleep 40000ms
使后面无论执行任何语句都要在40000ms后返回结果

2.升级过程参考升级文档，无其余操作，升级过程中也未发生异常

3.select触发问题时对应log、完整监控信息可在楼下回帖中查看

Lucien-卢西恩 · 2020 年9 月 10 日 09:09

explain analyze SQL 发一下结果哈～

tidbtest3 · 2020 年9 月 10 日 09:22

这个集群升级前是3.0.7版本，没有出现过此问题，我在今天升级的另一套4.0.5集群执行该sql也没有出现这种情况

Lucien-卢西恩 · 2020 年9 月 10 日 09:26

执行一下 explain analyze 对一层的算子执行时间都会有记录的。你最上面发的那个只能看出来是走 tablefullscan，以及一个 slow query 的耗时时间。我想确认一下是不是在 TiDB Server 层做汇聚计算的时间长是因为查询缓存数据大导致的。
https://docs.pingcap.com/zh/tidb/stable/sql-statement-explain-analyze#explain-analyze

Lucien-卢西恩 · 2020 年9 月 10 日 09:44

看起来不是本身 SQL 的问题，麻烦确认一下集群负载。这个 SQL 正常在 2ms 左右就应该返回。确认一下系统资源，比如网络带宽、内存资源、CPU 资源是否有瓶颈。你也可以尝试一下其他的 SQL 有没有类似问题。

tidbtest3 · 2020 年9 月 10 日 09:48

集群负载没有很明显的波动，此外，如果cpu、内存等原因导致sql执行慢的话，应该在dashboard的各项耗时时间里体现出来，另外就是这个集群是一个备份集群，目前也没有业务在使用，执行的sql也都是写操作的，整体的query time也没有明显波动，所以才感觉很诡异

Lucien-卢西恩 · 2020 年9 月 10 日 09:57

这个 SQL 执行时间超过 30s ，建议执行过程中，抓一下 gopprof

go tool pprof http://{TiDBIP}:10080/debug/pprof/profile?seconds=30s

另外查一下 TiDB log 有没有其他异常。

tidbtest3 · 2020 年9 月 10 日 10:28

看了下tidb.log
第一次执行sql，0.01s返回结果，但是log中大量的
[2020/09/10 18:21:07.963 +08:00] [WARN] [region_request.go:407] [“receive a grpc cancel signal from remote”] [error=“rpc error: code = Canceled desc = context canceled”]
[2020/09/10 18:21:07.963 +08:00] [WARN] [region_request.go:407] [“receive a grpc cancel signal from remote”] [error=“rpc error: code = Canceled desc = context canceled”]
[2020/09/10 18:21:07.963 +08:00] [WARN] [region_request.go:407] [“receive a grpc cancel signal from remote”] [error=“rpc error: code = Canceled desc = context canceled”]
[2020/09/10 18:21:07.963 +08:00] [WARN] [region_request.go:407] [“receive a grpc cancel signal from remote”] [error=“rpc error: code = Canceled desc = context canceled”]
然后还会出现
[2020/09/10 18:21:49.483 +08:00] [WARN] [backoff.go:316] ["tikvRPC backoffer.maxSleep 40000ms is exceeded, errors:\ send tikv request error: rpc error: code = Canceled desc = context canceled, ctx: region ID: 108124, meta: id:108124 start_key:\"t\\200\\000\\000\\000\\000\\000\\004\\343_r\\200\\000\\000\\000\\002\\371\\227\\016\" end_key:\"t\\200\\000\\000\\000\\000\\000\\004\\343_r\\200\\000\\000\\000\\002\\374\\257\\347\" region_epoch:<conf_ver:5 version:632 > peers:<id:108125 store_id:1 > peers:<id:108126 store_id:4 > peers:<id:108127 store_id:5 > , peer: id:108125 store_id:1 , addr: 10.10.111.193:20160, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv, try next peer later at 2020-09-10T18:21:46.098159789+08:00\ send tikv request error: rpc error: code = Canceled desc = context canceled, ctx: region ID: 108124, meta: id:108124 start_key:\"t\\200\\000\\000\\000\\000\\000\\004\\343_r\\200\\000\\000\\000\\002\\371\\227\\016\" end_key:\"t\\200\\000\\000\\000\\000\\000\\004\\343_r\\200\\000\\000\\000\\002\\374\\257\\347\" region_epoch:<conf_ver:5 version:632 > peers:<id:108125 store_id:1 > peers:<id:108126 store_id:4 > peers:<id:108127 store_id:5 > , peer: id:108125 store_id:1 , addr: 10.10.111.193:20160, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv, try next peer later at 2020-09-10T18:21:47.86963704+08:00\ send tikv request error: rpc error: code = Canceled desc = context canceled, ctx: region ID: 108124, meta: id:108124 start_key:\"t\\200\\000\\000\\000\\000\\000\\004\\343_r\\200\\000\\000\\000\\002\\371\\227\\016\" end_key:\"t\\200\\000\\000\\000\\000\\000\\004\\343_r\\200\\000\\000\\000\\002\\374\\257\\347\" region_epoch:<conf_ver:5 version:632 > peers:<id:108125 store_id:1 > peers:<id:108126 store_id:4 > peers:<id:108127 store_id:5 > , peer: id:108125 store_id:1 , addr: 10.10.111.193:20160, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv, try next peer later at 2020-09-10T18:21:49.483228026+08:00"]

第二次执行这个sql就会很慢，30s以上

tidbtest3 · 2020 年9 月 10 日 11:15

看报错跟grpc有关系，不过grpc相关的配置都是默认值，分别执行
show config where type = ‘tidb’ and name like ‘%grpc%’;
show config where type = ‘pd’ and name like ‘%grpc%’;
show config where type = ‘tikv’ and name like ‘%grpc%’;
结果与其他正常集群对比都是一样的

yilong · 2020 年9 月 11 日 03:12

curl http://{TiDBIP}:10080/regions/{regionID} 检查下 region ID: 108124 是什么信息
这个集群会有写操作，这个表 supplies 会有大量写入吗？
能否麻烦您反馈下问题发生前到报错的 tidb.log 和 tikv.log 日志，方便查看是否还有其他问题，多谢。

tidbtest3 · 2020 年9 月 11 日 03:22

1.{ "region_id": 108124, "start_key": "dIAAAAAAAATjX3KAAAAAAvmXDg==", "end_key": "dIAAAAAAAATjX3KAAAAAAvyv5w==", "frames": [ { "db_name": "material", "table_name": "supplies", "table_id": 1251, "is_record": true, "record_id": 49911566 } ]

2.这个集群是用来做备份的，很多库的数据都会往这里写，但是supplies不会有大量写入，这个表目前为止也就1000多万数据
3.问题发生前都没有异常，这个问题是稳定复现的，只要一执行select * from xxx limit 1这种sql就会复现(测试非supplies的其他表也是一样)，tidb中出现大量receive a grpc cancel signal from remote，接下来执行任何sql好像都会触发tikvRPC backoffer.maxSleep 40000ms 这个条件，在第一条sql执行后的40s左右返回结果

Lucien-卢西恩 · 2020 年9 月 11 日 03:42

发一下昨天和你说的信息，我们要确认一下执行 explain 时候,通过 go-pprofe 抓一下 debug 信息，我们要在确认一下。

go tool pprof http://{TiDBIP}:10080/debug/pprof/profile?seconds=30s

另外麻烦反馈一下以下信息：

通过 pd-ctl 查看以下 region ID: 108124 的状态；
在 PD log 和 Region ID 108124 对应的 leader store 的 tikv log 记录的这个 Region 的 transfer 和 schedule 的情况看看。
反馈上面的信息，另外注意有没有类似的问题的 region 。

tidbtest3 · 2020 年9 月 11 日 04:09

pprof.tidb-server.samples.cpu.001.pb.gz (66.1 KB)

pprof.tidb-server.samples.cpu.002.pb.gz (88.4 KB)

附件001为第一次执行sql的debug信息（sql很快，但是会触发receive a grpc cancel signal from remote）
附件002为第二次执行sql的debug信息，此时耗时较长，执行时间为30s+

测试sql均为select * from supplies limit 1

另外任意表都会出现这个情况，不只supplies，所以感觉跟region关系不大

Lucien-卢西恩 · 2020 年9 月 11 日 07:18

这个麻烦查一下？有没有非预期的 region 调度问题。

tidbtest3 · 2020 年9 月 11 日 09:15

region状态如下
» region 108124
{
“id”: 108124,
“start_key”: “7480000000000004FFE35F728000000002FFF9970E0000000000FA”,
“end_key”: “7480000000000004FFE35F728000000002FFFCAFE70000000000FA”,
“epoch”: {
“conf_ver”: 5,
“version”: 632
},
“peers”: [
{
“id”: 108125,
“store_id”: 1
},
{
“id”: 108126,
“store_id”: 4
},
{
“id”: 108127,
“store_id”: 5
}
],
“leader”: {
“id”: 108125,
“store_id”: 1
},
“written_bytes”: 433,
“read_bytes”: 0,
“written_keys”: 1,
“read_keys”: 0,
“approximate_size”: 58,
“approximate_keys”: 163840
}

查看对应store的tikv.log，未发现非预期的region调度问题，调度的三次均与修改tikv配置reload有关，此外昨天有一次reload时加了–force，不确定是否跟这个有关系
另外关于“另外注意有没有类似的问题的 region”，如果查询每个表都出现此类情况，是否可以排除是region的问题？

Lucien-卢西恩 · 2020 年9 月 11 日 10:01

这个会和当时的 reload 的时间段内影响到那个时间段的读写请求。刚才看了你发的 pprof 的情况，应该还是在 tikv 这里面慢了。所以还是需要看一下监控，尤其是出现问题的前后对比的监控。排查一下资源瓶颈。

robi · 2020 年9 月 14 日 03:40

确认下是 explain 就比较慢？（不是 explain analyze）

可以帮忙看下 tidb slow log 中看下这个这个执行比较慢的 explain 的慢日志情况

tidbtest3 · 2020 年9 月 14 日 03:43

这个sql本身不慢，慢的原因在上面有提到，第一遍执行很快，但是出现大量receive a grpc cancel signal from remote
然后会触发tikvRPC backoffer.maxSleep 40000ms
紧接着第二次无论执行什么sql都会很慢，慢的原因是触发了tikvRPC backoffer.maxSleep 40000ms

robi · 2020 年9 月 14 日 06:52

嗯嗯方便提供下 tidb 和 10.10.111.193:20160 对应的 tikv 在报 receive a grpc cancel signal from remote 时间点附近的日志文件吗？

tidbtest3 · 2020 年9 月 14 日 07:03

tidb_error_20200914.log (201.4 KB)

是tidb报错的，非tikv，我又执行了一次select * from supplies limit 1主动触发了这个问题，从日志上看在触发错误前，tidb日志中有很多switch region leader to specific leader due to kv return
NotLeader问题