简单SQL，在压测情况下，性能不稳定，但慢日志信息判断并不慢

[Hacker_Rc5f1tYG]

为提高效率，请提供以下信息，问题描述清晰能够更快得到解决：

【TiDB 版本】
4.0.10

【问题描述】
背景：1. 业务压测
2. 慢语句阀值是100ms
3.system_config_id 和owner_id 有联合组合索引
4. system_config_item 为配置表，大概2k数据

语句:

select * from system_config_item where system_config_id = ? and owner_id = ?

现象：偶尔会出现执行超过100ms的慢语句

捕获数据:

正常情况：

异常情况(超过100ms)：

慢语句执行计划(耗时0.104268595s):

id            	task     	estRows	operator info                                                                                                                                                                                                                                                         	actRows	execution info                                                                                                                                                  	memory   	disk
	IndexLookUp_10	root     	0      	                                                                                                                                                                                                                                                                      	0      	time:38.767685ms, loops:1,  table_task:{num:0, concurrency:4, time:130.383475ms}                                                                                	355 Bytes	N/A
	├─IndexScan_8 	cop[tikv]	0      	table:system_config_item, index:idx_system_config_item_sysconid_oid(system_config_id, owner_id), range:["46952b5516374a8b914d208399124871" "8e86801e12f4464ba1d8322c71e067af","46952b5516374a8b914d208399124871" "8e86801e12f4464ba1d8322c71e067af"], keep order:false	0      	time:0s, loops:0, cop_task: {num: 1, max:26.896672ms, proc_keys: 0, rpc_num: 1, rpc_time: 26.891244ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:0s, loops:1}	N/A      	N/A
	└─TableScan_9 	cop[tikv]	0      	table:system_config_item, keep order:false                                                                                                                                                                                                                            	0      	time:0ns, loops:0                                                                                                                                               	N/A      	N/A

分析:

1. 从慢日志信息获知改语句执行39ms 左右，但实际该语句执行了104ms.

---

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

[yilong (yi888long)]

抱歉，我不是很明白，怎么看出来，慢日志和实际记录不一样的？麻烦展示下具体内容，比如慢日志中记录了39ms？ 你的客户端反馈是104ms？

[Hacker_Rc5f1tYG]

104ms 是慢日志记录的。
39ms 是我看执行计划得出，如下。

[yilong (yi888long)]

1. 请问对应的是同一时间的同一个sql吗？ 方便上传下对应的慢日志吗？
2. 执行计划是哪里记录的？ 麻烦也帮忙上传下，多谢。
3. 比如 dashboard 记录了 慢sql，您从哪里看的对应的执行计划？
4. 如果不是同一个时间点的sql，即时执行的重复sql，不同时间对应的执行时间也可能是不一样的。
   
   

[Hacker_Rc5f1tYG]

@yilong

• 请问对应的是同一时间的同一个sql吗？ 方便上传下对应的慢日志吗？
• 执行计划是哪里记录的？ 麻烦也帮忙上传下，多谢。
• 比如 dashboard 记录了 慢sql，您从哪里看的对应的执行计划？
• 如果不是同一个时间点的sql，即时执行的重复sql，不同时间对应的执行时间也可能是不一样的。

1. 是同一条SQL语句， 但参数会不一样
2. 执行计划
   
   

id            	task     	estRows	operator info                                                                                                                                                                                                                                                         	actRows	execution info                                                                                                                                                  	memory   	disk
	IndexLookUp_10	root     	0      	                                                                                                                                                                                                                                                                      	0      	time:38.767685ms, loops:1,  table_task:{num:0, concurrency:4, time:130.383475ms}                                                                                	355 Bytes	N/A
	├─IndexScan_8 	cop[tikv]	0      	table:system_config_item, index:idx_system_config_item_sysconid_oid(system_config_id, owner_id), range:["46952b5516374a8b914d208399124871" "8e86801e12f4464ba1d8322c71e067af","46952b5516374a8b914d208399124871" "8e86801e12f4464ba1d8322c71e067af"], keep order:false	0      	time:0s, loops:0, cop_task: {num: 1, max:26.896672ms, proc_keys: 0, rpc_num: 1, rpc_time: 26.891244ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:0s, loops:1}	N/A      	N/A
	└─TableScan_9 	cop[tikv]	0      	table:system_config_item, keep order:false                                                                                                                                                                                                                            	0      	time:0ns, loops:0                                                                                                                                               	N/A      	N/A

3. 慢日志，我们直接从 information_schema.cluster_slow_log 获取的。
4. 成为慢日志的语句执行计划都一样的。 information_schema.cluster_slow_log 有对应的执行计划指纹

[yilong (yi888long)]

慢日志的 query time 包含客户端等待以及发送数据等之类的时间，并不完全是执行时间。

[Hacker_Rc5f1tYG]

@yilong

query time

query time 的组成部分是?

[yilong (yi888long)]

1. 详细的信息可能需要查看代码来确认。可以到 github 提问下，麻烦了。
2. 目前根据您的情况，可以多查看几个慢日志，是否都是这种情况。如果是的话，看下从业务侧压测机器到tidb-server有哪些达到了瓶颈？ 比如 压测服务器资源满，或者tidb-server压测资源满，如果都不是，可以关注下压测机器到tidb-server的网络情况。