当前位置：首页 > news >正文

MySQl查询分析工具 EXPLAIN ANALYZE

news 来源：原创 2024/9/28 11:09:13

文章目录

EXPLAIN ANALYZE是什么
- Iterator
输出内容解读
- EXPLAIN ANALYZE和EXPLAIN FORMAT=TREE的区别
- 单个 Iterator 内容解读
案例分析
- 案例1 文件排序
- 案例2 简单的JOIN查询

参考资料：https://hackmysql.com/book-2/

EXPLAIN ANALYZE是什么

EXPLAIN ANALYZE是MySQL8.0.18版本推出的一个用于查询的分析工具，它将显示MySQL在查询上花费的时间以及原因。它将生成查询计划、检测查询并执行查询操作，同时会计算行数并测量执行计划中各个点所花费的时间。执行完成后，EXPLAIN ANALYZE将打印计划和测量值，而不是查询结果。
这个新功能建立在常规的EXPLAIN查询计划检查工具之上，可以看作是MySQL 8.0中早期添加的EXPLAINFORMAT=TREE的一个扩展功能。除了正常的EXPLAIN会打印的查询计划和估计成本外，EXPLAIN ANALYZE还会打印执行计划中单个迭代器的实际成本。

Iterator

8.0的Query Executor使用模块化的迭代器进行了升级
在这里插入图片描述

EXPLAIN ANALYZE的结果每个箭头指向的就是一个iterator
在这里插入图片描述

template <class RealIterator>
bool TimingIterator<RealIterator>::Init() {++m_num_init_calls;steady_clock::time_point start = now();     /* start time    */bool err = m_iterator.Init();               /* real iterator */steady_clock::time_point end = now();       /* end time      */m_time_spent_in_first_row += end - start;m_first_row = true;return err;
}

迭代器接口有两个方法：Init()和Read()

一个loop表示一次迭代器的调用过程：调用Init()，然后调用Read()，直到没有更多的行
EXPLAIN ANALYZE会打印每个迭代器的测量值，如下图所示：
在这里插入图片描述

以(actual time=0.106..9.991 rows=2844 loops=2)为例：解释如下

0.106
Init time: 调用Init()和读取第一行（第一次执行Read()）花费的平均毫秒时间
9.991
Read time: 调用Init()和读取所有行(执行所有Read())的平均花费时间(毫秒)
rows=2844
读取行的总记录数，所有loop
loops=2
Init()调用的次数，或者迭代器执行的次数

第一个时间值，叫做init time，视为启动开销，通常来说是非常慢的，但是依赖于具体的迭代器
第二个时间值，叫做read time，可以通过loops * read time = iterator time这个公式来计算iterator time，即迭代器花在读取行的总时间 = 9.991 ms × 2 = 19.982，很显然，loops=1时，read time和iterator time相同

init time、read time和iterator time是我的术语，不是MySQL的官方术语，因为MySQL没有为这些值指定简洁的名称。

一般来说，iterator time是从叶子到根的累积时间
-> A (200ms loops=1)
-> B (185ms loops=1)
-> C (90ms loops=2)

叶子节点 iterator C 花费了 180 ms (90 × 2 loops). 由于iterator B 调用了 iterator C, iterator B 调用的时间是 5 ms ( 减去 iterator C的时间：185 ms − 180 ms). 同样地, iterator A 调用 iterator B, 因此 A 的时间是 15 ms (200 ms − 185 ms)。查询花费200 ms（180ms + 5ms + 15ms），而不是这些时间之和（575 ms = 200 ms + 185 ms + 90 ms）

输出内容解读

以列出每位员工在2005年8月拨打的电话总额这条sql为例：

SELECT first_name, last_name, SUM(amount) AS total
FROM staff INNER JOIN paymentON staff.staff_id = payment.staff_idAND payment_date LIKE '2005-08%'
GROUP BY first_name, last_name;

下面是EXPLAIN ANALYZE结果

mysql> EXPLAIN ANALYZE-> SELECT first_name, last_name, SUM(amount) AS total-> FROM staff INNER JOIN payment ON staff.staff_id = payment.staff_id AND payment_date LIKE '2005-08%'-> GROUP BY first_name, last_name\G;
*************************** 1. row ***************************
EXPLAIN: -> Table scan on <temporary>  (actual time=0.003..0.003 rows=2 loops=1)-> Aggregate using temporary table  (actual time=47.732..47.733 rows=2 loops=1)-> Nested loop inner join  (cost=1757.30 rows=1787) (actual time=0.305..35.779 rows=5686 loops=1)-> Table scan on staff  (cost=3.20 rows=2) (actual time=0.036..0.043 rows=2 loops=1)-> Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894) (actual time=0.221..17.469 rows=2843 loops=2)-> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id)  (cost=117.43 rows=8043) (actual time=0.210..13.576 rows=8022 loops=2)

EXPLAIN ANALYZE和EXPLAIN FORMAT=TREE的区别

如下图所示，EXPLAIN FORMAT=TREE会展示查询计划以及成本估计，但并不会告诉这些估计是否正确，也没有告诉我们时间实际上花在了查询计划中的哪些操作上，但EXPLAIN ANALYZE可以。
在这里插入图片描述

单个 Iterator 内容解读

这里有几个新的测量方法：

获取第一行的实际时间（毫秒）
获取所有行的实际时间（毫秒）
实际读取的行数
实际循环次数

以 Filter 这个 iterator 为例：

Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894) (actual time=0.221..17.469 rows=2843 loops=2)

下面对这些文本内容分开进行解释：

Filter: (payment.payment_date like ‘2005-08%’)

这是这个iterator的内容，可以知道这个 iterator 执行的是什么操作

cost=117.43 rows=894

Filter的成本消耗估计值为 117.43 ms，预计读取894行。这些估计是由查询优化器在执行查询之前根据可用统计数据进行的。此信息也存在于EXPLAIN FORMAT=TREE输出中。

actual time=0.221…17.469

这表示读取第一行平均需要0.221毫秒，读取所有行平均需要17.469毫秒。

为什么这里是平均值？因为存在循环操作，我们必须对这个iterator计时两次，报告的数字是所有循环迭代的平均值。这意味着Filter这个iterator操作的实际执行时间是这些数字的两倍。因此，如果我们查看Nested loop inner join这个iterator中接收所有行的时间，它是35.779毫秒，是 Filter 这个迭代器一次运行时间的两倍多。
![在这里插入图片描述](https://i-blog.csdnimg.cn/direct/a2ef5c752d60458c9694fb9dd2084549.png
这里这个时间值反映的是以 Filter 这个 iterator 为根节点的整个子树的时间，而不是单个 iterator 的执行时间。即Index lookup on payment using idx_fk_staff_id读取行的时间 + 判断payment_date LIKE '2005-08%'条件的时间 = Filter 这个 iterator 后面的的 actual 部分的时间值。

也就是说实际上 Filter 操作执行的时间 = 17.469 ms - 13.576 ms = 3.893 ms

如果我们查看 Index lookup on payment 这个迭代器，我们会看到相应的数字分别为 0.210 ms 和 13.576 ms。这意味着大部分时间都花在使用索引查找并读取行上，与读取数据相比，实际的 Filter 操作相对来说花费时间并不多。

rows=2843

实际读取的行数为2844行，而估计值为894行。实际读取的大概是预估值的 3 倍。同样，由于循环，估计和实际数字都是所有循环迭代的平均值。
如果我们查看模式，payment_date列上没有索引，因此提供给优化器以计算过滤器选择性的统计数据是有限的，所以优化器在生成查询计划时可能计算不到那么准，和实际还是有差距的
在这里插入图片描述
如果有索引的话，理论值和实际值就可能比较接近了。比如Index lookup on payment using idx_fk_staff_id这个输出内容：
-> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id) (cost=117.43 rows=8043) (actual time=0.210…13.576 rows=8022 loops=2)
估计为8043行，而实际读取的行为8024行，很接近了。这是因为索引附带了非索引列所没有的额外统计信息，优化器可以利用这些信息进行统计。

loops=2

loops表示循环的数量，这里表示Filter这个操作的循环数为2。这是什么意思？为了理解这个数字，我们必须查看查询计划中过滤迭代器上方的内容。在第11行有一个Nested loop inner join操作，在第12行有Table scan on staff操作。这里sql使用到的inner join操作，并且使用的是Nested loop inner join这个join算法。根据Nested loopjoin这个join算法的原理，会先扫描staff表，对于staff表中的每一行，根据staff.staff_id = payment.staff_id和payment_date LIKE '2005-08%'这两个条件在payment表中查找相应的记录。

由于staff表中只有两行数据
在这里插入图片描述
所以Filter这个操作和Index lookup on payment这个操作的loops都为2

案例分析

案例1 文件排序

使用到的表如下：

CREATE TABLE `sbtest1` (`id` int NOT NULL AUTO_INCREMENT,`k` int NOT NULL DEFAULT '0',`c` char(120) NOT NULL DEFAULT '',`pad` char(60) NOT NULL DEFAULT '',PRIMARY KEY (`id`),KEY `k_1` (`k`)
) ENGINE=InnoDB;

通过下面的存储过程填充1000000条数据

DELIMITER $$CREATE PROCEDURE InsertDataToSbtest1()
BEGINDECLARE i INT DEFAULT 1;DECLARE rand_k INT;DECLARE rand_c CHAR(120);DECLARE rand_pad CHAR(60);WHILE i <= 1000000 DO-- 生成随机的整数作为 'k' 列的值SET rand_k = FLOOR(RAND() * 10000);-- 生成随机的字符串作为 'c' 和 'pad' 列的值SET rand_c = LPAD(FLOOR(RAND() * 1000000), 120, 'a'); -- 用 'a' 填充字符SET rand_pad = LPAD(FLOOR(RAND() * 100000), 60, 'b'); -- 用 'b' 填充字符-- 插入一条记录INSERT INTO sbtest1 (k, c, pad) VALUES (rand_k, rand_c, rand_pad);-- 递增计数器SET i = i + 1;END WHILE;
END$$DELIMITER ;

经测试，在i712700 32G DDR5机器上跑了 1916s，使用的是MySQL 8.0.35 Windows版本
在这里插入图片描述
同时本地文件占了大概244M

默认情况没有走k_1索引，而是走的主键索引，查询449985条数据花了1.745s

mysql> EXPLAIN SELECT c FROM sbtest1 WHERE k < 4500 ORDER BY id;
+----+-------------+---------+------------+-------+---------------+---------+---------+------+--------+----------+-------------+
| id | select_type | table   | partitions | type  | possible_keys | key     | key_len | ref  | rows   | filtered | Extra       |
+----+-------------+---------+------------+-------+---------------+---------+---------+------+--------+----------+-------------+
|  1 | SIMPLE      | sbtest1 | NULL       | index | k_1           | PRIMARY | 4       | NULL | 987633 |    50.00 | Using where |
+----+-------------+---------+------------+-------+---------------+---------+---------+------+--------+----------+-------------+
1 row in set, 1 warning (0.00 sec)

如果让它强制走k_1索引，查询449985条数据花了15.932s，查询计划中出现了filesort

mysql> EXPLAIN SELECT c FROM sbtest1 FORCE INDEX(k_1) WHERE k < 4500 ORDER BY id;
+----+-------------+---------+------------+-------+---------------+------+---------+------+--------+----------+--------------------------------------------------+
| id | select_type | table   | partitions | type  | possible_keys | key  | key_len | ref  | rows   | filtered | Extra                                            |
+----+-------------+---------+------------+-------+---------------+------+---------+------+--------+----------+--------------------------------------------------+
|  1 | SIMPLE      | sbtest1 | NULL       | range | k_1           | k_1  | 4       | NULL | 493816 |   100.00 | Using index condition; Using MRR; Using filesort |
+----+-------------+---------+------------+-------+---------------+------+---------+------+--------+----------+--------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

using MRR表示使用了Multi-Range Read Optimization这个优化策略
走了索引，并且type是range，并且用了索引下推优化策略，Using index condition，看起来就是
Using filesort导致了查询慢

mysql> EXPLAIN ANALYZE SELECT c FROM sbtest1 FORCE INDEX(k_1) WHERE k < 4500 ORDER BY id\G;
*************************** 1. row ***************************
EXPLAIN: 
(1)-> Sort: sbtest1.id  (cost=298031 rows=493816) 
(2)	(actual time=16366..16450 rows=449985 loops=1)
(3)    -> Index range scan on sbtest1 using k_1 over (k < 4500), with index condition: (sbtest1.k < 4500)  
(4)    	(cost=298031 rows=493816) (actual time=59.7..15499 rows=449985 loops=1)1 row in set (16.51 sec)

首先，根据通常的理解，这个sql应该是先取出数据然后再进行排序，毕竟没有数据的话要怎么排序呢？所以这个结果应该是第3行在前，第1行在后，但是实际结果却是相反的

为了便于观察，我将输出进行了换行及标号（上面文本中每行开头的带数字的括号），现在解释一下这个输出内容里面各操作的执行时间：
第4行，15499(ms)表示第3行的Index range scan这个操作花了大约15.5s（15499 - 59.7 = 15439.3ms），第2行表示第1行的Sort操作从16366ms开始，到16450ms结束，花了84ms
总执行时间为16450ms，93.9%的时间花在读取数据上，0.5%的时间花在排序上，剩下5.6%的时间花在其他阶段，比如preparing，statistics，logging，cleaning up等等

答案很明显了文件排序不是使此查询变慢的根本原因。问题是数据访问，449985行不是一个小的结果集。对于每秒执行数十亿次操作的CPU来说，对449985个值进行排序几乎是零工作，但对于必须遍历索引、进行管理的关系数据库来说，读取449985行数据这是一项可观的工作量

为什么都觉得出现了Using Filesort会导致速度慢？

因为MySQL在排序数据超过sort_buffer_size这个变量的值（单位为字节）时，会使用磁盘上的临时文件。262144字节 = 256M，而我刚才测试的1000000条数据是244M，现在只是对449985条数据排序，所以肯定没超过sort_buffer_size值

mysql> SHOW VARIABLES LIKE 'sort_buffer_size';
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| sort_buffer_size | 262144 |
+------------------+--------+
1 row in set, 1 warning (0.00 sec)

而硬盘驱动器的速度比内存慢几个数量级。以前当旋转磁盘是标准时，所以很慢；但现在SSD固态硬盘存储通常非常快。在以高吞吐量QPS进行查询的场景，文件排序可能是一个问题，但还是需要使用EXPLAIN ANALYZE进行测量和验证。

案例2 简单的JOIN查询

CREATE TABLE IF NOT EXISTS `elem` (id int unsigned not null primary key,a char(2) not null,b char(2) not null,c char(2) not null,INDEX `idx_a_b` (a, b)
) ENGINE=InnoDB;INSERT INTO elem VALUES('1',  'Ag', 'B',  'C' )
,('2',  'Au', 'Be', 'Co')
,('3',  'Al', 'Br', 'Cr')
,('4',  'Ar', 'Br', 'Cd')
,('5',  'Ar', 'Br', 'C' )
,('6',  'Ag', 'B',  'Co')
,('7',  'At', 'Bi', 'Ce')
,('8',  'Al', 'B',  'C' )
,('9',  'Al', 'B',  'Cd')
,('10', 'Ar', 'B',  'Cd');CREATE TABLE IF NOT EXISTS `elem_names` (`symbol` char(2) NOT NULL,`name` varchar(16) DEFAULT NULL,PRIMARY KEY (`symbol`)
) ENGINE=InnoDB;INSERT INTO elem_names VALUES('Ag', 'Silver'   )
,('Al', 'Aluminum' )
,('Ar', 'Argon'    )
,('At', 'Astatine' )
,('Au', 'Gold'     )
,('B',  'Boron'    )
,('Be', 'Beryllium')
,('Bi', 'Bismuth'  )
,('Br', 'Bromine'  )
,('C',  'Carbon'   )
,('Cd', 'Cadmium'  )
,('Ce', 'Cerium'   )
,('Co', 'Cobalt'   )
,('Cr', 'Chromium' );

EXPLAIN SELECT name FROM elem JOIN elem_names ON (elem.a = elem_names.symbol) WHERE a IN (‘Ag’, ‘Au’, ‘At’)\G;

mysql> EXPLAIN SELECT name FROM elem JOIN elem_names ON (elem.a = elem_names.symbol) WHERE a IN ('Ag', 'Au', 'At');
+----+-------------+------------+------------+--------+---------------+---------+---------+--------------------+------+----------+--------------------------+
| id | select_type | table      | partitions | type   | possible_keys | key     | key_len | ref                | rows | filtered | Extra                    |
+----+-------------+------------+------------+--------+---------------+---------+---------+--------------------+------+----------+--------------------------+
|  1 | SIMPLE      | elem       | NULL       | range  | idx_a_b       | idx_a_b | 8       | NULL               |    4 |   100.00 | Using where; Using index |
|  1 | SIMPLE      | elem_names | NULL       | eq_ref | PRIMARY       | PRIMARY | 8       | mysql_learn.elem.a |    1 |   100.00 | NULL                     |
+----+-------------+------------+------------+--------+---------------+---------+---------+--------------------+------+----------+--------------------------+
2 rows in set, 1 warning (0.00 sec)

EXPLAIN ANALYZE结果如下

mysql> EXPLAIN ANALYZE SELECT name FROM elem JOIN elem_names ON (elem.a = elem_names.symbol) WHERE a IN ('Ag', 'Au', 'At')\G;
*************************** 1. row ***************************
EXPLAIN: -> Nested loop inner join  (cost=2.46 rows=4) (actual time=0.0295..0.0471 rows=4 loops=1)-> Filter: (elem.a in ('Ag','Au','At'))  (cost=1.06 rows=4) (actual time=0.0194..0.0319 rows=4 loops=1)-> Covering index range scan on elem using idx_a_b over (a = 'Ag') OR (a = 'At') OR (a = 'Au')  (cost=1.06 rows=4) (actual time=0.017..0.0284 rows=4 loops=1)-> Single-row index lookup on elem_names using PRIMARY (symbol=elem.a)  (cost=0.275 rows=1) (actual time=0.0032..0.00323 rows=1 loops=4)1 row in set (0.00 sec)

下面将其输出格式进行调整和标号

mysql> EXPLAIN ANALYZE SELECT name FROM elem JOIN elem_names ON (elem.a = elem_names.symbol) WHERE a IN ('Ag', 'Au', 'At')\G;
*************************** 1. row ***************************
(3)-> Nested loop inner join  (cost=2.46 rows=4) (actual time=0.0295..0.0471 rows=4 loops=1)
(1)    -> Filter: (elem.a in ('Ag','Au','At'))  (cost=1.06 rows=4) (actual time=0.0194..0.0319 rows=4 loops=1)
(0)        -> Covering index range scan on elem using idx_a_b over (a = 'Ag') OR (a = 'At') OR (a = 'Au')  (cost=1.06 rows=4) (actual time=0.017..0.0284 rows=4 loops=1)
(2)    -> Single-row index lookup on elem_names using PRIMARY (symbol=elem.a)  (cost=0.275 rows=1) (actual time=0.0032..0.00323 rows=1 loops=4)

通常应该以深度优先规则阅读EXPLAIN ANALYZE的输出内容。

虽然查询执行的结果显示JOIN操作是根节点，但开始读取行是从表elem上的Covering index range scan开始的，即(0)位置。然后在（1）位置使用IN子句的条件对行进行筛选。匹配的行用于查找和连接elem_names表中的相应行，PRIMARY lookup（2）

注意，（0）位置处的Covering index range scan操作和（1）位置处的Filter操作的loops均为1，这是因为，join操作中的第一个表只会被访问一次。但是（2）位置的primary key lookup的loops=4，这是因为被连接的表（join操作中的第二个和后续表）通常会对前面表中的每一行进行多次访问。同样，(1)位置处的filter匹配结果rows=4，这对应于primary key lookup的loops=4：第一个表（elem表）中的4行导致MySQL访问连接的表（elem_names表）4次。