一个TiKV节点的cpu很高导致整个集群基本不可用

脚本小王子 · 2021 年12 月 3 日 10:37

为提高效率，请提供以下信息，问题描述清晰能够更快得到解决：
【 TiDB 使用环境】
生产环境

【概述】场景+问题概述

22:30开始使用br对整个集群进行备份，0点时强制中止
业务一直有写入操作，大数据也会不定期的写入大量数据（百万级别）
2021-12-02 23:00:00收到第一条操作tidb慢的报警

接到报警后进入tidb执行show processlist发现一个tidb-server有约500个线程在insert一个2900万的表，业务使用两个tidb-server，总共约1000个连接在执行insert一个表，但执行很慢，当时看到有四五十秒还在执行的，如下图（23:18时的截图）：

另外，大数据也在写另一个tidb-server（写入300万+），下图为23:21时的状态

当时TiDB基本处理无响应的状态，查看监控发现TiKV的cpu很慢，其中一个tikv节点的Storage ReadPool CPU，如下图：

【背景】做过哪些操作
接到报警后：
1、停止大数据的写入
2、对业务写入的表重命名到另外一个库作为备份，业务库新建一张空表供业务写入
3、停掉mysql->TiDB的dm同步
4、停掉cdc服务
上述处理过后，tidb依然很卡！

【现象】业务和数据库现象
【业务影响】
业务无法提供服务
【TiDB 版本】
v4.0.10
【附件】

相关日志和监控

TiUP Cluster Display 信息

image1209×458 17.1 KB
TiUP Cluster Edit Config 信息
TiUP Cluster Edit Config 信息.txt (3.9 KB)
TiDB- Overview 监控
mg-tidb-Overview_2021-12-03T10_11_48.425Z.rar (286.4 KB)

mg-tidb-TiKV-Details_2021-12-03T10_11_25.950Z.rar (3.1 MB)

对应模块日志（包含问题前后1小时日志）

cpu高的tikv节点日志如下：

[root@tidb-tikv-1 log]# tail tikv.log.2021-12-03-00:00:16.126888600
[2021/12/01 19:04:59.982 +08:00] [ERROR] [store.rs:487] ["handle raft message failed"] [err_code=KV:Raftstore:Unknown] [err="Other(\"[components/raftstore/src/store/fsm/store.rs:1360]: [region 17616486] region not exist but not tombstone: region { id: 17616486 start_key: 7480000000000061FF195F728000000000FF1952C90000000000FA end_key: 7480000000000061FF195F728000000000FF23A29B0000000000FA region_epoch { conf_ver: 4112 version: 26806 } peers { id: 17616487 store_id: 2 } peers { id: 17616488 store_id: 1077486 } peers { id: 17616489 store_id: 1203960 } }\")"] [store_id=2]
[2021/12/01 22:31:59.369 +08:00] [ERROR] [endpoint.rs:160] ["backup snapshot failed"] [err_code=KV:Raftstore:NotLeader] [err="Request(message: \"peer is not leader for region 459321, leader may Some(id: 459323 store_id: 1)\" not_leader { region_id: 459321 leader { id: 459323 store_id: 1 } })"]
[2021/12/01 22:31:59.372 +08:00] [ERROR] [endpoint.rs:680] ["backup region failed"] [err_code=KV:Unknown] [err="Engine(Request(message: \"peer is not leader for region 459321, leader may Some(id: 459323 store_id: 1)\" not_leader { region_id: 459321 leader { id: 459323 store_id: 1 } }))"] [end_key=7480000000000006CB5F698000000000000001037FFFFFFFFFFFFFFF0380000000054BBDC5] [start_key=7480000000000006CB5F698000000000000001037FFFFFFFFFFFFFFF0380000000053BCE16] [region="id: 459321 start_key: 7480000000000006FFCB5F698000000000FF000001037FFFFFFFFFFFFFFFFF03800000FF00053BCE16000000FC end_key: 7480000000000006FFCB5F698000000000FF000001037FFFFFFFFFFFFFFFFF03800000FF00054BBDC5000000FC region_epoch { conf_ver: 11 version: 5806 } peers { id: 459322 store_id: 2 } peers { id: 459323 store_id: 1 } peers { id: 1232387 store_id: 1203960 }"]
[2021/12/02 06:58:23.872 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]
[2021/12/02 10:05:11.735 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]
[2021/12/02 11:30:07.143 +08:00] [ERROR] [<unknown>] ["ipv4:172.16.5.167:38988: Keepalive watchdog fired. Closing transport."]
[2021/12/02 17:01:05.945 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]
[2021/12/02 17:04:58.249 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg="CaptureChange { cmd: RegisterObserver { observe_id: ObserveID(9679), region_id: 17706758, enabled: true }, region_epoch: conf_ver: 1454 version: 22974, callback: Callback::Read(..) }"]
[2021/12/02 17:04:58.254 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg="CaptureChange { cmd: RegisterObserver { observe_id: ObserveID(9680), region_id: 17706758, enabled: true }, region_epoch: conf_ver: 1454 version: 22974, callback: Callback::Read(..) }"]
[2021/12/03 00:00:16.119 +08:00] [ERROR] [service.rs:86] ["backup canceled"] [error=RemoteStopped]
[root@tidb-tikv-1 log]# 
[root@tidb-tikv-1 log]# head tikv.log
[2021/12/03 00:00:16.128 +08:00] [ERROR] [service.rs:86] ["backup canceled"] [error=RemoteStopped]
[2021/12/03 00:00:19.728 +08:00] [ERROR] [endpoint.rs:707] ["backup failed to send response"] [err_code=KV:Unknown] [err="TrySendError { kind: Disconnected }"]
[2021/12/03 00:00:21.529 +08:00] [ERROR] [endpoint.rs:707] ["backup failed to send response"] [err_code=KV:Unknown] [err="TrySendError { kind: Disconnected }"]
[2021/12/03 02:24:20.603 +08:00] [ERROR] [<unknown>] ["ipv4:172.16.5.167:17368: Keepalive watchdog fired. Closing transport."]
[2021/12/03 02:24:32.121 +08:00] [ERROR] [<unknown>] ["ipv4:172.16.5.167:20600: Keepalive watchdog fired. Closing transport."]
[2021/12/03 02:28:58.629 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]
[2021/12/03 07:11:48.250 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]
[2021/12/03 07:34:13.914 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg="CaptureChange { cmd: RegisterObserver { observe_id: ObserveID(12107), region_id: 9472123, enabled: true }, region_epoch: conf_ver: 1769 version: 23196, callback: Callback::Read(..) }"]
[2021/12/03 07:34:14.260 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]
[2021/12/03 07:49:42.669 +08:00] [ERROR] [router.rs:170] ["failed to send significant msg"] [msg=LeaderCallback(Callback::Read(..))]

xfworld · 2021 年12 月 3 日 15:50

有两个问题：

如下图：

image876×398 32.2 KB
备份操作时，有没有对tikv 做限流？

image835×190 13.2 KB

image851×467 21.8 KB
大量数据写入，是否有热点问题？从你提交的图上来看， 172.16.2.222 和 172.16.5.233 的cpu 高得有点厉害～不知道是写入问题，还是备份导致的？

你提交的日志有点大，明天在看了～

xfworld · 2021 年12 月 4 日 02:02

这两个节点的错误有点多噢

tidb 卡，就这个节点了

这个场景有点复杂，我感觉是 BR 操作时没选好时机，然后没对 BR 操作进行限流

现在集群正常了么？

脚本小王子 · 2021 年12 月 4 日 05:23

感谢回复！
1、目前安排在22:30开始备份已经是业务最低峰的时候了，深夜会有大量的大数据作业写入
2、没有加–ratelimit参数做限流，下一步会增加这个参数（不过br备份都上了大半年了，就只有那天有问题）
3、会有点索引热点，主键都是都是随机主键了，但作业也是以前每天都跑的

脚本小王子 · 2021 年12 月 4 日 05:25

嗯，165这台tidb-server是专给大数用的，220和221才是给业务用的
目前集群是正常的，就是担心以后也会出现类似的情况。

脚本小王子 · 2021 年12 月 6 日 03:52

请问除了备份外，还能看现什么问题导致吗？

xfworld · 2021 年12 月 6 日 04:32

可以考虑解决掉哪个索引的热点问题
跟踪下慢查询

脚本小王子 · 2021 年12 月 8 日 03:40

昨晚22点和今天上午8:40又出现类似的情况，表现都是一个TiKV中的Storage ReadPool CPU很高，然后整个集群卡住，重启该TiKV节点后恢复正常，监控如下：

这两次出现问题时都没在备份了，只有业务正常的读写，另外这两次故障发生时都对一个表插入40万+的记录，40个线程并发写，每个线程的一个insert插入4000多条记录，该表结构如下：

CREATE TABLE `xxx_device_active_type` (
  `id` bigint(20) NOT NULL /*T![auto_rand] AUTO_RANDOM(5) */,
  `imei` varchar(30) NOT NULL DEFAULT '' COMMENT 'imei',
  `type` tinyint(3) NOT NULL DEFAULT '0' COMMENT '设备类型',
  `startDate` date NOT NULL DEFAULT '1970-01-01' COMMENT '开始日期',
  `endDate` date NOT NULL DEFAULT '1970-01-01' COMMENT '结束日期',
  `createTime` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '记录创建时间',
  PRIMARY KEY (`id`),
  UNIQUE KEY `ENDDATE_IMEI_STARTDATE` (`endDate`,`imei`,`startDate`),
  KEY `idx_type` (`type`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin /*T![auto_rand_base] AUTO_RANDOM_BASE=17092576

目前表记录数980万+

xfworld · 2021 年12 月 8 日 03:47

你可以查一下这个表的 region 怎么分布的，查阅一下热力图看看是不是有读写热点

脚本小王子 · 2021 年12 月 8 日 03:53

这个表的region分布如下：

热力图是哪个？是流量可视化那个吗？

xfworld · 2021 年12 月 8 日 06:52

从region 分布上来看，这个有点不均匀了

对，这个就是热力图（流量可视化），基本上都是集中式访问

能上传一下出问题 tikv 的日志么？就出问题时间段前后的日志就行

脚本小王子 · 2021 年12 月 8 日 07:17

今天出问题是8:40左右，对应的tikv的日志如下：
tikv.log (560.4 KB)

xfworld · 2021 年12 月 8 日 08:06

这个表示tikv 之间的联系断开了
1）查看是否有 TiKV 挂掉
2）查看 TiKV 之间的网络是否有异常

查到这个问题的参考解答：

脚本小王子 · 2021 年12 月 8 日 11:05

感谢！
把表xxx_device_active_type重建后问题不再出现了

数据小黑 · 2021 年12 月 9 日 01:01

这个地方有个认知错误，主键是随机的也会出现热点读写，只要不是bigint或者int作为主键，数据落盘是根据row_id落盘的，建议参考：https://docs.pingcap.com/zh/tidb/stable/shard-row-id-bits

脚本小王子 · 2021 年12 月 9 日 02:16

出问题的表原来已经是定义为bigint的AUTO_RANDOM哦

数据小黑 · 2021 年12 月 9 日 02:24

了解了，

system · 2022 年10 月 31 日 19:04

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。