MySQL Query Profiler 分析SQL慢查

 最近的一段时间里,线上数据库出现了很多慢查询,但是通过代码去看都是走了索引的,而且通过explain分析也是走了索引,但确实是有慢查询,很奇怪,就想通过mysql-query-profiler分析SQL慢查。

 MySQL 的 Query Profiler 是一个使用非常方便的 Query 诊断分析工具,通过该工具可以获取一条Query 在整个执行过程中多种资源的消耗情况,如 CPU,IO,IPC,SWAP 等,以及发生的 PAGE FAULTS,CONTEXT SWITCHE 等等,同时还能得到该 Query 执行过程中 MySQL 所调用的各个函数在源文件中的位置。

(1) Query Profiler 的具体用法

(1.1) 查看是否开启 Query Profiler

/** 查看是否开启 Query Profiler */
mysql>  show variables like 'profiling' ;  
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | OFF   |
+---------------+-------+
1 row in set (0.03 sec)

mysql>

 

(1.2) 设置开启Query Profiler功能

/** 开启 Query Profiler 功能。 */
mysql>  set profiling = 1 ;    
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql>

 

(1.3) 获取系统中保存的所有 Query Profiler 概要信息

/** 获取系统中保存的所有 Query 的 profile 概要信息 */
mysql>  show profiles;  
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                                                         |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.00138750 | show variables like 'profiling'                                                                                                                                                                                                                               |
|        2 | 0.19619525 | SELECT * FROM xxxx_biz_db_xxx_base_xxxxxxxx LIMIT 10 OFFSET 0 |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

mysql>

 

(1.4) 针对单个 Query 获取 profile 信息

  /** 针对单个 Query 获取详细的 profile 信息。 */ 
mysql> show profile for query 2 ;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000092 |
| checking permissions | 0.000015 |
| Opening tables       | 0.000023 |
| init                 | 0.000060 |
| System lock          | 0.000018 |
| optimizing           | 0.000022 |
| statistics           | 0.000729 |
| preparing            | 0.000037 |
| Sorting result       | 0.000020 |
| executing            | 0.000014 |
| Sending data         | 0.000030 |
| Creating sort index  | 0.194956 |
| end                  | 0.000049 |
| query end            | 0.000017 |
| closing tables       | 0.000017 |
| freeing items        | 0.000034 |
| logging slow query   | 0.000040 |
| cleaning up          | 0.000025 |
+----------------------+----------+
18 rows in set, 1 warning (0.00 sec)

mysql>
show profile cpu,block io for query query_id;

通过Status一列,可以看到整条SQL的运行过程
1. starting //开始
2. checking permissions //检查权限
3. Opening tables //打开数据表
4. init //初始化
5. System lock //锁机制
6. optimizing  //优化器
7. statistics  //分析语法树
8. prepareing  //预准备
9. Sorting result 
10. executing   //引擎执行开始
11. Sending data
12. Creating sort index 
13. end        //引擎执行结束
14. query end  //查询结束
15. closing tables //释放数据表
16. freeing items //释放内存
17. logging slow query
18. cleaning up //彻底清理

(1.6) 针对单个Query获取详细profile信息

/** 针对单个 Query 获取详细的 profile 信息。 */ 
show profile cpu, block io, memory, swaps,context switches, source for query 2;
all    // 显示所有的开销信息
block io    //显示块IO相关开销
context switches    // 上下文切换相关开销
cpu    // 显示cpu相关开销
ipc    // 显示发送和接收相关开销信息
memory    // 显示内存相关开销
page faults    // 显示页面错误相关开销
source    // 显示和Source_function, Source_file, Source_line相关的开销
swaps    // 显示交换次数相关开销

(2) Query Profiler实战-order by排序导致的SQL慢查

本次问题是外卖业务的评论服务遇到了sql慢查
评论表里有订单索引、店铺索引、骑手索引,所以无论是用户、商家还是骑手查询评论,肯定是走索引的。通过explain确认一下

(2.1) 首先通过explain查看sql语句分析

(2.1.1) sql语句explain-优化前

mysql> explain
    -> SELECT *
    -> FROM xxxx_biz_db_xxx_base_xxxxxxxx
    -> WHERE shop_city_id = xxxxxxxx
    -> AND rider_id = 5764611828814449467
    -> AND c_d_score = 10
    -> AND c_d_has_content = 1
    -> AND evaluate_role = 1
    -> AND is_deleted = 0
    -> ORDER BY c_evaluate_timestamp DESC
    -> LIMIT 10 OFFSET 0 ;
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+----------------------------------------------------+
| id | select_type | table                         | partitions | type | possible_keys | key          | key_len | ref   | rows | filtered | Extra                                              |
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+----------------------------------------------------+
|  1 | SIMPLE      | xxxx_biz_db_xxx_base_xxxxxxxx | NULL       | ref  | idx_rider_id  | idx_rider_id | 8       | const | 2174 |     0.00 | Using index condition; Using where; Using filesort |
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+----------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

mysql>

可以看到走了骑手索引idx_rider_id,但是备注里提升用了文件排序 Using filesort,
一看就知道是order by排序导致Using filesort
如果MySQL内存够用优先在内存里排序,内存不够用了才会使用文件排序,但是耗时就高了。


(2.1.2) sql语句explain-优化后

把sql语句优化了一下,把 ORDER BY c_evaluate_timestamp DESC 改成 ORDER BY id DESC 试一下

mysql> explain
    -> SELECT *
    -> FROM xxxx_biz_db_xxx_base_xxxxxxxx
    -> WHERE shop_city_id = xxxxxxxx
    -> AND rider_id = 5764611828814449467
    -> AND c_d_score = 10
    -> AND c_d_has_content = 1
    -> AND evaluate_role = 1
    -> AND is_deleted = 0
    -> ORDER BY id DESC
    -> LIMIT 10 OFFSET 0 ;
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+-------------+
| id | select_type | table                         | partitions | type | possible_keys | key          | key_len | ref   | rows | filtered | Extra       |
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+-------------+
|  1 | SIMPLE      | xxxx_biz_db_xxx_base_xxxxxxxx | NULL       | ref  | idx_rider_id  | idx_rider_id | 8       | const | 2174 |     0.00 | Using where |
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+-------------+
1 row in set, 1 warning (0.00 sec)

mysql>

通过explain发现,没有文件排序Using filesort

(2.2.4) 获取系统中保存的所有 Query Profiler 概要信息

mysql>  show profiles;
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                                                         |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.00138750 | show variables like 'profiling'                                                                                                                                                                                                                               |
|        2 | 0.19619525 | SELECT *
FROM xxxx_biz_db_xxx_base_xxxxxxxx
WHERE shop_city_id = 'xxxxxxxx'
AND rider_id = '5764611828814449467'
AND c_d_score = '10'
AND c_d_has_content = '1'
AND evaluate_role = 1
AND is_deleted = 0
ORDER BY c_evaluate_timestamp DESC
LIMIT 10 OFFSET 0 |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

mysql>

 可以看到有2条查询信息,第二条是我们想要查看的

(2.2.5) 获取sql的详细profile信息

mysql> show profile for query 2 ;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000092 |
| checking permissions | 0.000015 |
| Opening tables       | 0.000023 |
| init                 | 0.000060 |
| System lock          | 0.000018 |
| optimizing           | 0.000022 |
| statistics           | 0.000729 |
| preparing            | 0.000037 |
| Sorting result       | 0.000020 |
| executing            | 0.000014 |
| Sending data         | 0.000030 |
| Creating sort index  | 0.194956 |
| end                  | 0.000049 |
| query end            | 0.000017 |
| closing tables       | 0.000017 |
| freeing items        | 0.000034 |
| logging slow query   | 0.000040 |
| cleaning up          | 0.000025 |
+----------------------+----------+
18 rows in set, 1 warning (0.00 sec)

mysql>

通过Query Profiler确认,Creating sort index确实耗时,200ms的查询有194ms耗费在了排序上。


(3) Query Profiler实战-IO导致的慢查

商家端会有查询某个商家评论的需求,这次遇到的问题是商家查询近x天用户评论商家的SQL

(3.1) 通过explain确认走索引

// 

(3.2) Query Profiler分析

Query Profiler处于开启状态,直接进入分析阶段

(3.2.1)获取系统中保存的所有 Query Profiler 概要信息

mysql>  show profiles;
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                                                                                                        |
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.00070225 | show variables like 'profiling'                                                                                                                                                                                                                                                                              |
|        2 | 0.13942025 | SELECT COUNT(*) AS count
FROM xxxx_biz_db_xxx_base_xxxxxxxx
WHERE shop_city_id = 'xxxxxxxx'
AND shop_id = '5764607706930086100'
AND c_b_score IN ('2', '10', '100', '200', '300', '400', '500')
AND c_evaluate_timestamp BETWEEN '1666242000' AND '1666933199'
AND evaluate_role = 1
AND is_deleted = |
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

mysql>

(3.2.2) 获取sql的详细profile信息

mysql>  show profile for query 2 ;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000105 |
| checking permissions | 0.000015 |
| Opening tables       | 0.000024 |
| init                 | 0.000042 |
| System lock          | 0.000017 |
| optimizing           | 0.000023 |
| statistics           | 0.000495 |
| preparing            | 0.000039 |
| executing            | 0.000013 |
| Sending data         | 0.138473 |
| end                  | 0.000045 |
| query end            | 0.000016 |
| closing tables       | 0.000018 |
| freeing items        | 0.000032 |
| logging slow query   | 0.000043 |
| cleaning up          | 0.000022 |
+----------------------+----------+
16 rows in set, 1 warning (0.00 sec)

mysql>

最耗时的竟然是发送数据Sending data,有点不太相信

(3.2.3) 获取sql的详细profile信息

再来一次

mysql>  show profiles;
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                                                                                                   |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.00204875 | show variables like 'profiling'                                                                                                                                                                                                                                                                         |
|        2 | 0.13039850 | SELECT COUNT(*) AS count
FROM xxxx_biz_db_xxx_base_xxxxxxxx
WHERE shop_city_id = 'xxxxxxxx'
AND shop_id = '5764607706930086100'
AND c_b_score IN ('2', '10', '100', '200', '300', '400', '500')
AND c_evaluate_timestamp BETWEEN '1666242000' AND '1666933199'
AND evaluate_role = 1
AND is_deleted = 0 |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

mysql>

(3.2.4) 获取sql的profile信息

mysql>  show profile for query 2 ;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000145 |
| checking permissions | 0.000020 |
| Opening tables       | 0.000030 |
| init                 | 0.000062 |
| System lock          | 0.000021 |
| optimizing           | 0.000031 |
| statistics           | 0.000664 |
| preparing            | 0.000041 |
| executing            | 0.000016 |
| Sending data         | 0.129180 |
| end                  | 0.000042 |
| query end            | 0.000017 |
| closing tables       | 0.000018 |
| freeing items        | 0.000028 |
| logging slow query   | 0.000054 |
| cleaning up          | 0.000033 |
+----------------------+----------+
16 rows in set, 1 warning (0.00 sec)

mysql>

(3.2.5) 获取sql的详细profile信息

mysql>   show profile cpu, block io for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000145 | 0.000126 |   0.000000 |            0 |             0 |
| checking permissions | 0.000020 | 0.000019 |   0.000000 |            0 |             0 |
| Opening tables       | 0.000030 | 0.000030 |   0.000000 |            0 |             0 |
| init                 | 0.000062 | 0.000062 |   0.000000 |            0 |             0 |
| System lock          | 0.000021 | 0.000020 |   0.000000 |            0 |             0 |
| optimizing           | 0.000031 | 0.000000 |   0.000074 |            0 |             0 |
| statistics           | 0.000664 | 0.000258 |   0.000000 |           96 |             0 |
| preparing            | 0.000041 | 0.000039 |   0.000000 |            0 |             0 |
| executing            | 0.000016 | 0.000016 |   0.000000 |            0 |             0 |
| Sending data         | 0.129180 | 0.015645 |   0.008681 |        33824 |             0 |
| end                  | 0.000042 | 0.000026 |   0.000000 |            0 |             0 |
| query end            | 0.000017 | 0.000017 |   0.000000 |            0 |             0 |
| closing tables       | 0.000018 | 0.000017 |   0.000000 |            0 |             0 |
| freeing items        | 0.000028 | 0.000028 |   0.000000 |            0 |             0 |
| logging slow query   | 0.000054 | 0.000054 |   0.000000 |            0 |            16 |
| cleaning up          | 0.000033 | 0.000033 |   0.000000 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
16 rows in set, 1 warning (0.00 sec)

mysql>

通过Block_ops_in可以看到确实有大量数据读取

Block_ops_in和Block_ops_out表示块存储设备输入和输出的次数,即从硬盘读取和写入数据的次数。
正常情况下,只有当数据量大于内存可用量时,才会借助硬盘进行内存交换(Swap),因此产生如此大量的硬盘读取和写入。

有几个办法:
第一个办法,优化查询语句,减少数据量。
第二个办法,索引覆盖。
第三个办法,增大MySQL内存。

我们首先分析了sql语句和索引,发现sql语句只走了店铺索引,然后回表取回了一千多条数据,再根据 评价时间c_evaluate_timestamp、评分c_b_score、角色evaluate_role做过滤,
而且通过代码和sql发现查询用的select *,也就是回表的时候取的是所有的字段,通过show tabl status发现该表的AVG_row_length是203字节,计算一下 203*1000字节 回表会取200字节左右数据,所以我们把select *优化成select 必要字段
而且优化索引,把店铺索引改为店铺评价时间索引,这样通过索引能过滤大部分的数据

参考

[1] MySQL 8.0 show-profile
[2] MySQL- SQL执行计划 & 统计SQL执行每阶段的耗时
[3] MySQL分析SQL耗时瓶颈
[4] MySQL Profiling 的使用
[5] MySQL PROFILING 不仅仅是性能检测