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确认走索引
mysql> explain
-> 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
-> ;
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+----------------------------------------------------+
| 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_shop_id | idx_shop_id | 8 | const | 2174 | 0.00 | Using index condition; Using where; |
+----+-------------+-------------------------------+------------+------+---------------+--------------+---------+-------+------+----------+----------------------------------------------------+
1 row in set, 1 warning (0.00 sec)
mysql>
shop_id=5764607706930086100的店铺评价有1229条
根据shop_id索引扫描到1229条数据
然后需要根据c_b_score字段过滤
由于索引里没有，mysql回表读取数据到内存里，
然后再过滤，最后得到结果5条
(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 必要字段
而且优化索引，把店铺索引改为店铺评价时间索引，这样通过索引能过滤大部分的数据
(4) show profile all for query 6
mysql> show profile all for query 6 ;
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-------------------------+----------------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-------------------------+----------------------+-------------+
| starting | 0.000117 | 0.000075 | 0.000042 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 5 | 0 | NULL | NULL | NULL |
| Executing hook on transaction | 0.000028 | 0.000006 | 0.000022 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 3 | 0 | launch_hook_trans_begin | rpl_handler.cc | 1409 |
| starting | 0.000016 | 0.000006 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | launch_hook_trans_begin | rpl_handler.cc | 1411 |
| checking permissions | 0.000005 | 0.000004 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 2160 |
| Opening tables | 0.002163 | 0.000072 | 0.000453 | 1 | 1 | 0 | 0 | 0 | 0 | 0 | 24 | 0 | open_tables | sql_base.cc | 5784 |
| init | 0.000018 | 0.000008 | 0.000010 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | execute | sql_select.cc | 559 |
| System lock | 0.000025 | 0.000010 | 0.000015 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 3 | 0 | mysql_lock_tables | lock.cc | 331 |
| optimizing | 0.000011 | 0.000009 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 297 |
| statistics | 0.000536 | 0.000156 | 0.000380 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 78 | 0 | optimize | sql_optimizer.cc | 624 |
| preparing | 0.000061 | 0.000044 | 0.000018 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | optimize | sql_optimizer.cc | 708 |
| executing | 0.062404 | 0.053891 | 0.007371 | 0 | 95 | 0 | 0 | 0 | 0 | 0 | 1380 | 0 | ExecuteIteratorQuery | sql_union.cc | 1196 |
| end | 0.000015 | 0.000006 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | execute | sql_select.cc | 592 |
| query end | 0.000004 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4703 |
| waiting for handler commit | 0.000032 | 0.000012 | 0.000020 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 6 | 0 | ha_commit_trans | handler.cc | 1594 |
| closing tables | 0.000009 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4761 |
| freeing items | 0.000048 | 0.000023 | 0.000025 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | dispatch_sql_command | sql_parse.cc | 5216 |
| logging slow query | 0.000061 | 0.000018 | 0.000044 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_do | log.cc | 1644 |
| cleaning up | 0.000044 | 0.000016 | 0.000026 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 7 | 0 | dispatch_command | sql_parse.cc | 2360 |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-------------------------+----------------------+-------------+
18 rows in set, 1 warning (0.00 sec)
mysql>参考资料
[1] MySQL 8.0 show-profile
[2] MySQL- SQL执行计划 & 统计SQL执行每阶段的耗时
[3] MySQL分析SQL耗时瓶颈
[4] MySQL Profiling 的使用
[5] MySQL PROFILING 不仅仅是性能检测