[v4.0.10]执行计划中关于rpc_time的问题

[xiexin (荒岛)]

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

【概述】 场景 + 问题概述
相同的sql，并且force index，问题期间从执行计划的算子信息中查看是rpc_time比正常期间更长，这个值的含义从官网有看到，但是不清楚具体原因是什么。
问题期间服务器无压力，cpu load在2.39%左右、io使用率在10%以内，内存256G
tikv节点无pending，恢复正常前无analyze table，表健康度91。

【背景】 做过哪些操作
无任何操作

【现象】 业务和数据库现象
问题期间该条sql慢查较多

【问题】 当前遇到的问题
相同的执行计划，问题期间limit算子中的rpc_time比正常时间高200ms左右

【TiDB 版本】
v4.0.10

【附件】 相关日志及配置信息
sql如下：

SELECT id, videocid, videoaid, cmtid, userid, state, dmctime, utime, last_push_time, last_push_state, current_push_status, last_hit_strategy, validate, mtime, ctime FROM table_xx force index(ix_current_push_status_utime) WHERE (current_push_status = 0 AND utime <= 1640335762) AND utime >= 1640332252 LIMIT 2000;

表结构如下：

 CREATE TABLE `table_xx` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `videocid` bigint(20) unsigned NOT NULL DEFAULT '0'',
  `cmtid` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `userid` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `state` int(11) NOT NULL DEFAULT '0',
  `dmctime` int(11) NOT NULL DEFAULT '0',
  `utime` int(11) NOT NULL DEFAULT '0',
  `last_push_time` int(11) NOT NULL DEFAULT '0' ,
  `last_push_state` int(11) NOT NULL DEFAULT '0',
  `current_push_status` tinyint(4) NOT NULL DEFAULT '0' ,
  `last_hit_strategy` varchar(20) NOT NULL DEFAULT '' ,
  `validate` int(11) NOT NULL DEFAULT '0',
  `mtime` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP ,
  `ctime` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP,
  `videoaid` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  PRIMARY KEY (`id`),
  UNIQUE KEY `ix_cmtid` (`cmtid`),
  KEY `ix_current_push_status_last_push_time` (`current_push_status`,`last_push_time`),
  KEY `ix_dmctime` (`dmctime`),
  KEY `ix_ctime` (`ctime`),
  KEY `ix_mtime` (`mtime`),
  KEY `ix_utime` (`utime`),
  KEY `ix_aid` (`videoaid`),
  KEY `ix_current_push_status_utime` (`current_push_status`,`utime`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin AUTO_INCREMENT=730415744 

正常期间执行计划：

+----------------------------------+---------+---------+-----------+-----------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+------+
| id                               | estRows | actRows | task      | access object                                                               | execution info                                                                                                                                                        | operator info                                                                                                                                                                                                                                                                                                                                                                                                                                                                            | memory       | disk |
+----------------------------------+---------+---------+-----------+-----------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+------+
| Projection_7                     | 77.71   | 0       | root      |                                                                             | time:38.881407ms, loops:1, Concurrency:OFF                                                                                                                            | DBxx.tablexx.id, DBxx.tablexx.videocid, DBxx.tablexx.videoaid, DBxx.tablexx.cmtid, DBxx.tablexx.userid, DBxx.tablexx.state, DBxx.tablexx.dmctime, DBxx.tablexx.utime, DBxx.tablexx.last_push_time, DBxx.tablexx.last_push_state, DBxx.tablexx.current_push_status, DBxx.tablexx.last_hit_strategy, DBxx.tablexx.validate, DBxx.tablexx.mtime, DBxx.tablexx.ctime | 5.5703125 KB | N/A  |
| └─IndexLookUp_14                 | 77.71   | 0       | root      |                                                                             | time:38.878846ms, loops:1,  table_task:{num:0, concurrency:4, time:155.34822ms}                                                                                       | limit embedded(offset:0, count:2000)                                                                                                                                                                                                                                                                                                                                                                                                                                                     | 235 Bytes    | N/A  |
|   ├─Limit_13(Build)              | 77.71   | 0       | cop[tikv] |                                                                             | time:0s, loops:0, cop_task: {num: 1, max:38.73929ms, proc_keys: 50678, rpc_num: 1, rpc_time: 38.723702ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:36ms, loops:1} | offset:0, count:2000                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | N/A          | N/A  |
|   │ └─IndexRangeScan_11          | 77.71   | 0       | cop[tikv] | table:tablexx, index:ix_current_push_status_utime(current_push_status, utime) | time:0ns, loops:0, tikv_task:{time:36ms, loops:1}                                                                                                                     | range:[0 1640332252,0 1640335762], keep order:false                                                                                                                                                                                                                                                                                                                                                                                                                                      | N/A          | N/A  |
|   └─TableRowIDScan_12(Probe)     | 77.71   | 0       | cop[tikv] | table:tablexx                                                                 | time:0ns, loops:0                                                                                                                                                     | keep order:false, stats:pseudo                                                                                                                                                                                                                                                                                                                                                                                                                                                           | N/A          | N/A  |
+----------------------------------+---------+---------+-----------+-----------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+------+
5 rows in set (0.04 sec)

问题期间执行计划：

|| |id                |task     |estRows          |operator info                                                                                                                                                                                                                                                                                                                                                                                                                                                                           |actRows|execution info                                                                                                                                                          |memory      |disk|
|---|---|---|---|---|---|---|---|---|
||Projection_7      |root     |77.62712324719992|DBxx.tablexx.id, DBxx.tablexx.videocid, DBxx.tablexx.videoaid, DBxx.tablexx.cmtid, DBxx.tablexx.userid, DBxx.tablexx.state, DBxx.tablexx.dmctime, DBxx.tablexx.utime, DBxx.tablexx.last_push_time, DBxx.tablexx.last_push_state, DBxx.tablexx.current_push_status, DBxx.tablexx.last_hit_strategy, DBxx.tablexx.validate, DBxx.tablexx.mtime, DBxx.tablexx.ctime|0      |time:182.72606ms, loops:1, Concurrency:OFF                                                                                                                              |5.5703125 KB|N/A|
||└─IndexLookUp_14  |root     |77.62712324719992|limit embedded(offset:0, count:2000)                                                                                                                                                                                                                                                                                                                                                                                                                                                    |0      |time:182.723766ms, loops:1,  table_task:{num:0, concurrency:4, time:730.762083ms}                                                                                       |235 Bytes   |N/A|
||  ├─Limit_13      |cop[tikv]|77.62712324719992|offset:0, count:2000                                                                                                                                                                                                                                                                                                                                                                                                                                                                    |0      |time:0s, loops:0, cop_task: {num: 1, max:182.618097ms, proc_keys: 50678, rpc_num: 1, rpc_time: 182.606906ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:64ms, loops:1}|N/A         |N/A|
||  │ └─IndexScan_11|cop[tikv]|77.62712324719992|table:tablexx, index:ix_current_push_status_utime(current_push_status, utime), range:[0 1640332252,0 1640335762], keep order:false                                                                                                                                                                                                                                                                                                                                                        |0      |time:0ns, loops:0, tikv_task:{time:64ms, loops:1}                                                                                                                       |N/A         |N/A|
||  └─TableScan_12  |cop[tikv]|77.62712324719992|table:tablexx, keep order:false, stats:pseudo                                                                                                                                                                                                                                                                                                                                                                                                                                             |0      |time:0ns, loops:0                                                                                                                                                       |N/A         |N/A ||

两个执行计划不同的地方：
有问题：cop_task: {num: 1, max:182.618097ms, proc_keys: 50678, rpc_num: 1, rpc_time: 182.606906ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:64ms, loops:1}

正常：cop_task: {num: 1, max:38.73929ms, proc_keys: 50678, rpc_num: 1, rpc_time: 38.723702ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:36ms, loops:1}

---

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

[Meditator (Wendywong020)]

• rpc_num , rpc_time ：向 TiKV 发送 Cop 类型的 RPC 请求总数量和总时间。

可以在grafana上看看grpc的cpu负载情况，另外要看看tikv所在主机的负载情况。

[Kongdom]

我这边一般出现stats:pseudo，就代表需要重新收集统计信息

operator info 结果

EXPLAIN 返回结果中 operator info 列可显示诸如条件下推等信息。本文以上示例中， operator info 结果各字段解释如下：

• range: [1,1] 表示查询的 WHERE 字句 ( a = 1 ) 被下推到了 TiKV，对应的 task 为 cop[tikv] 。
• keep order:false 表示该查询的语义不需要 TiKV 按顺序返回结果。如果查询指定了排序（例如 SELECT * FROM t WHERE a = 1 ORDER BY id ），该字段的返回结果为 keep order:true 。
• stats:pseudo 表示 estRows 显示的预估数可能不准确。TiDB 定期在后台更新统计信息。也可以通过执行 ANALYZE TABLE t 来手动更新统计信息。

[xiexin (荒岛)]

grpc poll cpu这个值么？问题期间不到10%，大概在6-7%之间
集群的拓扑是3tikv、3tidb、3pd，部署在3台物理机（64C256G）上，问题期间cpu、io、内存使用率如下：
服务器1：单核load avg0.04、磁盘io使用率3%以内（iops 2k左右无明显波动、bandwidth write 13.7MBs左右，问题期间有1min30s波动到34.31MBs，read 几十kBs）、内存：use117G、available134G、network inbound 12-16Mbps、outbound15Mbps以内
服务器2：单核load avg0.04、磁盘io使用率7%以内（iops 2k左右无明显波动、bandwidth write 40MBs左右，read 几十kBs-13MBs）、内存：use115G、available136G、network inbound 10Mbps以内、outbound15Mbps以内
服务器3：单核load avg0.05、磁盘io使用率3%以内（iops 2k左右无明显波动、bandwidth write 20MBs以内，read 几MBs）、内存：use113G、available137G、network inbound 10Mbps以内、outbound15Mbps以内

[h5n1]

看下问题期间tikv的系统负载情况

[xiexin (荒岛)]

服务器级别的一些监控信息上面发了，大佬看看还需要哪些内容

[这道题我不会 (Lizhengyang@PingCAP)]

@xiexin

min30s波动到34.31MBs

整体 grpc poll cpu 可能看不出来问题，需要看下 gRPC CPU Per Thread ，是不是里面单个线程打满了；
或者在 tikv-details → grpc 监控面板中，可以把 duration 调成 999 线，看看 grpc message duration 正常时间点和问题时间点的差异。

[xiexin (荒岛)]

tikv-details -> grpc 下有6个面板
1.gRPC message count——问题期间并无高峰
2.gRPC message failed 无数据
3.99% gRPC message duration——coprocessor问题期间250ms左右（问题时间之前也是这个耗时），其余项无明显波动
4.Average gRPC message duration——coprocessor略有上升（5ms上升25ms左右，16:36左右该sql恢复正常，这个耗时17:10才恢复5ms左右）
5.gRPC batch size——无明显波动
6.raft message batch size——avg无明显波动，99%问题期间略有下降（7下降到5）

Thread CPU下无gRPC CPU Per Thread面板，关于gRPC的只有gRPC poll CPU

[xiexin (荒岛)]

问题期间前后，该表的统计信息都没有更新过，而且表统计信息健康度在90以上，前后的执行计划来看是一致的，感觉跟统计信息没太大关系

[h5n1]

https://docs.pingcap.com/zh/tidb/v5.2/exporting-grafana-snapshots/#将-grafana-监控数据导出成快照

[xiexin (荒岛)]

不一定导的出监控数据，之前试过
我导出一波看看

[这道题我不会 (Lizhengyang@PingCAP)]

1.可以把监控 「99% gRPC message duration」调整 999 线看下，调整下监控表达式：

2.grpc poll cpu 也可以调整下监控指标的表达式，添加下 by name：

3.可以按照楼上的建议导出下监控数据瞅瞅~

[xiexin (荒岛)]

全量的监控导不出，我就导了gRPC以及Thread CPU面板的相关数据
TiDB4.0-Cluster-TiKV-Details_2021-12-27T08_49_21.912Z.json (2.1 MB)

[h5n1]

问题时间段是什么时候开始的？平时unifired read pool也是这么不均衡吗？ 16:10分前有比较多的读写操作。

[xiexin (荒岛)]

15:11-16:10,16:22-16:36左右，这两个时间点
平时unifired read pool CPU波动也是比较高的，下图是last 24 hours

[这道题我不会 (Lizhengyang@PingCAP)]

如果方便的话，可以把监控项 「99% gRPC message duration」和 「grpc poll cpu 」表达式调整后的结果反馈下 ，看下是不是存在单线程的瓶颈。

[xiexin (荒岛)]

1.[99% gRPC message duration]调整 999 线后面板如下

2.[grpc poll cpu]调整下控指标的表达式，添加by name 后面板如下

[这道题我不会 (Lizhengyang@PingCAP)]

从 tikv cop 监控中看到，慢的主要是 index scan 相关请求（table scan 请求耗时最长 ～30ms），从 index scan 请求相关的 rocksdb 操作看到读 write cf 时遇到 tombstone 比较多:

猜测是写入量太少无法触发 compaction 所以 tombstone 数据无法及时清理导致的，可以试试使用 tikv-ctl 手动 compact write cf

[疾风之狼]