mysql慢查询分析

当我们开始关注数据库整体性能优化时，我们需要一套 MySQL 查询分析工具。特别是在开发中大型项目时，往往有数百个查询分布在代码库中的各个角落，并实时对数据库进行大量访问和查询。如果没有一套趁手的分析方法和工具，就很难发现在执行过程中代码的效率瓶颈，MySQL Server 内置的查询分析工具 —— 慢查询日志、mysqldumpslow、Profiling等可以帮助我们发现分析这些问题。

慢查询日志

慢查询日志是什么？

MySQL 慢查询日志是用来记录 MySQL 在执行命令中，响应时间超过预设阈值的 SQL 语句。

记录这些执行缓慢的 SQL 语句是优化 MySQL 数据库效率的第一步。

默认情况下，慢查询日志功能是关闭的，需要我们手动打开。当然，如果不是调优需求的话，一般也不建议长期启动这个功能，因为开启慢查询多少会对数据库的性能带来一些影响。慢查询日志支持将记录写入文件，当然也可以直接写入数据库的表中。一般通过慢查询日志可以解决大部分问题。

配置并打开慢查询日志

在 MySQL Server 中临时开启慢查询功能

在 MySQL Server 中，默认情况慢查询功能是关闭的，我们可以通过查看此功能的状态

1

show variables like 'slow_query_log';

slow_query_log

如上图所示，慢查询日志（slow_query_log ）的状态为关闭。

我们可以使用以下命令开启并配置慢查询日志功能，在 mysql 中执行以下命令：

1
2
3
4
5


SET GLOBAL slow_query_log = 'ON';# 开启慢查询日志
SET GLOBAL slow_query_log_file = 'slow.log';# 指定慢查询日志文件
SET GLOBAL log_queries_not_using_indexes = 'ON'; # 开启慢查询日志，并记录不使用索引的查询
SET SESSION long_query_time = 1; # 设置慢查询时间阈值，单位为秒
SET SESSION min_examined_row_limit = 100; # 设置慢查询时，查询的最小行数

简单测试：

1
2


SET SESSION min_examined_row_limit = 0; # 设置结果只有一条记录也记录，方便测试；
select sleep(2);

查询被日志记录：

1
2
3
4
5
6
7
8


mysqld, Version: 5.7.36 (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2022-05-11T01:44:29.382572Z
# User@Host: root[root] @ localhost []  Id:     2
# Query_time: 2.000406  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1652233469;
select sleep(2);

**注意：**日志的位置如果指定的是相对位置slow.log，那么日志文件会被放在mysql的默认位置，即：/var/lib/mysql/slow.log。

慢查询日志记录参数详解

上图中日志中信息的说明：

Time ：被日志记录的代码在服务器上的运行时间。
User@Host：谁执行的这段代码。
Query_time：这段代码运行时长。
Lock_time：执行这段代码时，锁定了多久。
Rows_sent：慢查询返回的记录。
Rows_examined：慢查询扫描过的行数。

特别注意：

在实践中常常会碰到无论慢查询阈值long_query_time调到多小，日志就是不被记录。这个问题很有可能是min_examined_row_limit行数过大，导致没有被记录。min_examined_row_limit在配置中常被忽略，这里要特别注意。

以上修改 MySQL 慢查询配置的方法是用在临时监测数据库运行状态的场景下，当 MySQL Server 重启时，以上修改全部失效并恢复原状。

将慢查询设置写入 MySQL 配置文件，永久生效

虽然我们可以在命令行中对慢查询进行动态设置，但动态设置会随着重启服务而失效。如果想长期开启慢查询功能，需要把慢查询的设置写入 MySQL 配置文件中，这样无论是重启服务器，还是重启 MySQL ，慢查询的设置都会保持不变。

1

sudo find /etc -name my.cnf

找到位置后，编辑 my.cnf 将慢查询设置写入配置文件。

sudo vi /etc/mysql/my.cnf

1
2
3
4
5
6
7
8


[mysqld]

slow-query-log = 1
slow-query-log-file = slow.log
long_query_time = 1
SET GLOBAL log_queries_not_using_indexes = 1;
SET long_query_time = 10;
SET min_examined_row_limit = 0;

重启mysql生效；

清空日志文件

如果日志文件太大，需要清空：

1
2
3


mv slow.log slow.log.bak # 备份文件
#在mysql的命令行中执行flush logs命令,清空日志文件，就会在新文件中写日志，不然一直写入在原文件中。
flush logs

这时候自动会生成新的slow.log文件，并写入日志。注意：在docker中，日志文件是在/var/lib/mysql/目录下的，mv操作需要进入容器内操作，使用docker exec命令，不含会报找不到slow.log文件的错，这是因为mysql拥有文件的引用，如果没有在系统内改名字，但是mysql并没有更新。

使用 mysqldumpslow 工具对慢查询日志进行分析

实际工作中，慢查询日志可不像上文描述的那样，仅仅有几行记录。现实中慢查询日志会记录大量慢查询信息，写入也非常频繁。日志记录的内容会越来越长，分析数据也变的困难。好在 MySQL 内置了 mysqldumpslow 工具，它可以把相同的 SQL 归为一类，并统计出归类项的执行次数和每次执行的耗时等一系列对应的情况。

我们先来执行几行代码让慢查询日志记录下来，然后再用 mysqldumpslow 进行分析。

上文我们把min_examined_row_limit 设置为 100，在这里，我们要将它改为 0 ，慢查询才能有记录。在 MySQL Server 中执行以下代码：

1

SET min_examined_row_limit = 0;

接着我们执行几条查询命令：

1
2
3


select * from shop_product where pprice = '34';
select * from shop_product where pprice = '45';
select * from shop_product where pprice = '45';

根据前文的慢查询设置，这三条记录都将被记录在日志中。

现在，我们切换到命令行的窗口中，执行 mysqldumpslow 命令：

1

sudo mysqldumpslow -s at /var/log/mysql/slow.log

返回的数据：

1
2
3


Reading mysql slow query log from /var/lib/mysql/slow.log
Count: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.7 (5), root[root]@localhost
  select * from shop_product where pprice = 'S'

我们可以看到，返回的数据中，已经把三条类似的 SQL 语句记录抽象成一条记录select * from shop_product where pprice = 'S' 并且针对这条记录列出了对应的总量和平均量的记录。

常见的 mysqldumpslow 命令平时大家也可以根据自己的常用需求来总结，存好这些脚本备用。

1
2
3
4
5


mysqldumpslow -s at -t 10 /var/log/mysql/slow.log：平均执行时长最长的前 10 条 SQL 代码。
mysqldumpslow -s al -t 10 /var/log/mysql/slow.log：平均锁定时间最长的前10条 SQL 代码。
mysqldumpslow -s c -t 10 /var/log/mysql/slow.log：执行次数最多的前10条 SQL 代码。
mysqldumpslow -a -g 'user' /var/log/mysql/slow.log：显示所有 user 表相关的 SQL 代码的具体值
mysqldumpslow -a /var/log/mysql/slow.log：直接显示 SQL 代码的情况。

常用的参数讲解：

-s
- al：平均锁定时间
- at：平均查询时间 [默认]
- ar：平均返回记录时间
- c：count 总执行次数
- l：锁定时间
- r：返回记录
- t：查询时间
- -t：返回前 N 条的数据
-g：可写正则表达，类似于 grep 命令，过滤出需要的信息。如，只查询 X 表的慢查询记录。
-r：rows sent 总返回行数。

mysqldumpslow 日志查询工具好用就好用在它特别灵活，又可以合并同类项式的分析慢查询日志。我们在日常工作的使用中，就能够体会 mysqldumpslow 的好用之处。

另外 mysqldumpslow 的使用参数也可在 MySQL 8.0 使用手册中找到。

Profilling - MySQL 性能分析工具

为了更精准的定位一条 SQL 语句的性能问题，我们需要拆分这条语句运行时到底在什么地方消耗了多少资源。我们可以使用 Profilling 工具来进行这类细致的分析。我们可通过 Profilling 工具获取一条 SQL 语句在执行过程中对各种资源消耗的细节。

进入 MySQL Server 后，执行以下代码，启动 Profilling

1
2


SET SESSION profiling = 1; 
SELECT @@profiling; # 检查 profiling 的状态

返回数据： 0 表示未开启，1 表示已开启。

执行需要定位问题的 SQL 语句。

1

select * from shop_product where pprice = '34';

查看 SQL 语句状态。

1

SHOW PROFILES;

打开 profiling 后，SHOW PROFILES; 会显示一个将 Query_ID 链接到 SQL 语句的表。

1
2
3
4
5
6


+----------+------------+------------------------------------------------+
| Query_ID | Duration   | Query                                          |
+----------+------------+------------------------------------------------+
|        1 | 0.00034000 | SELECT @@profiling                             |
|        2 | 0.00039800 | select * from shop_product where pprice = '34' |
+----------+------------+------------------------------------------------+

Query_ID：SQL 语句的 ID 编号。
Duration：SQL 语句执行时长。
Query：具体的 SQL 语句。

执行以下 SQL 代码，将 [# Query_ID] 替换为我们要分析的 SQL 代码Query_ID的编号。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23


# SHOW PROFILE CPU, BLOCK IO FOR QUERY [# Query_ID];

mysql> SHOW PROFILE CPU, BLOCK IO FOR QUERY 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000122 | 0.000013 |   0.000026 |            0 |             0 |
| checking permissions | 0.000005 | 0.000002 |   0.000003 |            0 |             0 |
| Opening tables       | 0.000010 | 0.000003 |   0.000007 |            0 |             0 |
| init                 | 0.000013 | 0.000004 |   0.000008 |            0 |             0 |
| System lock          | 0.000052 | 0.000018 |   0.000035 |            0 |             0 |
| optimizing           | 0.000006 | 0.000002 |   0.000004 |            0 |             0 |
| statistics           | 0.000026 | 0.000008 |   0.000017 |            0 |             0 |
| preparing            | 0.000025 | 0.000009 |   0.000017 |            0 |             0 |
| executing            | 0.000001 | 0.000000 |   0.000001 |            0 |             0 |
| Sending data         | 0.000054 | 0.000018 |   0.000036 |            0 |             0 |
| end                  | 0.000003 | 0.000001 |   0.000001 |            0 |             0 |
| query end            | 0.000021 | 0.000007 |   0.000014 |            0 |             0 |
| closing tables       | 0.000003 | 0.000001 |   0.000003 |            0 |             0 |
| freeing items        | 0.000023 | 0.000008 |   0.000015 |            0 |             0 |
| logging slow query   | 0.000029 | 0.000009 |   0.000019 |            0 |             8 |
| cleaning up          | 0.000006 | 0.000002 |   0.000004 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+

Status 是执行查询过程中的具体步骤，Duration 是完成该步骤所需的时间（以秒为单位）。我们可以根据这些细节来具体分析，如何优化对应的 SQL 代码。

慢查询教程总结

慢查询是让我们看到数据库真实运行状态的工具，对服务器和数据库性能优化有着指导性的意义。无论是生产环境、开发、QA，都可以谨慎的打开慢查询来记录性能日志。

我们可以先把动态变量long_query_time 设置的大一些，观察一下，然后在进行微调。有了慢查询日志，我们就有了优化性能的方向和目标，再使用 mysqldumpslow 和 profiling 进行宏观和微观的日志分析。找到低效 SQL 语句的细节，进行微调，最终使我们的系统可以获得最佳执行性能。