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

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

  • 【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、完整监控信息可在楼下回帖中查看

explain analyze SQL 发一下结果哈 ~

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

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

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

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

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

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

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

看了下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以上

看报错跟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%’;
结果与其他正常集群对比都是一样的

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

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左右返回结果

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

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

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

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

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关系不大

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

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的问题?

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

确认下是 explain 就比较慢?(不是 explain analyze)

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

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

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

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问题