SQL响应慢如何分析解决

原文地址：http://www.linzichen.cn/article/1568527609149521920
系统上线一段时间之后，由于表中的数据不断增加，可能会导致有些sql查询越来越慢。针对这种情况，我们需要 定位到慢sql，从而进行sql分析 ，找到原因后进行 查询优化，让sql的响应时间更快。

数据准备

为了更直观的表现出优化后的效果，我们需要事先准备好数据，并通过自定义函数和存储过程，向表中添加 100W条数据。

创建表

CREATE TABLE student (
	id INT ( 11 ) PRIMARY KEY auto_increment,
	stuno INT NOT NULL,
	`name` VARCHAR ( 20 ),
	age INT ( 3 ),
	class_id INT ( 11 ) 
) ENGINE = INNODB DEFAULT charset = 'utf8';

创建自定义函数

创建自定义函数之前，需要设置数据库服务信任我们自定义的函数或触发器，即设置 log_bin_trust_function_creators 为 ON。

mysql> set global log_bin_trust_function_creators='ON';
Query OK, 0 rows affected (0.04 sec)

mysql> show variables like 'log_bin_trust_function_creators';
+---------------------------------+-------+
| Variable_name                   | Value |
+---------------------------------+-------+
| log_bin_trust_function_creators | ON    |
+---------------------------------+-------+
1 row in set (0.00 sec)

创建生成随机数的函数

DELIMITER $$
CREATE FUNCTION rand_string(n INT)
    RETURNS VARCHAR(255)
BEGIN
    DECLARE chars_str VARCHAR(100) DEFAULT 'abcdefghigklmnopqrstuvwxyzABCDEFGHIGKLMNOPQRSTUVWXYZ';
    DECLARE return_str VARCHAR(255) DEFAULT '';
    DECLARE i INT DEFAULT 0;
    WHILE i < n DO
        SET return_str = concat(return_str, substring(chars_str, floor(1+rand()*52), 1));
        SET i = i + 1;
    END WHILE ;
    RETURN return_str;
END $$
DELIMITER;

创建存储过程

往 student表中添加数据的存储过程。

DELIMITER $$
CREATE PROCEDURE insert_student (IN min_num INT (10), IN max_num INT(10))
BEGIN
    DECLARE i INT DEFAULT 0;
    SET autocommit = 0 ;
    REPEAT
    SET i = i + 1 ;
    INSERT INTO student VALUES(
      null,
      (min_num + 30 * i + 5),
      rand_string(7),
      FLOOR(15 +RAND() * 10),
      null
    );
    UNTIL i = max_num
    END REPEAT;
    COMMIT;
END $$
DELIMITER;

添加数据

执行 insert_student 存储过程，往 student 表中添加100w 条数据。这个过程比较耗时，我用了 576 秒。

call insert_student(0, 1000000);

查看数据

mysql> select count(*) from student;
+----------+
| count(*) |
+----------+
|  1000000 |
+----------+
1 row in set (0.12 sec)

定位慢sql

设置慢查询日志参数

1.开启slow_query_log

通过查看 slow_query_log 我们可以获取慢查询参数的开启状态及日志位置，为了记录慢查询日志，我们需要将此参数设置为 ON。

mysql> set global slow_query_log = 'ON';
Query OK, 0 rows affected (0.20 sec)

mysql> show variables like 'slow_query_log%';
+---------------------+-----------------------------------+
| Variable_name       | Value                             |
+---------------------+-----------------------------------+
| slow_query_log      | ON                                |
| slow_query_log_file | /var/lib/mysql/localhost-slow.log |
+---------------------+-----------------------------------+
2 rows in set (0.00 sec)

2.修改long_query_time阈值

通过 long_query_time 我们可以获取慢查询的时间阈值，默认是 10，意思就是如果一条sql的响应时间超过了10s，系统会将此sql记录到慢日志中。我们将其设置为 0.5。

mysql> set global long_query_time = 0.5;
Query OK, 0 rows affected (0.00 sec)

-- 经过测试，发现设置global时，只针对新的会话有效，对当前会话无效。
-- 所以还需要针对当前会话设置一次。
mysql> set long_query_time = 0.5;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.500000 |
+-----------------+----------+
1 row in set (0.00 sec)

案例测试

mysql> select sql_no_cache * from student where age = 19 and name like '%xefobsK%';
+--------+----------+---------+------+----------+
| id     | stuno    | name    | age  | class_id |
+--------+----------+---------+------+----------+
| 999994 | 29999825 | xefobsK |   19 |     NULL |
+--------+----------+---------+------+----------+
1 row in set, 1 warning (0.60 sec)

此sql执行时间超出了 0.5s，根据我们上面 long_query_time 的设置，此sql 我们会认为是一条慢sql。

接下来需要去慢查询日志中，查看是否将此sql 记录了下来。

[root@localhost ~]# cd /var/lib/mysql
[root@localhost mysql]# cat localhost-slow.log 

# Time: 2022-09-11T04:38:01.726837Z
# User@Host: root[root] @  [192.168.2.3]  Id:    21
# Query_time: 0.695226  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 1000000
SET timestamp=1662871081;
select sql_no_cache * from student where age = 19 and name like '%xefobsK%';

由上可见，我们已经把慢sql 记录了下来。所以接下来，我们需要分析此sql 查询为何慢。

我们知道，设置 long_query_time 为 0.5 可以将时间超过0.5s的sql 记录到慢查询日志中。实际上 这里还有一个参数 min_examined_row_limit，这个参数的意思是 扫描过的最少记录，其值默认为 0。

mysql> show variables like 'min%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| min_examined_row_limit | 0     |
+------------------------+-------+
1 row in set (0.00 sec)

这个变量和查询时间阈值，共同组成了判定一个查询是否是慢查询的条件。
如果扫描过的记录大于等于这个变量，且查询执行时间超过阈值，那么此查询就被记录到慢查询日志中。反之，则不被记录到日志。

慢sql分析

通过查看慢查询日志，定位到慢sql之后，我们需要对此sql进行分析，它为什么会慢。

show profile介绍

show profile可以分析当前会话中mysql都做了什么，以及资源消耗的情况，可以用于sql调优的测量。默认情况是处于 关闭 状态，并保存最近15次的运行结果。

mysql> set profiling = 'ON';
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | ON    |
+---------------+-------+
1 row in set (0.00 sec)

此功能开启后，我们可以通过 show profiles命令查看当前会话中sql的执行情况：

mysql> show profiles;
+----------+------------+----------------------------------+
| Query_ID | Duration   | Query                            |
+----------+------------+----------------------------------+
|        1 | 0.00063825 | select @@version_comment limit 1 |
|        2 | 0.00041000 | set profiling = 'ON'             |
|        3 | 0.00589550 | show variables like 'profiling'  |
+----------+------------+----------------------------------+
3 rows in set, 1 warning (0.00 sec)

由上可见，我们在当前会话中执行过的sql可以通过 show profiles 来查看资源消耗情况，比如我们想查看 Query_ID 为3 的这条sql的消息详细，可以通过以下命令：

mysql> show profile cpu, block io for query 3;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000135 | 0.000062 |   0.000064 |            0 |             0 |
| checking permissions | 0.000104 | 0.000105 |   0.000000 |            0 |             0 |
| Opening tables       | 0.000214 | 0.000214 |   0.000000 |            0 |             0 |
| init                 | 0.000008 | 0.000007 |   0.000000 |            0 |             0 |
| System lock          | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| optimizing           | 0.000004 | 0.000004 |   0.000000 |            0 |             0 |
| optimizing           | 0.000007 | 0.000006 |   0.000000 |            0 |             0 |
| statistics           | 0.000027 | 0.000027 |   0.000000 |            0 |             0 |
| preparing            | 0.000014 | 0.000013 |   0.000000 |            0 |             0 |
| statistics           | 0.000025 | 0.000027 |   0.000000 |            0 |             0 |
| preparing            | 0.000016 | 0.000014 |   0.000000 |            0 |             0 |
| executing            | 0.005103 | 0.005163 |   0.000000 |            0 |             0 |
| end                  | 0.000012 | 0.000007 |   0.000000 |            0 |             0 |
| query end            | 0.000012 | 0.000012 |   0.000000 |            0 |             0 |
| closing tables       | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| freeing items        | 0.000187 | 0.000188 |   0.000000 |            0 |             0 |
| cleaning up          | 0.000017 | 0.000015 |   0.000000 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
17 rows in set, 1 warning (0.00 sec)

show profile常用查询参数：

• all：显示所有的开销信息。
• block io：显示块io开销。
• context switches： 上下文切换开销。
• cpu：显示cpu开销信息。
• ipc：显示发送和接受开销信息。
• memory：显示内存开销信息。
• page faults：显示页面错误开销信息。
• source：显示和 source_function,source_file,source_line 相关的开销信息。
• swaps：显示交换次数开销信息。

那我们通过 show profile 查看资源消耗，如何判定一个sql 是否需要优化呢，这里列举出 4 点，如果在诊断结果中出现以下情况，则说明sql需要优化：

• converting HEAP to MyISAM：查询结果太大，内存不够，数据往磁盘上搬了。
• Creating tmp table：创建临时表。先拷贝数据到临时表，用完后再删除临时表。
• Copying to tmp table on disk：把内存中临时表复制到磁盘上，警惕！
• locked。

查看慢sql执行成本

我们可以将慢查询日志中的sql拿出来，在当前会话中执行一次，并分析其资源消耗情况。

mysql> show profiles;
+----------+------------+------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                  |
+----------+------------+------------------------------------------------------------------------+
|       31 | 0.69543050 | select sql_no_cache * from student where age = 19 and name like '%xefobsK%'  |
+----------+------------+------------------------------------------------------------------------+
7 rows in set, 1 warning (0.00 sec)

mysql> show profile for query 31;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000096 |
| Executing hook on transaction  | 0.000007 |
| starting                       | 0.000008 |
| checking permissions           | 0.000007 |
| Opening tables                 | 0.000060 |
| init                           | 0.000026 |
| System lock                    | 0.000012 |
| optimizing                     | 0.000030 |
| statistics                     | 0.000022 |
| preparing                      | 0.000041 |
| executing                      | 0.694731 |
| end                            | 0.000014 |
| query end                      | 0.000005 |
| waiting for handler commit     | 0.000045 |
| closing tables                 | 0.000014 |
| freeing items                  | 0.000117 |
| logging slow query             | 0.000166 |
| cleaning up                    | 0.000032 |
+--------------------------------+----------+
18 rows in set, 1 warning (0.00 sec)

根据 show profile 的结果，我们发现sql在 executing 阶段消耗了0.694秒，所以判定此sql是在执行阶段慢了，就说明我们的sql 存在问题，所以接下来，需要通过 explain来做针对性的分析。

分析查询语句：explain

我们在编写完一个sql 执行后，mysql底层优化器并不一定会按照我们编写的sql来运行。比如我们在sql中使用了索引字段，优化器执行时并不一定使用索引；再比如我们写了子查询，优化器可能会优化成多表join方式来执行……

我们需要通过 explain关键字，来帮助我们查看sql的查询方式，比如多表连接的顺序、是否使用索引等等。有关 explain 的用法，由于细节众多，这里就不一一介绍了，后面会单独发布一篇《explain用法案例剖析》文章。

所以针对慢查询日志中的sql，我们使用 explain 来分析一下：

mysql> explain select sql_no_cache * from student where age = 19 and name like '%xefobsK%';
+----+-------------+---------+------------+------+---------------+------+---------+------+--------+----------+-------------+
| id | select_type | table   | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra       |
+----+-------------+---------+------------+------+---------------+------+---------+------+--------+----------+-------------+
|  1 | SIMPLE      | student | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 998089 |     1.11 | Using where |
+----+-------------+---------+------------+------+---------------+------+---------+------+--------+----------+-------------+
1 row in set, 2 warnings (0.00 sec)

这里看几个重要指标：

• type：type的值是 all，最熟悉的全表扫描，效率多低就不用再多介绍了。
• key： key为null，说明一个索引都没有用到。
• key_len：索引都没有用到，更别提索引长度了。
• rows：预计读取的记录条数，此值越小越好。表中总共100w条数据，这里值是99w多，不言而喻了。
• Extra：using where 表示搜索条件中，用到了非索引列的查询。

查询优化

针对上面分析出来的结果，我们需要对此查询进行优化。

1.我们发现在查询中没有用到索引，所以我们考虑对该表创建索引。

2.因为where 条件中用到了 age 和 name，所以我们需要针对这两个字段，创建联合索引。

mysql>  create index idx_age_name on student(age, name);
Query OK, 0 rows affected (8.07 sec)
Records: 0  Duplicates: 0  Warnings: 0

添加索引成功后，我们再用explain来查看下sql执行计划：

mysql> explain select sql_no_cache * from student where age = 19 and name like '%xefobsK%';
+----+-------------+---------+------------+------+---------------+--------------+---------+-------+--------+----------+-----------------------+
| id | select_type | table   | partitions | type | possible_keys | key          | key_len | ref   | rows   | filtered | Extra                 |
+----+-------------+---------+------------+------+---------------+--------------+---------+-------+--------+----------+-----------------------+
|  1 | SIMPLE      | student | NULL       | ref  | idx_age_name  | idx_age_name | 5       | const | 203772 |    11.11 | Using index condition |
+----+-------------+---------+------------+------+---------------+--------------+---------+-------+--------+----------+-----------------------+
1 row in set, 2 warnings (0.00 sec)

我们再去观察几个重要的属性：

• type：ref 说明用辅助索引的列与常量进行等值匹配了。
• key： idx_age_name ，已经用到我们创建的索引了。
• key_len：5，说明只是用到了联合索引中的age字段（int 4 + default null 1）。
• rows：20多w，比没加索引的99w 优化太多了。
• Extra：Using index condition。

此时我们再去执行慢查询中的sql：

mysql> select sql_no_cache * from student where age = 19 and name like '%xefobsK%';
+--------+----------+---------+------+----------+
| id     | stuno    | name    | age  | class_id |
+--------+----------+---------+------+----------+
| 999994 | 29999825 | xefobsK |   19 |     NULL |
+--------+----------+---------+------+----------+
1 row in set, 1 warning (0.04 sec)

我们发现，添加完索引之后的执行时间明显小于未添加索引的时间，且此时sql的耗时小于long_query_time的阈值，所以此sql已不属于慢sql，那基本就完成了我们想要达到的效果。

总结

通过以上案例，我们通过 slow_query_log 和 long_query_time 来定位到慢sql，然后通过 show profile 查看对应sql的执行成本，发现是在 执行阶段耗时后，又通过 explain 来分析sql，最后以添加索引的方式 来解决了慢sql的问题。

当遇到数据库调优问题的时候，我们可以把整个调优流程划分成 观察（show status）和行动（action）两个部分。字母 S 的部分代表观察（会使用相应的分析工具），字母 A 代表的是行动（对应分析可以采取的行动）。

以上添加索引的方式仅仅是sql优化的一种，当我们遇到了 通过索引方式也不能有效解决的时候，我们需要判定此sql 查询是否到达瓶颈，从而去考虑 是否做一些例如读写分离、分库分表等一系列的操作。