MySQL中Profiling功能的介绍以及通过Profiling排查慢SQL的案例
更新时间：
免责声明： 本文档可能包含第三方产品信息，该信息仅供参考。阿里云对第三方产品的性能、可靠性以及操作可能带来的潜在影响，不做任何暗示或其他形式的承诺。
概述
一般情况下，出现慢SQL问题，往往会定位到某些具体的SQL语句上，然后通过所谓的“优化三板斧”，如下：
| 板斧一 | 板斧二 | 板斧三 |
|
查询执行计划。 |
建立合适的索引。 | 使用合适的连接关系和过滤条件来实现SQL语句的优化。 |
但是，如果执行计划是正确的，SQL语句的性能还是很慢，可参考本文，通过MySQL中的Profiling工具进一步定位问题。
详细信息
为了更精准定位一条SQL语句的性能问题，需要清楚地知道这条SQL语句运行时消耗了多少系统资源。而MySQL中的Profiling工具可以满足此需求，通过该工具可以获取一条SQL语句在执行过程中多种资源的消耗情况，如CPU、IO、IPC、SWAP等。
Profiling的使用方法
下列内容为MySQL中Profiling的基本使用方法，如果您需要获取更多详细信息，请参见MySQL官方说明文档。
步骤一：启用Profiling
连接MySQL数据库后，执行以下SQL语句，启用Profiling。
SET profiling = 1;
步骤二：检查Profiling状态
连接MySQL数据库后，执行以下SQL语句，查询Profiling状态。
SELECT @@profiling;
系统返回下列内容，0表示未启用Profiling，1表示已启用Profiling。
+-------------+ | @@profiling | +-------------+ | 1 | +-------------+ 1 row in set (0.00 sec)
步骤三：执行需要定位性能问题的SQL语句
启用Profiling后，执行需要定位性能问题的SQL语句。
CREATE TABLE T1 (id INT);
说明：此处为示例，仅供参考，现场以实际情况为准。
步骤四：查询SQL语句信息
执行以下SQL语句，查询已保存的SQL语句信息。
SHOW PROFILES;
系统返回下列内容。
+----------+----------+--------------------------+
| Query_ID | Duration | Query |
+----------+----------+--------------------------+
| 1 | 0.011947 | CREATE TABLE t1 (id INT) |
+----------+----------+--------------------------+
3 rows in set (0.00 sec)
说明：
- Query_ID：SQL语句的ID编号，步骤五中会用到。
- Duration：SQL语句执行时长。
- Query：具体的SQL语句。
步骤五：查询资源消耗情况
执行以下SQL语句，查询指定SQL语句的资源消耗情况。
SHOW PROFILE CPU, BLOCK IO FOR QUERY [$Query_ID];
说明：
- [$Query_ID]：需要查询资源消耗情况的SQL语句ID，从步骤四中获取。
- 此SQL语句中的“CPU, BLOCK IO”将仅查询CPU和IO相关的资源消耗数据。如果您需要查询所有的资源消耗数据，可使用此SQL语句
SHOW PROFILE ALL FOR QUERY [$Query_ID];。
系统返回下列内容，可检查SQL语句执行过程中是否消耗较多的CPU资源或IO资源，再针对性地进行对比测试以及分析。
+----------------------+----------+----------+------------+---------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+---------------+---------------+ | checking permissions | 0.000040 | 0.000038 | 0.000002 | 0 | 0 | | creating table | 0.000056 | 0.000028 | 0.000028 | 0 | 0 | | After create | 0.011363 | 0.000217 | 0.001571 | 347 | 347 | | query end | 0.000375 | 0.000013 | 0.000028 | 0 | 0 | | freeing items | 0.000089 | 0.000010 | 0.000014 | 0 | 0 | | logging slow query | 0.000019 | 0.000009 | 0.000010 | 0 | 0 | | cleaning up | 0.000005 | 0.000003 | 0.000002 | 0 | 0 | +----------------------+----------+----------+------------+---------------+---------------+ 7 rows in set (0.00 sec)
步骤六：关闭Profiling
检查完毕后，可执行以下SQL语句，关闭Profiling。
SET profiling = 0;
通过Profiling排查慢SQL的案例
案例描述
在RDS MySQL版主实例和只读实例上分别执行以下SQL语句，在主实例上的执行时间为30秒，而在只读实例上的执行时间为1秒，两者之间的性能相差甚远。
SELECT COUNT(1)
FROM table_a
WHERE INSTR(col_var, 'abcd') > 0
AND col_id = 108;
排查过程
- 分别在主实例和只读实例上通过
explain语句查看上述SQL语句的执行计划，发现除rows略有不同外，其他信息是一致的。+----+-------------+---------+------+---------------+--------------+---------+-------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | | 1 | SIMPLE | table_a | ref | index_col_id | index_col_id | 9 | const | 2418 | Using where |
+----+-------------+---------+------+---------------+--------------+---------+-------+------+-------------+ - 一般情况下，如果执行计划一致，执行性能不会有太大差异，最有可能导致此差异的是等待锁。为了进一步验证，在主实例上重新执行上述SQL语句，同时新开一个Session并执行
show processlist语句，发现上述SQL语句一直处于sending data的状态，并非等待锁状态。 - 尝试重建索引并重复测试，无任何效果。
- 对比主实例和只读实例上的表结构，发现表结构完全一致。
- 参见Profiling的使用方法，在主实例和只读实例上启用Profiling，重复上述SQL语句的测试，然后收集结果进行对比分析。此步骤用到的SQL语句如下。
SET profiling = 1;
SELECT COUNT(1)
FROM table_a
WHERE INSTR(col_var, 'abcd') > 0
AND col_id = 108;
SHOW PROFILECPU, BLOCK IOFOR QUERY 1;
SET profiling = 0; - 主实例和只读实例上收集到的profiling结果如下：
- 主实例
+----------------------+----------+----------+------------+---------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+---------------+---------------+ | continuing | 0.000050 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000075 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000039 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000049 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000032 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.002955 | 0.001000 | 0.000000 | 352 | 0 | | preparing | 0.000037 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | | Sending data |94.410074 | 8.153760 | 1.684743 | 366608 | 110328 | | end | 0.000057 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000040 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000030 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000084 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+---------------+---------------+ 18 rows in set (0.01 sec) - 只读实例
+----------------------+----------+----------+------------+---------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+---------------+---------------+ | continuing | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000072 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000034 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000049 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000028 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.000138 | 0.001000 | 0.000000 | 0 | 0 | | preparing | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.992242 | 0.991849 | 0.000000 | 0 | 24 | | end | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000036 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+---------------+---------------+ 16 rows in set (0.01 sec)
- 主实例
- 通过对比可见，主实例的Sending data过程消耗了大量的Block_ops_in和Block_ops_out，而只读实例一切正常。Block_ops_in和Block_ops_out表示块存储设备输入和输出的次数，即从硬盘读取和写入数据的次数。正常情况下，只有当数据量大于内存可用量时，才会借助硬盘进行内存交换（Swap），因此产生如此大量的硬盘读取和写入。
BLOCK_OPS_IN and BLOCK_OPS_OUT indicate the number of block input and output operations.
- 检查主实例和只读实例的硬件规格后，发现主实例的内存只有2G，而只读实例的内存为4G。
问题根源
本案例中，慢SQL语句查询的数据量大小为4G左右，与只读实例的内存大小相当，只读实例可以把这些数据放在内存中进行使用。而主实例的内存大小仅为2G，无法存下所有数据，需要进行大量的内存交换，因此耗时较长。
借助MySQL的Profiling功能，进一步确认慢SQL语句消耗了哪些系统资源，为分析性能瓶颈提供了帮助。
相关文档
适用于
- 云数据库RDS MySQL版
文档内容是否对您有帮助？