一个慢查询的基本分析

作者： chenbo 原文来源：https://tidb.net/blog/f75b9b28

一、问题提出

某测试环境, sql 普遍跑得慢。

随便查看一条 sql 执行计划 exec info 中 tikv_task:{proc max:12.5s}, 扫表一次 TableRowIDScan 最大能达到 12 秒, 是不是 tikv 有什么问题？

二、用 grafana 查看 tikv 状态

查看 TiKV-Details 面板下 Thread CPU 目录中的 [Unified read pool CPU] 图形, 发现某些 tikv cpu 已远超 800% 这个警戒线, 并且忙的 tikv 是交替变换的。

记下忙的 tikv 实例, 比如 08:50 附近 113-tikv 很忙。

下面要查看 113 主机都在跑什么 sql。

三、用 dashboard 定位 sql

3.1 [ Top SQL ] 面板

使用 dashboard 的[Top SQL]面板来查看 tikv 113 主机在 08:50 时，都在运行什么 sql 语句。

从上面查看 sql 的执行频率和具体信息, 第一条 sql 用时很多, 且每秒 0.7 次, 频率高。

不过要注意, 这里看到的执行计划有两个地方不准确, 后面会说明。

3.2 [ SQL 语句分析 ] 面板

这个面板是按 sql 的总用时排序的, 有几个特点:

• 查看最近半小时高耗时的 sql, 比较准确 ;

• 可以关注计划数大于 1 的 sql;

下图中第二行的 select 就是上节的 top sql, 平均耗时 45 秒, 且有两个计划。

点击进去看 sql 计划详情，两个执行计划的性能差异很大

sql 类似于

select t1.*, t2.*from t1, t2where t1.id = t2.idand t1.cust_id='xxx'and t2.state='01'

理论上, 应该是 T1 IndexJoin T2 才是好的计划, 而 T2 IndexJoin T1 是坏的计划。

这里看到的执行计划信息是准确的。

而上一节中[top sql]中显示的计划，有两个地方不准确:

• 只显示了其中一个计划 [d23969...], 没有显示另一个[72b6c4...];

• plan-id 与执行 plan 对不上, [d23969...]是差的 plan-id, 显示的却是好的 plan;

四、用 explain 命令查看 sql 计划

实际执行一下 sql, 分析各个环节的信息。

下面是差的计划, T2 全表扫描后去 T1 中查询。

从 plan 中得到以下信息:

• T2 统计信息不准, 估计 3 条, 实际 28 万条, 查看 T2 的 healthy 为 0;

• 关联 T1 后根据 cust_id 过滤, 结果为 0, 也就是 cust_id 有很好的过滤性 ;

• tikv_task max:25.8s, 说明 tikv 的请求非常缓慢 ;

收集 T2 表的统计信息后, 查看执行 plan 的变化。

从 plan 中得到以下信息:

• T1 根据 cust_id 过滤出来的 0 条, 用时只有 1.5ms, 整体 3ms

• 由于 T1 为 0, 不再查找 T2

当系统开始使用正确的 plan 后，tikv 主机的资源也随着恢复正常, 慢 sql 消失。

五、总结

本篇分析处理过程如下: