slow_query_log
2019-07-11 本文已影响0人
左轮Lee
与慢查询相关的参数说明：
+------------------------------------------+------------------------+--------------------------------------------------------------------------
| Variable_name | Value | Content
+------------------------------------------+------------------------+--------------------------------------------------------------------------
| slow_query_log | ON |打开慢查询，默认为关闭OFF
| long_query_time | 1.000000 |定义慢查询时间，执行时间超过1s的sql才会记录到slow log
| log_output | FILE |定义日志(general_log and slow_log)存放方式，FILE/TABLE/NONE
| slow_query_log_file | D:\mysql\data\slow.log |慢日志存放的文件
| log_queries_not_using_indexes | OFF |5.6.5版本之后新增，记录任何不使用索引的sql
| log_throttle_queries_not_using_indexes | 0 |5.6.5版本之后新增，用来限制相同sql每分钟写slow log的频率，默认0，不限制
| log_slow_admin_statements | OFF |5.6.11版本后新增，记录执行慢的管理操作，如ALTER/CREATE INDEX/ANALYZE TABLE
| min_examined_row_limit | 0 |sql返回值小于设置的值则不记录到slow log，可设置为100
| log_slow_slave_statements | OFF |在从服务器开启慢查询日志
+------------------------------------------+------------------------+--------------------------------------------------------------------------
慢日志格式化工具：
mysqldumpslow
pt-query-digest
验证：
1.版本：5.7.25-log
2.表存储引擎：InnoDB
3.开启慢查询，设置慢查询1s
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)
mysql> set global long_query_time=1;
Query OK, 0 rows affected (0.00 sec)
场景一：实际执行时间超过1s的全表查询
select * from t_count ;
-- 查看slow_log D:\mysql\mysql-5.7.25-winx64\data\PC-20190305OQKR-slow.log
D:\mysql\mysql-5.7.25-winx64\bin\mysqld, Version: 5.7.25-log (MySQL Community Server (GPL)). started with:
TCP Port: 3306, Named Pipe: MySQL
Time Id Command Argument
# Time: 2019-07-11T02:19:57.199989Z
# User@Host: root[root] @ localhost [127.0.0.1] Id: 42
# Query_time: 29.290112 Lock_time: 0.000123 Rows_sent: 8713478 Rows_examined: 8713478
SET timestamp=1562811597;
select *from t_count;
此SQL的查询时间：Query_time: 29.290112，超过1s，被记录到 slow_log 中。
场景二：实际执行时间超过1s且有锁等待的更新
-- session 1 开启事务，执行更新，不提交
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> update t_innodb set supplier ='Ali' limit 1;
Query OK, 0 rows affected (0.02 sec)
Rows matched: 1 Changed: 0 Warnings: 0
-- session 2 执行更新后再提交session 1的事务
mysql> update t_innodb set supplier ='Ali' limit 1000000;
等待中ing
-- 提交session 1事务
情况一：在session 2执行后的1s内完成session 1的事务提交；
情况二：在session 2执行后等待1s以上再完成session 1的事务提交。
-- 查看 slow_log
D:\mysql\mysql-5.7.25-winx64\bin\mysqld, Version: 5.7.25-log (MySQL Community Server (GPL)). started with:
TCP Port: 3306, Named Pipe: MySQL
Time Id Command Argument
####### 情况一的session 2对应的更新语句
# Time: 2019-07-11T02:27:45.968064Z
# User@Host: root[root] @ localhost [::1] Id: 41
# Query_time: 4.147952 Lock_time: 0.365963 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1562812065;
update t_innodb set supplier ='Ali' limit 1000000;
####### 情况二的session 2对应的更新语句
# Time: 2019-07-11T02:34:05.315304Z
# User@Host: root[root] @ localhost [::1] Id: 41
# Query_time: 8.287104 Lock_time: 5.597558 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1562812445;
update t_innodb set supplier ='Ali' limit 1000000;
可见两次都记录到了slow_log中
因为两种情况的 Query_time 均大于1s
那么是不是只要 Query_time > 1s 就都会记录到 slow_log 呢？ 看第三个场景。
场景三：实际执行时间小于1s且锁等待超过1s的更新
-- session 1 开启事务，执行更新，不提交
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> update t_innodb set supplier ='Ali' limit 1;
Query OK, 0 rows affected (0.02 sec)
Rows matched: 1 Changed: 0 Warnings: 0
-- session 2 执行更新后等待2s回到session 1 提交事务
mysql> update t_innodb set supplier ='Ali' limit 1000;
等待中ing
-- session 1 提交
等待1s以上然后提交session 1，session 2 返回下面的信息，更新完成
Query OK, 0 rows affected (11.22 sec)
Rows matched: 1000 Changed: 0 Warnings: 0
-- 查看slow_log
发现慢日志中并不没有记录这个sql
调整long_query_time到很小的值，使得慢日志记录此sql，然后查看详细信息
set global long_query_time=0.0001；
重新打开两个session，重复上面的操作
-- 再次查看slow_log
Time Id Command Argument
# Time: 2019-10-17T02:45:17.282337Z
# User@Host: root[root] @ localhost [::1] Id: 18196
# Query_time: 0.024622 Lock_time: 0.022905 Rows_sent: 0 Rows_examined: 1
use test1;
SET timestamp=1571280317;
update t_innodb set supplier ='Ali' limit 1;
# Time: 2019-10-17T02:45:44.956452Z
# User@Host: root[root] @ localhost [::1] Id: 18197
# Query_time: 11.219081 Lock_time: 11.189756 Rows_sent: 0 Rows_examined: 1000
SET timestamp=1571280344;
update t_innodb set supplier ='Ali' limit 1000;
两次更新都记录到了慢日志中，主要看第二个SQL
此处Query_time: 11.219081，大于1s，但是未记录到慢日志，可见并不是按照 Query_time超过1s就记录到慢查询
结论：而是只有在sql真正执行时间(Query_time-Lock_time)超过1s的语句才会被记录。与锁等待时间无关。
场景四：开启参数log_queries_not_using_indexes
mysql> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)
-- 重新建立连接执行：
mysql> select * from t1;
+----+------+------+
| id | name | code |
+----+------+------+
| 1 | a | aa |
| 2 | b | NULL |
| 3 | c | NULL |
+----+------+------+
3 rows in set (0.00 sec)
-- 查看slow_log
# Time: 2019-07-11T06:09:47.127776Z
# User@Host: root[root] @ localhost [::1] Id: 46
# Query_time: 0.000763 Lock_time: 0.000648 Rows_sent: 3 Rows_examined: 3
SET timestamp=1562825387;
select * from t1;
全表扫描，虽然时间未超过1s，仍记录到了slow_log.
场景五：设置参数log_throttle_queries_not_using_indexes=3
mysql> set global log_throttle_queries_not_using_indexes=3 ;
Query OK, 0 rows affected (0.00 sec)
-- 重新建立连接执行下面sql 20次：
mysql> select * from t1;
+----+------+------+
| id | name | code |
+----+------+------+
| 1 | a | aa |
| 2 | b | NULL |
| 3 | c | NULL |
+----+------+------+
3 rows in set (0.00 sec)
-- 查看slow_log
# Time: 2019-07-11T06:15:05.414391Z
# User@Host: root[root] @ localhost [::1] Id: 47
# Query_time: 0.000827 Lock_time: 0.000692 Rows_sent: 3 Rows_examined: 3
SET timestamp=1562825705;
select * from t1;
# Time: 2019-07-11T06:15:06.086333Z
# User@Host: root[root] @ localhost [::1] Id: 47
# Query_time: 0.000206 Lock_time: 0.000083 Rows_sent: 3 Rows_examined: 3
SET timestamp=1562825706;
select * from t1;
# Time: 2019-07-11T06:15:06.708325Z
# User@Host: root[root] @ localhost [::1] Id: 47
# Query_time: 0.000131 Lock_time: 0.000056 Rows_sent: 3 Rows_examined: 3
SET timestamp=1562825706;
select * from t1;
1分钟之内仅记录3次。
场景六：开启 log_slow_admin_statements
mysql> set global log_slow_admin_statements =1;
Query OK, 0 rows affected (0.00 sec)
-- 重新建立连接执行下面sql ：
mysql> alter table t_innodb add col1 int ;
Query OK, 0 rows affected (26.57 sec)
Records: 0 Duplicates: 0 Warnings: 0
-- 查看slow_log
# Time: 2019-07-11T06:30:14.245466Z
# User@Host: root[root] @ localhost [::1] Id: 48
# Query_time: 26.575194 Lock_time: 0.005018 Rows_sent: 0 Rows_examined: 0
SET timestamp=1562826614;
alter table t_innodb add col1 int;
alter语句成功记录到slow log中。
场景六：设置参数 min_examined_row_limit=800000
mysql> set global min_examined_row_limit=800000;
Query OK, 0 rows affected (0.00 sec)
-- 重新建立连接执行下面sql ：
select * from t_innodb limit 700001 ;
查询时间：1.987s
-- 查看slow_log
未记录此慢sql。
