通过 SLOW_QUERY 表快速确认 慢语句

🌌 运维指南 TiDB 运维手册
1

背景

我们在日常 TiDB 运维中，经常会遇到因为一些慢 SQL 将整个 TiDB 集群拖慢，甚至打挂的情况。生产环境如战场，SLA 就是 DBA 的
K(m)P(o)I(ney)
临时写 SQL 检查肯定是来不及的。根据我在日常使用 TiDB ，解决线上问题时候会使用到的一些排查 SQL，在这里分享下。希望对广大 DBA 有所帮助。

注意事项

重要的事情说 3 遍都不够！

  • 一定限制 time 的范围 ！！！！！
  • 一定限制 time 的范围 ！！！！！！！！
  • 一定限制 time 的范围 ！！！！！！！！！！！

SQL

-- 查询当前 TiDB Instance SLOW Log ,适用于 TiDB v3.0.x-v4.0.x
SET sql_mode = '';
SET @mintime = '2020-11-01';
SET @maxtime = '2020-11-02';

SELECT
	digest,
	plan_digest,
	sum( Query_time ) AS 'query_responces',
	avg( Query_time ) AS 'avg_query_resp',
	count( 1 ) cnt,
	count( CASE WHEN Backoff_types > '' THEN 1 END ) AS 'Backoff_query_cnt',
	count( CASE WHEN Backoff_types > '' THEN 1 END )/ count( 1 ) * 100 AS 'Backoff_query_pct',
	avg( process_keys ) AS 'avg_process_keys',
	avg( total_keys ) AS 'avg_total_keys',
	sum( process_keys )/ sum( total_keys )*100 AS 'process_key_pct',
    sum( Wait_time) as 'Wait_time',
    sum( Wait_time) / sum( Query_time )*100 as 'wait_time_pct',
	count( CASE succ WHEN 1 THEN succ END ) AS 'succ_cnt',
	count( CASE succ WHEN 1 THEN succ END )/ count( 1 ) * 100 AS 'succ_pct',
	sum( Mem_max )/ 1024 / 1024 AS 'sum_mem(MB)',
	avg( Mem_max )/ 1024 / 1024 AS 'avg_mem(MB)',
	-- sum( disk_max )/ 1024 / 1024 AS 'sum_disk(MB)',
	-- avg( disk_max )/ 1024 / 1024 AS 'avg_disk(MB)',
	min(
	from_unixtime(( Txn_start_ts >> 18 )/ 1000 )) AS 'min_txn_start_time',
	max(time) AS 'max_time',
	LEFT ( CASE WHEN length( Prev_stmt )> 0 THEN Prev_stmt ELSE QUERY END, 256 ) AS 'query' 
FROM
	information_schema.SLOW_QUERY
	JOIN (
	SELECT
		digest AS dg,
		min( CASE WHEN Txn_start_ts > 0 THEN from_unixtime(( Txn_start_ts >> 18 )/ 1000 ) ELSE time END ) mintime,
		max( time ) maxtime 
	FROM
		information_schema.SLOW_QUERY 
	WHERE
		Is_internal = 0 
		AND time >= @mintime 
		AND time < @maxtime 
	GROUP BY
		Digest 
	) o ON o.dg = digest 
	AND time BETWEEN mintime 
	AND maxtime 
GROUP BY
	digest,
	Plan_digest 
ORDER BY
	query_responces DESC 
	LIMIT 50;

由于 TiDB slowlog 实现是解析 slowlog file，不指定时间范围可能造成查不到想要的信息，同时也是对各各 TiDB 节点的一种资源保护。所以需要特别注意

-- 查询当前集群所有 TiDB 集群的 Slowlog, 适用于 TiDB v4.0.x
SET sql_mode = '';
SET @mintime = '2020-11-01 20:00:00';
SET @maxtime = '2020-11-01 20:30:00';

SELECT
	digest,
	plan_digest,
	sum( Query_time ) AS 'query_responces',
	avg( Query_time ) AS 'avg_query_resp',
	count( 1 ) cnt,
	count( CASE WHEN Backoff_types > '' THEN 1 END ) AS 'Backoff_query_cnt',
	count( CASE WHEN Backoff_types > '' THEN 1 END )/ count( 1 ) * 100 AS 'Backoff_query_pct',
	avg( process_keys ) AS 'avg_process_keys',
	avg( total_keys ) AS 'avg_total_keys',
	sum( process_keys )/ sum( total_keys )* 100 AS 'process_key_pct',
    sum( Wait_time) as 'Wait_time',
    sum( Wait_time) / sum( Query_time )*100 as 'wait_time_pct',
	count( CASE succ WHEN 1 THEN succ END ) AS 'succ_cnt',
	count( CASE succ WHEN 1 THEN succ END )/ count( 1 ) * 100 AS 'succ_pct',
	sum( Mem_max )/ 1024 / 1024 AS 'sum_mem(MB)',
	avg( Mem_max )/ 1024 / 1024 AS 'avg_mem(MB)',
	sum( disk_max )/ 1024 / 1024 AS 'sum_disk(MB)',
	avg( disk_max )/ 1024 / 1024 AS 'avg_disk(MB)',
	min(
	from_unixtime(( Txn_start_ts >> 18 )/ 1000 )) AS 'min_time',
	max( time ) AS 'max_time',
	group_concat( DISTINCT INSTANCE ) AS 'INSTANCE',
	LEFT ( CASE WHEN length( Prev_stmt )> 0 THEN Prev_stmt ELSE QUERY END, 256 ) AS 'query' 
FROM
	information_schema.CLUSTER_SLOW_QUERY
	JOIN (
	SELECT
		digest AS dg,
		min( CASE WHEN Txn_start_ts > 0 THEN from_unixtime(( Txn_start_ts >> 18 )/ 1000 ) ELSE time END ) mintime,
		max( time ) maxtime 
	FROM
		information_schema.CLUSTER_SLOW_QUERY 
	WHERE
		Is_internal = 0 
		AND time >= @mintime 
		AND time < @maxtime 
	GROUP BY
		Digest 
	) o ON o.dg = digest 
	AND time BETWEEN mintime 
	AND maxtime 
GROUP BY
	digest,
	Plan_digest 
ORDER BY
	query_responces DESC 
	LIMIT 50;

#重点语句排查思路

  • query_responces 排名靠前，avg_total_keys 超过 10000 以上的 SQL ；
    说明这是一条大 SQL
  • query_responces 排名靠前，cnt 出现次数排名靠前，但avg_total_keys并不一定很多的 SQL；
    说明这条 SQL 可能存在非常高的并发，需要进一步排查是否与其他 SQL 的query 耗时标准差非常大

查询结果解析

  • digest: SQL 指纹，用于识别 SQL 语句是否属于同一类
  • plan_digest：执行计划指纹，用于判断执行计划是否属于同一类
  • query_responces：SLOW LOG 中 SQL的总耗时
  • avg_query_resp：SLOW LOG 中 SQL的平均耗时
  • cnt：SLOW LOG 中 SQL被记录次数
  • Backoff_query_cnt：SQL 出现 异常重试的总次数
  • Backoff_query_pct：出现异常重试 SQL ，在总次数中的 占比
    如果此重试占比很高，需要具体排查 相关 Backoff type 所对应的含义。
    更新语句经常出现Backoff 类型有 NotFound，txnLock代表有锁竞争，建议在悲观锁模式下使用显示事物
  • avg_process_keys：平均 Coprocessor 处理的 key 的数量。
  • avg_total_keys：平均 Coprocessor 扫过的 key 的数量，如果此数量很高说明是个大 SQL，我一般会对超过 1000 的 SQL 加以关注
  • process_key_pct：processkey 在 totalkeys 中的占比，相比 total_keys，processed_keys 不包含 MVCC 的旧版本。如果 processed_keys 和 total_keys 相差很大，说明旧版本比较多。如果占比在 70% 以下会特别关注下。并且排查下 TiDB 的 GC Lift Time；
  • wait_time: 表示 SQL 在 TiKV 的等待时间之和
  • wait_time_pct: SQL 的 TiKV 等待时间在整个语句耗时的占比。一般等待时间超过 20%会特别关注；如果这条 SQL 的 total_key 很少，很有可能是因为其他语句占用了 TiKV 资源导致这条语句延迟增加，这时候需要将重点切换到那些 真正的 大 SQL 上
  • succ_cnt：语句是否执行成功次数
  • succ_pct：语句是否执行成功次数占比，如果占比低于 90%需要特别关注下
  • sum_mem(MB)：SQL 在 TiDB 使用内存的汇总
  • avg_mem(MB)：SQL 在 TiDB 内存使用的平均值
  • sum_disk(MB)：SQL 在 TiDB 使用磁盘空间的汇总 （仅 v4.0 适用）
  • avg_disk(MB)：SQL 在 TiDB 使用磁盘空间的平均值（仅 v4.0 适用）
  • min_time：SQL在统计时间段的最早开始的时间；
  • max_time：SQL在统计时间段的最终结束的时间；
  • INSTANCE：TiDB 实例的枚举（仅 v4.0 适用）
  • query：具体 SQL 语句

查询语句解析

由于 Slow log 中 的 time 记录的是日志记录时间，我们可以将其理解为 SQL 执行结束的时间。但是好在日志中还记录了 Txn_start_ts，Ta 代表事物的开始时间。多数情况下可以将其理解为 SQL 的开始时间。当然也可以用 记录中 Time 减去 query_time 的秒数获得最精准的语句开始时间。
所以整个查询会将具体的统计时间范围圈定在 语句最早的 事物开始时间到最终的 slowlog 打印时间

结束语

这篇文档纯粹是个人见解，欢迎其他老师拍砖指正。也希望有其他好想法的同学将自己的见解分享出来。让工作变动简单高效

7 个赞
4

苏老师，赞

5

补充一下， 如果 查询 (CLUSTER_)SLOW_QUERY 没有限制 time 的范围，则只会解析当前 TiDB 进程正在写的 慢日志 文件，并不会解析所有的慢日志文件，由于默认慢日志文件满 300M 后会 rotate, 所以如果在刚发生慢日志文件 rotate 后，不限制 time 查询 (CLUSTER_)SLOW_QUERY ，返回结果就是空。

1 个赞
6

:+1: