一、问题提出
某测试环境, 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, t2
where t1.id = t2.id
and 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消失。
五、总结
本篇分析处理过程如下:
