【TiDB 使用环境】生产环境
【TiDB 版本】v6.5.0
【操作系统】centos8
【集群节点数】3db 6kv
今天凌晨发现使用集群的任务在创建数据库连接位置频繁报错,信息为登录阶段 network timeout,在多个环境测试手动登录发现也连不上,当时检查 dashboard 和 grafana 上 db pd kv 监控未发现负载有明显异常,同时 db 存在还活着的连接一百多个。
最开始怀疑是 db 的问题,于是 tiup restart -R tidb 重启了所有 db 节点, 但 tiup 随后报 tidb 启动超时,tiup display 显示所有 db 节点为 down,但 db 进程本省正常启动且没有快速重启,日志打印至 [INFO] [printer.go:48] ["loaded config"]
后没有下文,为了排除是 pd 的问题,在 db 起不来的情况下重启了 pd 所有节点,发现 db 日志中正常打印了 pd 断开 [2025/09/09 07:25:51.525 +08:00] [ERROR] [base_client.go:144] ["[pd] failed updateMember"] [error="[PD:client:ErrClientGetLeader]get leader from [http://10.120.33.151:2379 http://10.120.33.42:2379 http://10. 120.33.68:2379] error"]
,并且在 pd 重启后 db 仍然无法启动,暂时没再看 pd 的问题。
因为 db 起不来,就把 db 的日志等级提到了 info 并再次重启 db 节点,发现 db 在启动时输出了以下日志:
[2025/09/09 07:35:20.226 +08:00] [INFO] [coprocessor.go:1080] ["[TIME_COP_WAIT] resp_time:1m0.069574963s txnStartTS:460685170478415880 region_id:360338375 store_addr:10.120.33.148:20160 kv_process_ms:7 kv_wait_ms:0 kv_read_ms:3 processed_versions:224 total_versions:301 rocksdb_delete_skipped_count:19 rocksdb_key_skipped_count:878 rocksdb_cache_hit_count:120 rocksdb_read_count:0 rocksdb_read_byte:0"]
[2025/09/09 07:35:20.354 +08:00] [INFO] [coprocessor.go:1080] ["[TIME_COP_WAIT] resp_time:1m0.079600874s txnStartTS:460685170478415880 region_id:313686217 store_addr:10.120.33.148:20160 kv_process_ms:0 kv_wait_ms:0 kv_read_ms:0 processed_versions:0 total_versions:1 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:0 rocksdb_cache_hit_count:15 rocksdb_read_count:0 rocksdb_read_byte:0"]
[2025/09/09 07:36:20.439 +08:00] [INFO] [coprocessor.go:1080] ["[TIME_COP_WAIT] resp_time:1m0.082817939s txnStartTS:460685170478415880 region_id:313686217 store_addr:10.120.33.148:20160 kv_process_ms:0 kv_wait_ms:0 kv_read_ms:1 processed_versions:224 total_versions:225 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:448 rocksdb_cache_hit_count:15 rocksdb_read_count:0 rocksdb_read_byte:0"]
这几个 region 根据 id 查询发现都是 mysql db 下的表,具体有下面这些:
user
global_priv
db
tables_priv
columns_priv
GLOBAL_VARIABLES
tidb
help_topic
stats_meta
stats_buckets
gc_delete_range
gc_delete_range_done
stats_feedback
role_edges
default_roles
bind_info
stats_top_n
stats_histograms
由于 db 启动过程中在系统表上的 cop 报 TIME_COP_WAIT
,目前我怀疑是因为创建连接时用户相关的认证流程被这个卡住,导致创建连接超时,但时段内 kv 节点又没有什么报警,就只能又重启了所有 kv 节点,kv 节点重启后一分钟左右 db 节点也启动成功,各方面验证可以正常建立连接。
目前排查就直到这个程度,主要疑点就在 kv 在系统表的 cop 时长上,再看一下 db 无法启动时输出的日志:
[2025/09/09 07:36:20.439 +08:00] [INFO] [coprocessor.go:1080] ["[TIME_COP_WAIT] resp_time:1m0.082817939s txnStartTS:460685170478415880 region_id:313686217 store_addr:10.120.33.148:20160 kv_process_ms:0 kv_wait_ms:0 kv_read_ms:1 processed_versions:224 total_versions:225 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:448 rocksdb_cache_hit_count:15 rocksdb_read_count:0 rocksdb_read_byte:0"]
可以看到虽然 db 上层报 resp_time 有一分钟,但 kv 各项耗时指标都基本为零,反观一个正常的 cop 等待应该与下面这个类似:
[2025/09/09 08:14:23.656 +08:00] [INFO] [coprocessor.go:1080] ["[TIME_COP_WAIT] resp_time:304.795945ms txnStartTS:460685800475983930 region_id:323450017 store_addr:10.120.33.149:20160 kv_process_ms:0 kv_wait_ms:303 kv_read_ms:1 processed_versions:1 total_versions:1 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:0 rocksdb_cache_hit_count:11 rocksdb_read_count:0 rocksdb_read_byte:0"] [conn=3849783834006525241]
请问什么因素可能会导致这种情况?
图:问题时段(0350-0740) kv 出现大量未休眠 region
图:问题时段 kv raft store
图:raft propose,比较奇怪的是六台 kv 中有一台没有 read 负载,我们所有表都是三副本
图:db cop duration
图:kv unified read pool running task,这个也比较有疑点,正好是 raft propose 无负载的那个 kv 有很多 task
图:kv raft log lag
图:pd operator,发现同时间有大量 balance leader 产生且超时