正常执行计划的SQL突然变慢

[克里克里克 (Ti D Ber H052ej9m)]

一个好的问题描述有利于社区小伙伴更快帮你定位到问题，高效解决你的问题

【TiDB 使用环境】生产环境
【TiDB 版本】8.5.4
【部署方式】云上部署（什么云）/机器部署
【操作系统/CPU 架构/芯片详情】
【机器部署详情】CPU大小/内存大小/磁盘大小
【集群数据量】
【集群节点数】3台服务器各组件混布。
【问题复现路径】做过哪些操作出现的问题
【遇到的问题：问题现象及影响】
有选择性很好的二级索引查询变慢，慢SQL耗时都在rpc_info和tikv_wall_time，如何定位分析造成慢SQL的原因。
【资源配置】进入到 TiDB Dashboard -集群信息 (Cluster Info) -主机(Hosts) 截图此页面
【复制黏贴 ERROR 报错的日志】
【其他附件：截图/日志/监控】
具体执行计划：
| id | estRows | estCost | actRows | task | access object | execution info | | memory | disk |
| Projection_4 | 1.00 | 2012.39 | 1 | root | | time:948.2ms, loops:2, Concurrency:OFF |
| └─IndexLookUp_15 | 1.00 | 2005.80 | 1 | root | | time:948.2ms, loops:2, index_task: {total_time: 947.4ms, fetch_handle: 947.4ms, build: 635ns, wait: 2.51µs}, table_task: {total_time: 659µs, num: 1, concurrency: 5}, next: {wait_index: 947.5ms, wait_table_lookup_build: 44.5µs, wait_table_lookup_resp: 614.2µs} | | 51.3 KB | N/A |
| ├─IndexRangeScan_13(Build) | 1.00 | 222.87 | 1 | cop[tikv] | table:taba, index:idx_order_no(order_no) | time:947.4ms, loops:3, cop_task: {num: 1, max: 947.3ms, proc_keys: 1, tot_proc: 79.6µs, tot_wait: 28.6µs, copr_cache_hit_ratio: 0.00, build_task_duration: 14.8µs, max_distsql_concurrency: 1}, rpc_info:{Cop:{num_rpc:1, total_time:947.3ms}}, tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 1, total_process_keys_size: 168, total_keys: 2, get_snapshot_time: 9.48µs, rocksdb: {delete_skipped_count: 1, key_skipped_count: 2, block: {cache_hit_count: 8}}}, time_detail: {total_process_time: 79.6µs, total_wait_time: 28.6µs, tikv_wall_time: 518.2ms} | | N/A | N/A |
| └─TableRowIDScan_14(Probe) | 1.00 | 459.39 | 1 | cop[tikv] | table:taba | time:565µs, loops:2, cop_task: {num: 1, max: 531µs, proc_keys: 1, tot_proc: 99.1µs, tot_wait: 44.8µs, copr_cache_hit_ratio: 0.00, build_task_duration: 18.5µs, max_distsql_concurrency: 1, max_extra_concurrency: 1}, rpc_info:{Cop:{num_rpc:1, total_time:521.8µs}}, tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 1, total_process_keys_size: 729, total_keys: 1, get_snapshot_time: 12.6µs, rocksdb: {block: {cache_hit_count: 6}}}, time_detail: {total_process_time: 99.1µs, total_wait_time: 44.8µs, tikv_wall_time: 266.3µs} | | N/A | N/A |

最长等待时间实例主机的负载

[TiDBer_AHjy0eKV]

看下 网络延迟或丢包

[kang]

建议先检查TiKV节点的CPU和IO使用情况，特别是磁盘延迟和带宽。你提到rpc_info和tikv_wall_time高，大概率是TiKV处理慢。

可以试试：

1. 查看TiKV监控：Grafana中TiKV面板看gRPC duration、cop CPU、rocksdb block cache命中率。
2. 执行ADMIN SHOW SLOW RECENT N 10找出慢查询，看Cop_wait和Backoff时间。

[像风一样的男子]

执行时间里能看到是哪里慢吗？Coprocessor 累计执行耗时？

[克里克里克 (Ti D Ber H052ej9m)]

网络延迟没有很高，最高不到5ms，而且其他时间点的该慢SQLping延迟也在1.5ms以下。
系统整体负载都很低。

[克里克里克 (Ti D Ber H052ej9m)]

cop_task: {num: 1, max: 947.3ms, proc_keys: 1, tot_proc: 79.6µs, tot_wait: 28.6µs, copr_cache_hit_ratio: 0.00, build_task_duration: 14.8µs, max_distsql_concurrency: 1}, rpc_info:{Cop:{num_rpc:1, total_time:947.3ms}}, tikv_task:{time:0s, loops:1}, time_detail: {total_process_time: 79.6µs, total_wait_time: 28.6µs, tikv_wall_time: 518.2ms}
上面也贴出来了，就是在查找索引的这步耗时很高。

[a大力啊 (Ti D Ber O B5b6 R4 L)]

虚心学习，

[TiDBer_bawpguhQ]

先对比变慢前后执行计划与统计信息时间；查是否ANALYZE漂移、数据倾斜、coprocessor热点。绑定计划或强制索引作临时手段，根因仍看stats与Region热点。

[TIDB_逸昂 (Ti D Ber Gb7k B To0)]

[独善其身 (Ti D Ber Bi Rqfz5 K)]

是跨节点查询的代价变高了吧

[克里克里克 (Ti D Ber H052ej9m)]

有时候是点查也延时几百毫秒。当前集群的负载是很低的，目前观察的慢SQL里，每天都有几条执行时间是异常的，有的是点查，有的是选择性很好的索引的查询。
看异常时间段的Grafana各个监控指标都没有异常。

[WalterWj (王军 - PingCAP)]

社区问题 1057818（v8.5.4 慢 SQL IndexLookUp）根因结论

一、根因（一句话）

TiKV coprocessor 在 “tracker 之外” 的调度段（gRPC handler → unified-read-pool 排队 + parse_request + region cache 查询）累计 ~518ms，叠加 gRPC 往返 ~429ms；TiKV 自身计算/锁/snapshot/IO 都不是瓶颈。混部 3 台环境是放大器。

二、铁证三段 gap 拆解

IndexRangeScan_13 cop_task：

段	公式	耗时	性质
gap A（网络/gRPC 往返）	rpc_time − tikv_wall_time	429ms	TiDB ↔ TiKV 链路
gap B（TiKV tracker 之外）	tikv_wall_time − (proc+wait+snapshot)	518ms	调度/排队/parse_request
tracker 内部	tot_proc + tot_wait + get_snapshot	108µs	TiKV 真实处理

三、关键排除

• raftstore scheduler：coprocessor 不走 raftstore
• snapshot/read index：get_snapshot_time=9.48µs / wait_time=28.6µs 都是 µs 级
• 磁盘 IO：block_cache_hit_count=8 全命中，proc_keys=1
• 计算慢：tot_proc=79.6µs

四、源码层定位（@tidb源码解读 铁证）

tikv_wall_time 计时区间：kv.rs:1466 begin_instant → :1560-1607 handle_measures_for_batch_commands；tracker 在 endpoint.rs:622 才创建。gap B 必然落在这两段 tracker 之外：

• front：future_copr → Tracker::new（parse_request + region cache）
• back：tracker.on_finish_all_items → batch_commands measure（batch 组装 + gRPC 调度）

五、KB 先例

六、给社区的验证建议（按优先级）

1. TiKV-Details → Thread CPU → unified-read-pool CPU：是否打满
2. TiKV-Details → Time Used By Level：区分 busy vs wait（核心面板，不看 CPU usage）
3. TiKV-Details → gRPC message duration (Coprocessor) P99：gap A 验证
4. TiKV-Details → Unified Read Pool Wait Duration：gap B front 验证
5. TiDB-Details → Region Cache hit/refresh：是否频繁触发 PD RPC

七、临时缓解 + 长期建议

• 临时：调大 readpool.unified.max-thread-count；cgroup 隔离 TiKV CPU；检查网络
• 长期：解混部（TiKV 对 CPU/IO 延迟敏感）；启用 Resource Control（注意 #18939）；升级 v8.5.x 最新 patch

八、给社区的可直接回复段落

tikv_wall_time=518ms 但 total_process_time + total_wait_time ≈ 108µs，时间不在 TiKV 计算和锁。scan_detail 显示 block_cache_hit_count=8 全命中无 IO，get_snapshot_time=9.48µs 和 total_wait_time=28.6µs 都是 µs 级，排除 snapshot/read index/磁盘。源码上 tikv_wall_time 覆盖 begin_instant（gRPC handler 接收）到响应组装完成，而 tracker 只捕获到 unified-read-pool 内部处理段，所以 gap 必然在 tracker 之外——即 gRPC handler → unified-read-pool 的调度排队 + parse_request/region cache 查询，以及 batch_commands 响应组装。混部环境下最大嫌疑是 unified-read-pool CPU 争抢 + gRPC batch 调度。建议看 TiKV-Details 的 Thread CPU（unified-read-pool） 和 Time Used By Level 面板，必要时调大 readpool.unified.max-thread-count 或解混部。

---

@ticket-Walterwj 根因分析结构完整（gap 三段拆解 + 五候选排除 + 验证/缓解/长期），@wiki_ticket KB 反查扎实，@tidb源码解读 源码边界铁证。三方交叉印证一致。

[克里克里克 (Ti D Ber H052ej9m)]

@WalterWj

gap A（网络/gRPC 往返）

ping 有个瞬间的5ms的延时，但似乎其他偶尔异常的SQL并不是都能看到ping延迟；

六、给社区的验证建议（按优先级）

这几个指标都没达到瓶颈，普遍都在15%以下。

[WalterWj (王军 - PingCAP)]

如果服务器的 cpu 内存、io 用的不高。
网络带宽也没有到瓶颈。
那么监控 ping 5ms 算高得了。因为默认 blackbox 的 ping 是一个很小的请求，并且会被 15s 弱化掉。

tidb 读取 跨网络的，网络影响还是比较大的。

[克里克里克 (Ti D Ber H052ej9m)]

好的，感谢。我再观察吧。