Saki's 研究记录

MySQL 优化--慢查询日志

docker mysql slow
字数统计: 2k阅读时长: 8 min
2023/11/30

环境信息

OS: macOS 14.1.1 (23B81)
Docker: 24.0.5
Image: mysql:8.0.21

慢查询定位

定位慢查询问题，可以通过如下几个步骤进行：

  • 开启慢日志；
  • 使用慢日志查询分析管理工具；
  • 基于已有的慢日志分析，对系统本身做优化。

开启慢日志

如何开启慢查询日志

1、查看慢查询日志是否开启
因为开启慢查询日志是有代价的（跟bin log、optimizer-trace一样），所以它默认是关闭的。
开启慢日志，执行命令：

1
2
3
4
5
6
7
8
9
show variables like 'slow%'；
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| slow_launch_time    | 2                                    |
| slow_query_log      | OFF                                  |
| slow_query_log_file | /var/lib/mysql/d1673994303e-slow.log |
+---------------------+--------------------------------------+
3 rows in set (0.00 sec)

可以看到slow_query_log属性是OFF，处于关闭状态，那么我们需要先开启慢查询。
slow_query_log_file表示慢查询日志文件的存放路径，我们可以自定义文件路径（mysql安装、运行在docker）：

1
set global slow_query_log_file = '路径'

开启慢查询日志

执行命令：

1
set global slow_query_log = on

然后再查询一下，发现slow_query_log处于开启状态：

1
2
3
4
5
6
7
8
9
show variables like 'slow%'；
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| slow_launch_time    | 2                                    |
| slow_query_log      | ON                                   |
| slow_query_log_file | /var/lib/mysql/d1673994303e-slow.log |
+---------------------+--------------------------------------+
3 rows in set (0.00 sec)

开启了之后，是不是所有的查询都会记录在文件里呢?
当然不是，慢查询日志，顾名思义是只记录查询比较慢的语句，那问题又来了，怎么才算查询比较慢的语句呢?
实际上，这里会有一个标准值，而且这个标准值是可以由我们自己设定的。

慢查询的临界值设定

首先查看一下默认的临界值。
执行命令：

1
2
3
4
5
6
7
8
9
10
11
show variables like '%long%';
+----------------------------------------------------------+-----------+
| Variable_name                                            | Value     |
+----------------------------------------------------------+-----------+
| long_query_time                                          | 10.000000 |
| performance_schema_events_stages_history_long_size       | 10000     |
| performance_schema_events_statements_history_long_size   | 10000     |
| performance_schema_events_transactions_history_long_size | 10000     |
| performance_schema_events_waits_history_long_size        | 10000     |
+----------------------------------------------------------+-----------+
5 rows in set (0.01 sec)

其中有一个long_query_time属性，它的值为10.000000。它表示的意思是，只记录查询时间在10s以上的语句。
显然10s我们是不可接受的，所以需要自己设定一下这个值。因为我的测试表中没有多少条数据XD，查询很快，所以这里把慢查询的临界值设置为1.00：

1
set long_query_time=1.00;

可以看到现在临界值是1.00秒了。

1
2
3
4
5
6
7
8
9
10
+----------------------------------------------------------+----------+
| Variable_name                                            | Value    |
+----------------------------------------------------------+----------+
| long_query_time                                          | 1.000000 |
| performance_schema_events_stages_history_long_size       | 10000    |
| performance_schema_events_statements_history_long_size   | 10000    |
| performance_schema_events_transactions_history_long_size | 10000    |
| performance_schema_events_waits_history_long_size        | 10000    |
+----------------------------------------------------------+----------+
5 rows in set (0.01 sec)

现在来模拟手动触发一个大于 1.00s 的慢查询(测试表中没有多少条数据，就直接用sleep测试了)，看是否都记录在了慢查询日志中。

1
SELECT sleep(3);

查看慢查询日志当中有多少条记录:

1
2
3
4
5
6
7
show global status like '%Slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 1     |
+---------------+-------+
1 row in set (0.02 sec)

看下慢查询日志(mysql安装、运行在docker)：

1
2
3
4
5
6
7
8
docker exec -it d1673994303e cat /var/lib/mysql/d1673994303e-slow.log
Time                 Id Command    Argument
SELECT sleep(11);
# Time: 2023-11-30T02:26:27.779482Z
# User@Host: df-test[df-test] @  [192.168.65.1]  Id:    15
# Query_time: 3.000820  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1701311184;
SELECT sleep(3);

可以看到刚才模拟查询的日志，从该日志中能看到如下几个信息（根据不同的MySQL版本或者配置，这些信息可能有增减）：
产生时间(Time)：2021-03-12T08:52:54.227174Z
来源(User@Host)： df-test[df-test] @ [192.168.65.1]，即用户 df-test在192.168.65.1这个机器上执行了这个查询
查询统计(Query_time)：如消耗的时间，发送/接收的行数
具体的SQL语句

需要注意的是，上面的操作是在命令行中进行的，如果数据库进行重启，这些设置都会失效。

一般不建议长期开启慢查询日志，如果要永久生效，需要修改配置文件：

1
2
3
4
5
vim /etc/mysql/my.cnf
[mysqld]
slow_query_log = 1
long_query_time = 1.0
slow_query_log_file =/var/lib/mysql/mysql_slow.log

在配置文件中加上这三行就可以了，但需要重启MySQL才能生效!

使用慢日志查询分析管理工具

有了慢查询日志，怎么去分析统计呢？比如SQL语句的出现的慢查询次数最多，平均每次执行了多久？人工肉眼分析显然不可能。
可以通过MySQL官方自带的mysqldumpslow工具进行分析，执行命令(mysql安装、运行在docker)：

1
docker exec -it d1673994303e mysqldumpslow --help

例如：查询用时最多的10条慢SQL语句：

1
2
3
4
5
6
docker exec -it d1673994303e mysqldumpslow -s t -t 10 -g 'select' /var/lib/mysql/d1673994303e-slow.log
Reading mysql slow query log from /var/lib/mysql/d1673994303e-slow.log
Count: 1  Time=3.00s (3s)  Lock=0.00s (0s)  Rows=1.0 (1), df-test[df-test] @ [192.168.65.1]
  SELECT sleep(N)

Died at /usr/bin/mysqldumpslow line 162, <> chunk 1.

Count： 代表这个 SQL 执行了多少次；
Time： 代表执行的时间，括号里面是累计时间；
Lock： 表示锁定的时间，括号是累计；
Rows： 表示返回的记录数，括号是累计。
官方文档地址。

慢查询语句解析

通过慢查询日志，针对性的去找到这些慢查询日志去进行explain分析 然后去调优创建索引。
执行命令：

1
explain (SQL语句)。

把上面执行的两条语句放一起对比解析一下：

1
2
3
4
5
6
7
explain SELECT sleep(3);
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra          |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+
|  1 | SIMPLE      | NULL  | NULL       | NULL | NULL          | NULL | NULL    | NULL | NULL |     NULL | No tables used |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+
1 row in set, 1 warning (0.01 sec)

需要重点关注possible_keys、key、rows这几个属性值。
possible_keys表示该语句可能会用到的索引
key表示该语句实际用到的索引
rows表示该语句扫描的行数

通过这些属性，可以大致的分析定位到慢查询的原因，然后针对性的去解决。

开启性能详情

如果通过explain语句解析没有定位到问题，该加的索引也加了，但是还是比较慢，那就可以通过性能详情来进一步的探究一下原因。
性能详情可以追踪查询语句的整个生命周期的状态，有了这些状态值，就可以从更深层次找出具体是哪个环节慢了，从而能针对性的进行改善。

查看性能详情是否开启

执行命令：

1
2
3
4
5
6
7
8
9
show variables like '%profiling%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.01 sec)

可以看到profiling属性值为OFF，表示关闭。
开启性能详情，执行命令：

1
set profiling = on;

当我们开启了之后，在数据库上执行的任何的SQL语句都会被记录来。

查看性能记录

我们执行一条SQL语句：

1
SELECT sleep(3);

然后查看性能记录：

1
2
3
4
5
6
7
8
show profiles;
+----------+------------+-----------------------------------+
| Query_ID | Duration   | Query                             |
+----------+------------+-----------------------------------+
|        1 | 0.00213600 | show variables like '%profiling%' |
|        2 | 3.00362525 | SELECT sleep(3)                   |
+----------+------------+-----------------------------------+
2 rows in set, 1 warning (0.00 sec)

可以看到开启后的所有查询语句的记录。我们想查看一下第二条执行语句的整个执行周期的状态详情(SQL慢要么是CPU计算复杂,要么是IO频繁开销所以只看CPU和block io即可)：
执行命令：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
show profile cpu,block io for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.001054 | 0.001007 |   0.000000 |            0 |             0 |
| checking permissions | 0.000051 | 0.000050 |   0.000000 |            0 |             0 |
| Opening tables       | 0.000131 | 0.000131 |   0.000000 |            0 |             0 |
| init                 | 0.000061 | 0.000061 |   0.000000 |            0 |             0 |
| optimizing           | 0.000048 | 0.000047 |   0.000000 |            0 |             0 |
| executing            | 0.000125 | 0.000125 |   0.000000 |            0 |             0 |
| User sleep           | 3.000136 | 0.013049 |   0.001498 |            0 |             0 |
| end                  | 0.000063 | 0.000061 |   0.000000 |            0 |             0 |
| query end            | 0.000071 | 0.000070 |   0.000000 |            0 |             0 |
| closing tables       | 0.000029 | 0.000030 |   0.000000 |            0 |             0 |
| freeing items        | 0.000288 | 0.000000 |   0.000308 |            0 |             0 |
| logging slow query   | 0.001375 | 0.000009 |   0.000540 |            0 |             0 |
| cleaning up          | 0.000195 | 0.000134 |   0.000079 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
13 rows in set, 1 warning (0.00 sec)

可以看到整条SQL语句执行过程每个状态的耗时情况。然后定位到具体是哪个状态最耗时，然后针对性的排查原因。
官方也给出了每个状态的解释，具体可查看官方文档地址。

总结

以上是定位MySQL慢日志查询问题的步骤总结。在实际应用过程中，要多尝试不同维度的解决方案，并结合自身所处行业、业务等特点，挑选适合自己和团队使用的数据库分析工具，保障系统和业务的稳定。

以上。

原文作者：Saki Shum

原文链接：https://sakishum.com/2023/11/30/MySQL-%E4%BC%98%E5%8C%96-%E6%85%A2%E6%9F%A5%E8%AF%A2%E6%97%A5%E5%BF%97/

发表日期：十一月 30日 2023, 11:57:16 中午

更新日期：十二月 17日 2023, 3:16:04 下午

版权声明：本文采用知识共享署名-非商业性使用 4.0 国际许可协议进行许可

CATALOG
  1. 1. 环境信息
  2. 2. 慢查询定位
  • 开启慢日志
    1. 1. 如何开启慢查询日志
    2. 2. 开启慢查询日志
    3. 3. 慢查询的临界值设定
  • 使用慢日志查询分析管理工具
    1. 1. 慢查询语句解析
  • 开启性能详情
    1. 1. 查看性能详情是否开启
    2. 2. 查看性能记录
  • 总结
    • Total : 98
    2024
    2023
    2022
    2021
    python docker Elasticsearch error nginx minio pip docker-compose ETCD openresty golang go generate yum Mac appine git Linux etcd vue MySQL hexo chart go modules vue.js SEO google samba mount fstab cifs huginn webpushr elasticsearch plantuml jupyter notebook centos ssl linux smtp mysql musl macos ubuntu wish private pandas talib alpine sqlite3 df code inspirational article redis embed crosstool-ng nodejs postgres mac brew trash command brave m1 c++ chipmunk tool pyroscope tools ansible zinc yarn license terminal k3s multipass rust gitlab minikube helm dockerfile github temporal demo mac m1 watchdog redisson java openjdk wails slice append trap vite vue3 ts slow netstat socket tcpdump Kibana leetcode blind-75 algorithm tips naive-ui scss search npm qa goroutine qr-code go grpc app tiny clicker sakishum App package typescript
    ETCD MySQL Hexo Docker Error Huginn Samba Golang Apple 量化 postgres nodejs