【高性能MySQL】性能分析之剖析单条查询SHOW PROFILE

原创

用户9295575

修改于 2025-01-04 19:23:31

3230

在定位到需要优化的单条查询后，确认为什么花费这么长时间执行，以及需要如何去优化。本节主要介绍如何方便的测量查询执行的各部分花费了多少时间，有了这些数据才能决定采用何种优化技术。

使用SHOW PROFILE

SHOW PROFILE命令是在MySQL5.1以后的版本中引入的，默认是禁用的，可以通过服务器变量在会话级别动态地修改。

查看是否开启：

SHOW VARIABLES LIKE 'profiling';

使用下面命令开启：

SET profiling=1;

然后，在服务器上执行的所有语句，都会测量其耗费的时间和其他一些查询执行状态变更相关的数据。当一条查询提交给服务器时，此工具会记录剖析信息到一张临时表，并且给查询赋予一个从1开始的整数标识符。

输入一个查询语句：

select * from user;

我们来看下效果：

show profiles;

执行上面语句后，返回：

+----------+------------+-----------------------------+
| Query_ID | Duration   | Query                       |
+----------+------------+-----------------------------+
|        1 | 0.00299500 | select * from user          |
+----------+------------+-----------------------------+

首先可以看到的是以很高的精度显示了查询的响应时间。接着看下面的输出。

MySQL> show profile for query 1; 
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000153 |
| checking permissions | 0.000018 |
| Opening tables       | 0.000066 |
| init                 | 0.000071 |
| System lock          | 0.000027 |
| optimizing           | 0.000011 |
| statistics           | 0.000036 |
| preparing            | 0.000020 |
| executing            | 0.000009 |
| Sending data         | 0.002414 |
| end                  | 0.000029 |
| query end            | 0.000019 |
| closing tables       | 0.000017 |
| freeing items        | 0.000062 |
| cleaning up          | 0.000044 |
+----------------------+----------+

剖析报告给出了查询执行的每个步骤花费的时间，看结果很难快速的定位哪个步骤花费时间最多。因为输出是按照时间顺序排序的。而实际上我们更关心的是花费了多少时间，这样才能知道哪些开销比较大。但是不能ORDERY BY命令重新排序。不使用SHOW PROFILE命令而是直接查询INFORMATION_SCHEMA中的表，则可以按照我们想要的格式输出。

MySQL> SELECT
    -> state,
    -> sum( duration ) AS total_r,
    -> round( 100 * sum( duration )/( SELECT sum( duration ) FROM information_schema.profiling WHERE query_id = 1 ), 2 ) AS pct_r,
    -> count(*) AS calls,
    -> sum( duration )/ count(*) AS "r/call" 
    -> FROM
    -> information_schema.profiling 
    -> WHERE
    -> query_id = 1 
    -> GROUP BY
    -> state 
    -> ORDER BY
    -> total_r DESC;
+----------------------+----------+-------+-------+--------------+
| state                | total_r  | pct_r | calls | r/call       |
+----------------------+----------+-------+-------+--------------+
| Sending data         | 0.003248 | 81.90 |     2 | 0.0016240000 |
| freeing items        | 0.000138 |  3.48 |     1 | 0.0001380000 |
| starting             | 0.000125 |  3.15 |     1 | 0.0001250000 |
| init                 | 0.000103 |  2.60 |     1 | 0.0001030000 |
| closing tables       | 0.000045 |  1.13 |     2 | 0.0000225000 |
| preparing            | 0.000041 |  1.03 |     2 | 0.0000205000 |
| statistics           | 0.000039 |  0.98 |     2 | 0.0000195000 |
| checking permissions | 0.000039 |  0.98 |     1 | 0.0000390000 |
| Opening tables       | 0.000033 |  0.83 |     1 | 0.0000330000 |
| cleaning up          | 0.000030 |  0.76 |     1 | 0.0000300000 |
| end                  | 0.000026 |  0.66 |     1 | 0.0000260000 |
| executing            | 0.000025 |  0.63 |     2 | 0.0000125000 |
| removing tmp table   | 0.000021 |  0.53 |     1 | 0.0000210000 |
| optimizing           | 0.000020 |  0.50 |     2 | 0.0000100000 |
| query end            | 0.000017 |  0.43 |     1 | 0.0000170000 |
| System lock          | 0.000016 |  0.40 |     1 | 0.0000160000 |
+----------------------+----------+-------+-------+--------------+
16 rows in set, 2 warnings (0.003 sec)

通过这个结果，可以很容易看到哪个步骤耗时长。尽管剖析报告帮助我们定位了耗时环节，要弄清楚为什么耗时长，还需要继续剖析子任务。Sending data这个状态代表的原因很多，可能是各种不同的服务器活动。这部分很难说明优化可以节省多少的耗时。这个查询比较简单，对于复杂查询，我们会看到更多待优化的耗时。

每天学习一点，每天进步一点！

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

腾讯技术创作特训营S11#重启人生