慢查询日志中,发现一条 sql 每次执行时间都不理想,而且这条 SQL 在业务上是非常频繁调用(需要实时查库不能做redis缓存)的。于是着手对这条慢 sql 进行优化。
原 SQL 如下:
SELECT rtt.topic_id FROM rel_topic_theme rtt INNER JOIN topic t ON (rtt.topic_id = t.id) WHERE rtt.topic_theme_id = 119988 AND t.is_delete = 0 AND review_status >= 0 ORDER BY t.publish_time DESC, t.id DESC limit 0, 10;
两个表都处于 30 ~ 100w 记录数级别;一个热门 rtt.topic_theme_id = xxxx 记录数为几千级别。这个 SQL 本意是通过 theme_id 查询关联的 topic_id 同时根据 topic 的一些筛选条件过滤,并根据时间新旧降序排序。
看了下这个 SQL 的业务含义,在当前的表结构下,这句 SQL 的 INNER JOIN 部分 以及 WHERE 部分都没法再做优化了,增加冗余字段可以改成只查单表,但是冗余字段的更新是个大问题。
那就还是先着手于这条 SQL 本身进行效率上的深度分析,先 explain 看一下。
explain SELECT rtt.topic_id FROM rel_topic_theme rtt INNER JOIN topic t ON (rtt.topic_id = t.id) WHERE rtt.topic_theme_id = 159988 AND t.is_delete = 0 AND review_status >= 0 ORDER BY t.publish_time DESC, t.id DESC limit 0, 10;
+-------+------------+--------+-------------------------------------------+------------------------+---------+------------------+-------+----------+----------------------------------------------+
| table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+-------+------------+--------+-------------------------------------------+------------------------+---------+------------------+-------+----------+----------------------------------------------+
| rtt | NULL | ref | unique_rel_topic_theme,index_rel_topic_id | unique_rel_topic_theme | 4 | const | 29018 | 100.00 | Using index; Using temporary; Using filesort |
| t | NULL | eq_ref | PRIMARY,idx_id_review_delete | PRIMARY | 4 | avg.rtt.topic_id | 1 | 5.00 | Using where |
+-------+------------+--------+-------------------------------------------+------------------------+---------+------------------+-------+----------+----------------------------------------------+
2 rows in set, 1 warning (0.01 sec)
发现 Extra 信息中,有 Using temporary 和 Using filesort 信息,因为有 order by,所以 Using filesort 不足为奇,但关键在于 Using temporary – 使用了临时表。order by 并非一定需要触发临时表,问题出在关联表查询时 order by 字段的选取,这个呆会在对比来讲,先来看看 SQL 的 Query Profiler :
先看 MySQL 的 profiling 有没有启用,如果没有启用就打开开关:
-- 查看 profiling 开关,0表示未开启,1表示已开启
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 |
+-------------+
1 row in set, 1 warning (0.00 sec)
-- 开启Query Profiler分析功能
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
再跑下 select 语句,然后 show profiles;
看一下
-- 详细对比下执行计划和各阶段执行时间
mysql> show profiles
-> ;
+----------+------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 1 | 0.04972775 | SELECT rtt.topic_id FROM rel_topic_theme rtt INNER JOIN topic t ON (rtt.topic_id = t.id) WHERE rtt.topic_theme_id = 159988 AND t.is_delete = 0 AND review_status >= 0 ORDER BY t.publish_time DESC, t.id DESC limit 0, 10 |
| 2 | 0.00592800 | SELECT rtt.topic_id FROM rel_topic_theme rtt INNER JOIN topic t ON (rtt.topic_id = t.id) WHERE rtt.topic_theme_id = 159988 AND t.is_delete = 0 AND review_status >= 0 ORDER BY rtt.id DESC limit 0, 10 |
+----------+------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
这里,我把我优化后的 SQL (只是改了下 order by 字段,从原有使用 inner join 右表字段,改为使用左表主键字段,因为这两种排序,在业务上其实是等价的)一并拿过来对比时间 show profile for query #{Query_ID}
和show profile cpu, block io for query #{Query_ID};
可以进一步查看 Query_ID 的各阶段执行耗时分布:
mysql> show profile for query 1;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000191 |
| checking permissions | 0.000066 |
| checking permissions | 0.000007 |
| Opening tables | 0.000025 |
| init | 0.000052 |
| System lock | 0.000010 |
| optimizing | 0.000076 |
| statistics | 0.000157 |
| preparing | 0.000017 |
| Creating tmp table | 0.000082 |
| Sorting result | 0.000006 |
| executing | 0.000004 |
| Sending data | 0.047750 |
| Creating sort index | 0.000992 |
| end | 0.000007 |
| query end | 0.000011 |
| removing tmp table | 0.000197 |
| query end | 0.000007 |
| closing tables | 0.000012 |
| freeing items | 0.000040 |
| cleaning up | 0.000021 |
+----------------------+----------+
21 rows in set, 1 warning (0.00 sec)
mysql> show profile for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000181 |
| checking permissions | 0.000007 |
| checking permissions | 0.000007 |
| Opening tables | 0.000025 |
| init | 0.000033 |
| System lock | 0.000010 |
| optimizing | 0.000015 |
| statistics | 0.000151 |
| preparing | 0.000021 |
| Sorting result | 0.000008 |
| executing | 0.000004 |
| Sending data | 0.000007 |
| Creating sort index | 0.005279 |
| end | 0.000017 |
| query end | 0.000083 |
| closing tables | 0.000013 |
| freeing items | 0.000040 |
| cleaning up | 0.000029 |
+----------------------+----------+
18 rows in set, 1 warning (0.00 sec)
mysql> show profile cpu, block io for query 1;
+----------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000130 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 | 0 | 0 |
| Opening tables | 0.000035 | 0.000000 | 0.000000 | 0 | 0 |
| init | 0.000033 | 0.000000 | 0.000000 | 0 | 0 |
| System lock | 0.000009 | 0.000000 | 0.000000 | 0 | 0 |
| optimizing | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |
| statistics | 0.000115 | 0.000000 | 0.000000 | 0 | 0 |
| preparing | 0.000019 | 0.000000 | 0.000000 | 0 | 0 |
| Creating tmp table | 0.000022 | 0.000000 | 0.000000 | 0 | 0 |
| Sorting result | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 |
| Sending data | 0.048507 | 0.052000 | 0.000000 | 0 | 0 |
| Creating sort index | 0.000997 | 0.000000 | 0.000000 | 0 | 0 |
| end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000012 | 0.000000 | 0.000000 | 0 | 0 |
| removing tmp table | 0.000156 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| closing tables | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |
| freeing items | 0.000041 | 0.000000 | 0.000000 | 0 | 0 |
| cleaning up | 0.000020 | 0.000000 | 0.000000 | 0 | 0 |
+----------------------+----------+----------+------------+--------------+---------------+
21 rows in set, 1 warning (0.01 sec)
mysql> show profile cpu, block io for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000102 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000068 | 0.000000 | 0.000000 | 0 | 0 |
| Opening tables | 0.000018 | 0.000000 | 0.000000 | 0 | 0 |
| init | 0.000025 | 0.000000 | 0.000000 | 0 | 0 |
| System lock | 0.000008 | 0.000000 | 0.000000 | 0 | 0 |
| optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |
| statistics | 0.000082 | 0.000000 | 0.000000 | 0 | 0 |
| preparing | 0.000018 | 0.000000 | 0.000000 | 0 | 0 |
| Sorting result | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| executing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 |
| Sending data | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| Creating sort index | 0.005414 | 0.004000 | 0.000000 | 0 | 0 |
| end | 0.000012 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000035 | 0.000000 | 0.000000 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 |
| freeing items | 0.000035 | 0.000000 | 0.000000 | 0 | 0 |
| cleaning up | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |
+----------------------+----------+----------+------------+--------------+---------------+
18 rows in set, 1 warning (0.01 sec)
可以看到优化前后的 SQL,执行时间相差了接近10倍。原 SQL 的执行步骤中,多了一步 Creating tmp table
和 removing tmp table
,这两步本身不耗太多时间,关键在于Sending data
这一步,耗时太多,并且有一定的 CPU 使用【数据库的 CPU 使用一般说明是有磁盘 IO】,结合临时表分析,应该是从磁盘读取数据到临时表中进行排序,所以既耗时又费CPU。
所以关键就落到怎么优化掉 explain 中的 Using temporary,看能不能把它去掉。本文解决办法就是修改排序的字段。原理摘自参考文章3中的解释:
MYSQL优化器:JOIN中的顺序选择
Mysql在遇到inner join联接语句时,MySQL表关联的算法是 Nest Loop Join(嵌套联接循环),Nest Loop Join就是通过两层循环手段进行依次的匹配操作,最后返回结果集合。SQL语句只是描述出希望连接的对象和规则,而执行计划和执行操作要切实际将一行行的记录进行匹配。Nest Loop Join的操作过程很简单,很像我们最简单的排序检索算法,两层循环结构。进行连接的两个数据集合(数据表)分别称为外侧表(驱动表)和内侧表(非驱动表)。Mysql又会怎样去确定,哪张表是驱动表,哪张表又是非非驱动表呢?mysql它以表中数据最小的一张表作为驱动表(也就是基表),而另一张表就叫做非驱动表,首先处理驱动表中每一行符合条件的数据,之后的每一行数据和非驱动表进行连接匹配操作,直到循环结束,最后合并结果、返回结果给用户。对于驱动表的字段它是可以直接排序的,然而对于非驱动表的字段排序需要通过循环查询的合并结果(临时表)进行排序,因此,order by o.order_time 时,就先产生了 using temporary(使用临时表)。
前面我们知道 order_payment 的数据量只有11w,那么理所当然的order_payment是驱动表。所以,为了避免 using temporary,就必须使用order作为驱动表,这个时候STRAIGHT_JOIN关键字就来了。
参考文章:
MySQL Sending data导致表查询慢的问题剖析
MySQL Profiling 的使用
Mysql 调优记: INNER JOIN查询 Using temporary; Using filesort 问题优化