MySQL性能分析之Profiling
一、概述
一般情况下,出现慢SQL
问题,往往会定位到某些具体的SQL
语句上,然后通过所谓的“优化三板斧”,如下:
板斧一 | 板斧二 | 板斧三 |
---|---|---|
查询执行计划 | 建立合适的索引 | 使用合适的连接关系和过滤条件来实现SQL 语句的优化 |
但是,如果执行计划是正确的,SQL
语句的性能还是很慢,可通过MySQL
中的Profiling
工具进一步定位问题。
为了更精准定位一条SQL
语句的性能问题,需要清楚地知道这条SQL
语句运行时消耗了多少系统资源。而MySQL
中的Profiling
工具可以满足此需求,通过该工具可以获取一条SQL
语句在执行过程中多种资源的消耗情况,如CPU
、IO
、IPC
、SWAP
等。
二、使用方法
下列内容为MySQL
中Profiling
的基本使用方法,如果您需要获取更多详细信息,请参见MySQL
官方说明文档。
2.1 启用
连接MySQL
数据库后,执行以下SQL
语句,启用Profiling
。
SET profiling = 1;
2.2 检查状态
连接MySQL
数据库后,执行以下SQL
语句,查询Profiling
状态。
SELECT @@profiling;
系统返回下列内容,0
表示未启用Profiling
,1
表示已启用Profiling
。
+-------------+ | @@profiling | +-------------+ | 1 | +-------------+ 1 row in set (0.00 sec)
2.3 执行需要定位性能问题的SQL语句
启用Profiling
后,执行需要定位性能问题的SQL
语句。
CREATE TABLE T1 (id INT);
说明:此处为示例,仅供参考,现场以实际情况为准。
2.4 查询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
语句。
2.5 查询资源消耗情况
执行以下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)
2.6 关闭
检查完毕后,可执行以下SQL
语句,关闭Profiling
。
SET profiling = 0;
三、案例 - 通过Profiling排查慢SQL
3.1 案例描述
在RDS MySQL
版主实例和只读实例上分别执行以下SQ
L语句,在主实例上的执行时间为30
秒,而在只读实例上的执行时间为1
秒,两者之间的性能相差甚远。
SELECT COUNT(1) FROM test WHERE INSTR(col_var, 'abcd') > 0 AND col_id = 108;
3.2 排查过程
- 分别在主实例和只读实例上通过
explain
语句查看上述SQL
语句的执行计划,发现除rows
略有不同外,其他信息是一致的。
+----+-------------+-------+------+---------------+------------+---------+-------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+------+---------------+------------+---------+-------+------+-------------+ | 1 | SIMPLE | test | ref | idx_col_id | idx_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 test WHERE INSTR(col_var, 'abcd') > 0 AND col_id = 108; SHOW PROFILE CPU, BLOCK IO FOR 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
语句消耗了哪些系统资源,为分析性能瓶颈提供了帮助。