慢查询日志简介
慢查询日志是MySQL提供的一种日志记录形式,由SQL语句组成。用来记录在MySQL中响应时间超过阈值的语句,具体指运行时间超过long_query_time值的SQL,则会被记录到慢查询日志中。慢查询日志可用于查找执行时间较长的查询,因此可作为优化的候选对象。long_query_time的默认值为10,指运行10s以上的语句。
1 | 注意: |
慢查询相关参数
这里列出5.7版本中与慢查询相关的参数和描述,参考官网
系统变量 及命令行格式 |
作用域及动态设置 |
取值及默认值 |
描述 |
---|---|---|---|
slow_query_log –slow-query-log[={OFF/ON}] |
全局 YES |
OFF/ON OFF |
是否启用慢查询日志 |
long_query_time –long-query-time=# |
全局/会话 Yes |
[0-xxx] 10 |
慢查询时间阈值 |
min_examined_row_limit –min-examined-row-limit=# |
全局/会话 Yes |
[0-xxx] 0 |
扫描行数少于此值不会记录慢查询日志 |
log_slow_admin_statements –log-slow-admin-statements[={OFF/ON}] |
全局 Yes |
OFF/ON OFF |
是否记录管理语句,包括 ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE. |
log_queries_not_using_indexes –log-queries-not-using-indexes[={OFF/ON}] |
全局 Yes |
OFF/ON 0 |
未使用索引的语句是否记录到慢查询日志 |
log_throttle_queries_not_using_indexes –log-throttle-queries-not-using-indexes=# |
全局 Yes |
[0-xxx] 0 |
当log_queries_not_using_indexes开启,此参数用来限制每分钟记录到慢查询日志的数量 |
log_output –log-output=name |
全局 Yes |
TABLE/FILE/NONE FILE |
记录general_log和slow.log的日志存储方式 |
slow_query_log_file –slow-query-log-file=file_name |
全局 Yes |
string hostname-slow.log |
慢查询日志文件的名称 |
- –log-short-format[={OFF/ON}] |
全局 - |
OFF/ON OFF |
慢查询日志记录更少的信息 |
log_slow_slave_statements –log-slow-slave-statements[={OFF/ON}] |
全局 YES |
OFF/ON OFF |
作为从库时生效,从库复制中如何有慢sql也将被记录,当binlog格式为的ROW时不生效。并且设置此值不会立即生效,变量的状态应用于所有后续的START SLAVE语句。 |
慢查询日志内容
1 |
|
慢查询参数控制顺序
管理语句
- 开启慢查询:slow_query_log=ON
- 开启管理语句记录:log_slow_admin_statements = ON
- 关闭未使用索引的记录:log_queries_not_using_indexes=OFF
- 关闭从库同步过来是否记录:log_slow_slave_statements=OFF
- 设置min_examined_row_limit:10000
设置慢查询阈值:0.5s
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45[root@localhost][test][02:21:36]> set global log_slow_admin_statements = ON;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:21:57]> set global log_queries_not_using_indexes = OFF;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:22:03]> set global log_slow_slave_statements = OFF;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:22:08]> set global min_examined_row_limit = 10000;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:22:14]> set global long_query_time = 0.5;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:22:21]> set global slow_query_log_file = 'slow0001.log';
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:22:32]> select * from performance_schema.global_variables where variable_name in ('slow_query_log','long_query_time','min_examined_row_limit','log_slow_admin_statements','log_queries_not_using_indexes','log_throttle_queries_not_using_indexes','log_output','slow_query_log_file','log_slow_slave_statements');
+----------------------------------------+----------------+
| VARIABLE_NAME | VARIABLE_VALUE |
+----------------------------------------+----------------+
| log_output | FILE |
| log_queries_not_using_indexes | OFF |
| log_slow_admin_statements | ON |
| log_slow_slave_statements | OFF |
| log_throttle_queries_not_using_indexes | 10 |
| long_query_time | 0.500000 |
| min_examined_row_limit | 10000 |
| slow_query_log | ON |
| slow_query_log_file | slow0001.log |
+----------------------------------------+----------------+
9 rows in set (0.00 sec)
# 退出下session,重新建立
[root@localhost][test][02:22:51]> alter table employee1 engine = innodb;
Query OK, 0 rows affected (1.00 sec)
Records: 0 Duplicates: 0 Warnings: 0
# 查看slow.log
Tcp port: 3306 Unix socket: /opt/mysql3306/data/mysql.sock
Time Id Command Argument
# 此时慢查询日志没有记录alter table employee1 engine = innodb;在以上参数基础上,设置min_examined_row_limit为0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28[root@localhost][test][02:22:58]> set session min_examined_row_limit = 0;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][02:24:32]> alter table employee1 engine = innodb;
Query OK, 0 rows affected (1.09 sec)
Records: 0 Duplicates: 0 Warnings: 0
[root@localhost][test][02:25:22]> alter table employee1 modify employeeid int(10) unsigned NOT NULL COMMENT '0',algorithm=copy;
Query OK, 9999 rows affected, 1 warning (0.94 sec)
Records: 9999 Duplicates: 0 Warnings: 1
# 查看slow.log
Tcp port: 3306 Unix socket: /opt/mysql3306/data/mysql.sock
Time Id Command Argument
# Time: 2020-06-03T14:24:35.704816+08:00
# User@Host: root[root] @ localhost [] Id: 15
# Query_time: 1.089764 Lock_time: 0.000209 Rows_sent: 0 Rows_examined: 0
use test;
SET timestamp=1591165474;
alter table employee1 engine = innodb;
# Time: 2020-06-03T14:25:50.639222+08:00
# User@Host: root[root] @ localhost [] Id: 21
# Query_time: 0.939964 Lock_time: 0.000218 Rows_sent: 0 Rows_examined: 0
SET timestamp=1591165549;
alter table employee1 modify employeeid int(10) unsigned NOT NULL COMMENT '0',algorithm=copy;
# 02:22:58 设置的min_examined_row_limit为0
# 02:24:32 再次执行的alter,记录到了slow.log
总结:
慢查询管理语句的记录受参数log_slow_admin_statements、min_examined_row_limit的影响,并不受long_query_time影响。
alter table … ,algorithm=copy;时执行完成显示Query OK, 9999 rows affected,实际慢查询记录的Rows_sent、Rows_examined全是0
查询语句(利用索引)
- 开启慢查询:slow_query_log=ON
- 开启管理语句记录:log_slow_admin_statements = OFF
- 关闭未使用索引的记录:log_queries_not_using_indexes=OFF
- 关闭从库同步过来是否记录:log_slow_slave_statements=OFF
- 设置min_examined_row_limit:10001
设置慢查询阈值:0.0000001s
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42[root@localhost][test][03:14:29]> select * from performance_schema.global_variables where variable_name in ('slow_query_log','long_query_time','min_examined_row_limit','log_slow_admin_statements','log_queries_not_using_indexes','log_throttle_queries_not_using_indexes','log_output','slow_query_log_file','log_slow_slave_statements');
+----------------------------------------+----------------+
| VARIABLE_NAME | VARIABLE_VALUE |
+----------------------------------------+----------------+
| log_output | FILE |
| log_queries_not_using_indexes | OFF |
| log_slow_admin_statements | OFF |
| log_slow_slave_statements | OFF |
| log_throttle_queries_not_using_indexes | 10 |
| long_query_time | 0.500000 |
| min_examined_row_limit | 10000 |
| slow_query_log | ON |
| slow_query_log_file | slow0001.log |
+----------------------------------------+----------------+
9 rows in set (0.00 sec)
[root@localhost][test][03:14:31]> set session long_query_time = 0.0000001;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][03:14:39]> set session min_examined_row_limit = 10001;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][03:14:44]> explain select count(*) from employee1 where update_time > '20200501';
+----+-------------+-----------+--------------+-------+---------------+---------+---------+------+------+----------+--------------------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+-----------+--------------+-------+---------------+---------+---------+------+------+----------+--------------------------+
| 1 | SIMPLE | employee1 | P202005,PMAX | range | PRIMARY | PRIMARY | 5 | NULL | 4999 | 100.00 | Using where; Using index |
+----+-------------+-----------+--------------+-------+---------------+---------+---------+------+------+----------+--------------------------+
1 row in set, 1 warning (0.00 sec)
[root@localhost][test][03:14:48]> select count(*) from employee1 where update_time > '20200501';
+----------+
| count(*) |
+----------+
| 9999 |
+----------+
1 row in set (0.01 sec)
[root@localhost][test][03:14:53]>
# 查看slow log,此时并没有记录
# 由于select count(*) from employee1 where update_time > '20200501';扫描行数为4999,小于min_examined_row_limit设置的10001,并且执行时长是大于0.0000001s将min_examined_row_limit修改为3000
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21[root@localhost][test][03:15:01]> set session min_examined_row_limit = 3000;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][03:15:06]> select count(*) from employee1 where update_time > '20200501';
+----------+
| count(*) |
+----------+
| 9999 |
+----------+
1 row in set (0.00 sec)
[root@localhost][test][03:15:08]>
# 查看slow log
# Time: 2020-06-03T15:15:08.108595+08:00
# User@Host: root[root] @ localhost [] Id: 17
# Query_time: 0.002721 Lock_time: 0.000141 Rows_sent: 1 Rows_examined: 9999
SET timestamp=1591168508;
select count(*) from employee1 where update_time > '20200501';
# 此时语句记录到了slow log,select count(*) from employee1 where update_time > '20200501';扫描行数为4999,大于min_examined_row_limit设置的3000,并且执行时长是大于0.0000001s
总结:
查询语句(使用索引)的SQL,扫描行数大于min_examined_row_limit的前提下,执行时长如果大于long_query_time则会记录,小于则不会记录;
扫描行数小于min_examined_row_limit的前提下,执行时长的参数设置就不生效;
查询语句(不走索引)
- 开启慢查询:slow_query_log=ON
- 开启管理语句记录:log_slow_admin_statements = OFF
- 关闭未使用索引的记录:log_queries_not_using_indexes=ON
- 每分钟记录未索引的次数:log_throttle_queries_not_using_indexes=10
- 关闭从库同步过来是否记录:log_slow_slave_statements=OFF
- 设置min_examined_row_limit:10000
设置慢查询阈值:0.5s
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34[root@localhost][test][03:31:11]> select * from performance_schema.global_variables where variable_name in ('slow_query_log','long_query_time','min_examined_row_limit','log_slow_admin_statements','log_queries_not_using_indexes','log_throttle_queries_not_using_indexes','log_output','slow_query_log_file','log_slow_slave_statements');
+----------------------------------------+----------------+
| VARIABLE_NAME | VARIABLE_VALUE |
+----------------------------------------+----------------+
| log_output | FILE |
| log_queries_not_using_indexes | ON |
| log_slow_admin_statements | OFF |
| log_slow_slave_statements | OFF |
| log_throttle_queries_not_using_indexes | 10 |
| long_query_time | 0.500000 |
| min_examined_row_limit | 10000 |
| slow_query_log | ON |
| slow_query_log_file | slow0001.log |
+----------------------------------------+----------------+
9 rows in set (0.00 sec)
[root@localhost][test][03:31:15]> select sleep(1);
+----------+
| sleep(1) |
+----------+
| 0 |
+----------+
1 row in set (1.00 sec)
[root@localhost][test][03:31:36]> select sleep(0.1);
+-------------+
| sleep(0.01) |
+-------------+
| 0 |
+-------------+
1 row in set (0.01 sec)
# 查看slow log,没有记录日志
# 由于select sleep(1);扫描行数为0,小于min_examined_row_limit的10000,不管sql执行时长有没有大于long_query_time都不会记录将min_examined_row_limit修改为0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48[root@localhost][test][03:31:31]> set session min_examined_row_limit = 0;
Query OK, 0 rows affected (0.00 sec)
[root@localhost][test][03:31:45]> select sleep(1);
+----------+
| sleep(1) |
+----------+
| 0 |
+----------+
1 row in set (1.00 sec)
[root@localhost][test][03:31:55]> select sleep(0.1);
+------------+
| sleep(0.1) |
+------------+
| 0 |
+------------+
1 row in set (0.10 sec)
[root@localhost][test][03:31:59]> select sleep(0.4);
+------------+
| sleep(0.4) |
+------------+
| 0 |
+------------+
1 row in set (0.40 sec)
[root@localhost][test][03:32:18]> select sleep(0.6);
+------------+
| sleep(0.6) |
+------------+
| 0 |
+------------+
1 row in set (0.60 sec)
# 查看slow log
# Time: 2020-06-03T15:31:55.890178+08:00
# User@Host: root[root] @ localhost [] Id: 19
# Query_time: 1.000207 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1591169514;
select sleep(1);
# Time: 2020-06-03T15:32:20.820796+08:00
# User@Host: root[root] @ localhost [] Id: 19
# Query_time: 0.600206 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1591169540;
select sleep(0.6);
# 此时select sleep(1);select sleep(0.6);记录到了慢查询日志,大于min_examined_row_limit的0,满足了long_query_time会记录,不满足long_query_time不会记录
总结:
查询语句(不走索引)的SQL,扫描行数大于min_examined_row_limit的前提下,执行时长如果大于long_query_time则会记录,小于则不会记录;
扫描行数小于min_examined_row_limit的前提下,执行时长的参数设置就不生效;
其他参数
其他参数暂时未做测试
生产建议
1 | +----------------------------------------+----------------+ |
将log_queries_not_using_indexes设置为OFF的原因是,生产环境可能会有多套监控,当库中表或者其他对象过多时,监控的统计语句或者检索语句因大多从information_schema元数据库取数据,没有走索引,slow log可以会占比较多,会淹没正常的告警。生产的慢SQL完全依赖min_examined_row_limit和long_query_time及log_slow_admin_statements来控制,一类是DDL,别一类正常的DML。
慢查询日志分析工具
1.官方自带工具: mysqldumpslow
2.percona-toolkit工具包中的pt-query-digest
总结
MySQL日常运维工作中,慢查询日志的优化工作能占到日常工作的30%以上,因此对慢查询产生的时机,相关参数,输出内容要有清楚的认识,才能更好的去运维MySQL,最大化的优化慢查询语句,提高数据库服务的稳定性。