br备份报resolve lock timeout

【 TiDB 使用环境】生产
【 TiDB 版本】
v5.2.2
【遇到的问题】
br备份报错
[2022/05/08 16:17:13.955 +08:00] [ERROR] [main.go:58] [“br failed”] [error=“resolve lock timeout”] [errorVerbose="resolve lock timeout
【复现路径】做过哪些操作出现的问题
【问题现象及影响】
我们通过br,把数据备份到minio上,备份脚本如下:

【附件】
br备份日志,见附件br_backup_scolap_to_minioossbak_2022-05-08.log (7.7 MB)

  • 相关日志、配置文件、Grafana 监控(https://metricstool.pingcap.com/)
  • TiUP Cluster Display 信息
  • TiUP CLuster Edit config 信息
  • TiDB-Overview 监控
  • 对应模块的 Grafana 监控(如有 BR、TiDB-binlog、TiCDC 等)
  • 对应模块日志(包含问题前后 1 小时日志)

若提问为性能优化、故障排查类问题,请下载脚本运行。终端输出的打印结果,请务必全选并复制粘贴上传。

2赞

看日志是从pd获取信息失败,pd状态正常吗?

[2022/05/08 16:17:13.750 +08:00] [INFO] [base_client.go:292] ["[pd] cannot update member from this address"] [address=http://10.122.131.99:2379] [error="[PD:cli
ent:ErrClientGetMember]error:rpc error: code = Canceled desc = context canceled target:10.122.131.99:2379 status:READY: error:rpc error: code = Canceled desc =
context canceled target:10.122.131.99:2379 status:READY"]
[2022/05/08 16:17:13.750 +08:00] [ERROR] [base_client.go:166] ["[pd] failed updateMember"] [error="[PD:client:ErrClientGetMember]error:rpc error: code = Cancele
d desc = context canceled target:10.122.131.99:2379 status:READY: error:rpc error: code = Canceled desc = context canceled target:10.122.131.99:2379 status:READ
Y"] [errorVerbose="[PD:client:ErrClientGetMember]error:rpc error: code = Canceled desc = context canceled target:10.122.131.99:2379 status:READY: error:rpc erro
r: code = Canceled desc = context canceled target:10.122.131.99:2379 status:READY\ngithub.com/tikv/pd/client.(*baseClient).updateMember\n\t/nfs/cache/mod/github
.com/tikv/pd@v1.1.0-beta.0.20210818112400-0c5667766690/client/base_client.go:297\ngithub.com/tikv/pd/client.(*baseClient).memberLoop\n\t/nfs/cache/mod/github.co
m/tikv/pd@v1.1.0-beta.0.20210818112400-0c5667766690/client/base_client.go:165\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"] [stack="github.com
/tikv/pd/client.(*baseClient).memberLoop\n\t/nfs/cache/mod/github.com/tikv/pd@v1.1.0-beta.0.20210818112400-0c5667766690/client/base_client.go:166"]
[2022/05/08 16:17:13.750 +08:00] [INFO] [client.go:510] ["[pd] exit tso dispatcher"] [dc-location=global]
[2022/05/08 16:17:13.751 +08:00] [INFO] [metafile.go:499] ["exit write metas by context done"]
[2022/05/08 16:17:13.872 +08:00] [INFO] [collector.go:66] ["Full backup failed summary"] [total-ranges=4539] 
1赞

10.122.131.99:2379
这个节点的网络或者etcd是不是有什么异常

1赞

如果 pd 当时很忙,响应时间超过 3 s,会有这个错误。
可以试一下 比5.2.2 更新的版本,新版本会重试。

1赞

网络好像没有问题

pd.log.tar.gz (5.6 MB)

1赞

prober found high clock drift pd节点的时间一致么

1赞

apply request took too long 看看io怎么样是不是有什么占用io较高,是混合部署么

1赞

时间是一致的
不是混合部署,但是这些是虚机,可能跟其他虚机在同一台物理机上。

这个是每次备份都不成功么,之后有没有重试过,也许是那一时段的pd比较繁忙?
日志里“apply request took too long” 也是基本任何时候都是再出现,看看能不能先解决一下这个问题 看看磁盘的io状态?

有网络抖动吧?

从8号到现在每天备份一次,但是都不成功。

网络没有抖动。

可以手工调用命令,试试备份一个小表能否成功吗?

嗯嗯,我现在改成单备份一个库(这个库中数据量不大)试一下,脚本正在运行中

image

又是这个报错

备份过程中, TiKV 返回 ErrResolveLockTimeout, 导致 BR 失败。
从备份 log 目前无法定位到是那个 tikv 调用返回的这个错误。

能不能给个开启 debug 的 log, 方便我们进一步定位。

一些怀疑点:
1,备份时间点上,数据库是不是有写入,5.2.2 对于这个 ErrResolveLockTimeout 错误没有重试,选择一个没有写入的时间点备份试试。
2,BR 到 TiKV 之前的网络是否稳定,log 显示, 大量的 failed to connect store
[2022/05/08 16:17:13.646 +08:00] [ERROR] [client.go:788] [“fail to connect store”] [range-sn=4] [StoreID=4752270] [stack=“github.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\n\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:788\ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\n\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:612”]
BR 节点 到 TiKV 之前链接的稳定性,看起来怀疑最大。换个节点 跑 BR 试试