MySQL性能分析(二)之profiling详解

一、概述

一般情况下，出现慢SQL问题，往往会定位到某些具体的SQL语句上，然后通过所谓的“优化三板斧”，如下：

查询执行计划
建立合适的索引
使用合适的连接关系和过滤条件来实现SQL语句的优化

但是，如果执行计划是正确的，SQL语句的性能还是很慢，可通过MySQL中的Profiling工具进一步定位问题。

为了更精准定位一条SQL语句的性能问题，需要清楚地知道这条SQL语句运行时消耗了多少系统资源。而MySQL中的Profiling工具可以满足此需求，通过该工具可以获取一条SQL语句在执行过程中多种资源的消耗情况，如CPU、IO、IPC、SWAP等。

二、语法

完整的使用语法如下：

SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]
type: {
    ALL
  | BLOCK IO
  | CONTEXT SWITCHES
  | CPU
  | IPC
  | MEMORY
  | PAGE FAULTS
  | SOURCE
  | SWAPS
}

type说明如下：

ALL：显示所有的开销信息。
BLOCK IO：显示块存储设备输入和输出的次数，即从硬盘读取和写入数据的次数。正常情况下，只有当数据量大于内存可用量时，才会借助硬盘进行内存交换（Swap），因此产生如此大量的硬盘读取和写入。
CONTEXT SWITCHES：上下文切换开销。
CPU：显示CPU开销信息。
IPC：显示发送和接收开销信息。
MEMORY：显示内存开销信息。
PAGE FAULTS：显示页面错误开销信息。
SOURCE：显示和Source_function，Source_file， Source_line相关的开销信息。
SWAPS：显示交换次数开销信息。

三、使用方法

下列内容为MySQL中Profiling的基本使用方法，如果您需要获取更多详细信息，请参见MySQL官方说明文档。

3.1 启用

连接MySQL数据库后，执行以下SQL语句，启用Profiling。

SET profiling = 1;

3.2 检查状态

连接MySQL数据库后，执行以下SQL语句，查询Profiling状态。

SELECT @@profiling;

系统返回下列内容，0表示未启用Profiling，1表示已启用Profiling。

+-------------+
| @@profiling |
+-------------+
|           1 |
+-------------+
1 row in set (0.00 sec)

3.3 执行慢SQL语句

启用Profiling后，执行需要定位性能问题的SQL语句。

CREATE TABLE T1 (id INT);

说明：此处为示例，仅供参考，现场以实际情况为准。

3.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语句。

3.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)

列详情

status：显示了SQL执行的一个完整的生命周期，涉及到各个阶段。
Duration：表示SQL在这个阶段的耗时。
CPU_user/CPU_system：用户态/内核态CPU使用。
Block_ops_in/Block_ops_out：块存储设备输入和输出的次数。

status生命周期详情

starting：开始
checking permissions：检查权限
Opening tables：打开表
init：初始化
System lock：系统锁
optimizing：优化
statistics：统计
preparing：准备
create tmp table：创建临时表(如group时储存中间结果)
executing：执行
converting HEAP to MyISAM：查询结果太大时，把结果放在磁盘
Copying to tmp table on disk：把内存临时表复制到磁盘
Sending data：发送数据
Sorting result：排序
end：结束
query end：查询结束
removing tmp table：关闭表/去除TMP表
freeing items：释放物品
cleaning up：清理

3.6 关闭

检查完毕后，可执行以下SQL语句，关闭Profiling。

SET profiling = 0;

四、案例 - 通过Profiling排查慢SQL

4.1 案例描述

在RDS MySQL版主实例和只读实例上分别执行以下SQL语句，在主实例上的执行时间为30秒，而在只读实例上的执行时间为1秒，两者之间的性能相差甚远。

SELECT COUNT(1) FROM test WHERE INSTR(col_var, 'abcd') > 0 AND col_id = 108;

4.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语句消耗了哪些系统资源，为分析性能瓶颈提供了帮助。

posted @ 2022-04-25 09:57 夏尔_717 阅读(1425) 评论(0) 收藏举报

刷新页面返回顶部

ciel_717