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

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

【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.

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

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

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

image

  1. 请问对应的是同一时间的同一个sql吗? 方便上传下对应的慢日志吗?
  2. 执行计划是哪里记录的? 麻烦也帮忙上传下,多谢。
  3. 比如 dashboard 记录了 慢sql,您从哪里看的对应的执行计划?
  4. 如果不是同一个时间点的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
  1. 慢日志,我们直接从 information_schema.cluster_slow_log 获取的。
  2. 成为慢日志的语句执行计划都一样的。 information_schema.cluster_slow_log 有对应的执行计划指纹

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

query time 的组成部分是?

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