问题：开启慢查询日志后，超过long_query_time的操作哪些不会记录到慢日志文件中？

mysql> show global variables like '%slow%';

+---------------------------+-----------------------------+

| Variable_name | Value |

+---------------------------+-----------------------------+

| log_slow_admin_statements | OFF |

| log_slow_extra | OFF |

| log_slow_slave_statements | OFF |

| slow_launch_time | 2 |

| slow_query_log | ON |

| slow_query_log_file | /app/mysql/log/slow3306.log |

+---------------------------+-----------------------------+

6 rows in set (0.01 sec)

mysql> show global variables like 'long_query_time';

+-----------------+----------+

| Variable_name | Value |

+-----------------+----------+

| long_query_time | 1.000000 |

+-----------------+----------+

1 row in set (0.01 sec)

首先来看几种最普通的操作

（1）sleep

（2）正常的表查询

（3）查询过程中会话中断

（4）包含排序、分组等操作

mysql> select sleep(1) ;

+----------+

| sleep(1) |

+----------+

| 0 |

+----------+

1 row in set (1.00 sec)

mysql> select count(1) from test.account t1,test.account t2;

+----------------+

| count(1) |

+----------------+

| 35116409328100 |

+----------------+

1 row in set (1.08 sec)

mysql> select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

^C^C -- query aborted

ERROR 1317 (70100): Query execution was interrupted

mysql> select * from account t1 order by name limit 100000,1;

+---------+-------------+---------+---------------------+---------------------+-------------------+

+---------+-------------+---------+---------------------+---------------------+-------------------+

| 1134998 | name1134998 | e1 | 2021-10-15 13:36:08 | 2021-10-15 13:36:08 | 3 |

+---------+-------------+---------+---------------------+---------------------+-------------------+

1 row in set (23.63 sec)

mysql> select substr(name,4,3),count(1) from account t1 group by substr(name,4,3) limit 2;

+------------------+----------+

| substr(name,4,3) | count(1) |

+------------------+----------+

| e34 | 74076 |

| e35 | 74076 |

+------------------+----------+

2 rows in set (6.81 sec)

日志内容：

# Time: 2021-11-25T20:50:24.421438+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64077

# Query_time: 1.000365 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1

SET timestamp=1637844623;

select sleep(1);

# Time: 2021-11-25T20:51:12.203789+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64077

# Query_time: 1.078180 Lock_time: 0.000291 Rows_sent: 1 Rows_examined: 0

SET timestamp=1637844671;

select count(1) from test.account t1,test.account t2;

# Time: 2021-11-25T20:51:43.745724+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64077

# Query_time: 8.127499 Lock_time: 0.001228 Rows_sent: 0 Rows_examined: 27259

SET timestamp=1637844695;

select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

# Time: 2021-11-25T21:53:56.716651+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64141

# Query_time: 23.629454 Lock_time: 0.000146 Rows_sent: 1 Rows_examined: 6025911

SET timestamp=1637848413;

select * from account t1 order by name limit 100000,1;

# Time: 2021-11-25T21:55:09.622017+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64141

# Query_time: 6.810800 Lock_time: 0.000199 Rows_sent: 2 Rows_examined: 5925910

SET timestamp=1637848502;

select substr(name,4,3),count(1) from account t1 group by substr(name,4,3) limit 2;

这些都被正常记录到慢日志文件中。

再看几种较为复杂的场景：

（5）操作被阻塞

@会话1：

mysql> begin;

Query OK, 0 rows affected (0.00 sec)

mysql> select * from account where id=1134998 for update;

+---------+------------+---------+---------------------+---------------------+-------------------+

+---------+------------+---------+---------------------+---------------------+-------------------+

| 1134998 | namea12345 | e1 | 2021-11-25 21:59:54 | 2021-11-25 21:59:54 | 3 |

+---------+------------+---------+---------------------+---------------------+-------------------+

1 row in set (0.00 sec)

@会话2：

mysql> update account set name='namea111111' where id=1134998;

由于会话2需要等待会话1释放锁，一直处于阻塞状态，直到会话1 commit

Query OK, 1 row affected (41.99 sec)

Rows matched: 1 Changed: 1 Warnings: 0

虽然耗时41.99秒，但由于不是执行耗时，因此慢日志未记录

（6）DDL操作

mysql> alter table account drop column testcol;

Query OK, 0 rows affected (24.63 sec)

Records: 0 Duplicates: 0 Warnings: 0

也不会被记录到慢日志中。

##########################################################

根据官方文档，5.7版本中，记录慢日志需要顺序满足以下逻辑：

1.语句不能是管理语句（ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE,REPAIR TABLE），除非开启了log_slow_admin_statements

2.语句耗时超过long_query_time，或者开启了log_queries_not_using_indexes参数的情况下查询未使用索引（小于long_query_time也会被记录）

3.语句需要至少扫描了min_examined_row_limit行

4.设置了log_throttle_queries_not_using_indexes参数时，语句没有被压缩显示

不会记录查询缓存处理的语句(仅5.7版本涉及，8.0版本已经没有缓存)

从库默认不会记录replicated到的语句；如果开启log_slow_slave_statements，并且binlog_format是statement 或者binlog_format=MIXED且语句是按statement同步的，则可以被放入慢日志文件。

因此 5.7\8.0版本mysql中需要设置如下参数（个人总结），可以记录阻塞情况以外的大部分可疑慢查询语句。

slow_query_log=1

long_query_time=5 [根据实际情况调整]

log_slow_admin_statements=1

log_queries_not_using_indexes=1

global min_examined_row_limit=10000

log_throttle_queries_not_using_indexes=10

log_slow_extra=1

释义：开启慢查询日志，记录超过5秒的语句，包含管理类语句，包含未使用索引的语句且每分钟最多记录10条这样的语句，超过10条的部分将被压缩记录。记录慢查询的额外信息（起止时间、thread_id、是否被kill等）

相关实例1：下面是设置log_throttle_queries_not_using_indexes=2后，一分钟内6次执行未使用索引的语句，后面四次被压缩记录了。

# Time: 2021-11-25T22:38:48.769946+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64141

# Query_time: 0.001497 Lock_time: 0.000147 Rows_sent: 1 Rows_examined: 1000

SET timestamp=1637851128;

select * from test1 where name='name34';

# Time: 2021-11-25T22:38:48.777614+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64142

# Query_time: 0.001219 Lock_time: 0.000095 Rows_sent: 1 Rows_examined: 1000

SET timestamp=1637851128;

select * from test1 where name='name35';

# Time: 2021-11-25T22:40:02.848238+08:00

# User@Host: [] @ [] Id: 64195

# Query_time: 0.004725 Lock_time: 0.000398 Rows_sent: 1 Rows_examined: 1

SET timestamp=1637851202;

throttle: 4 'index not used' warning(s) suppressed.; 《《《《《有额外的四条语句未使用索引

相关实例2：开启log_slow_extra前后，同一sql的日志差异:

# Time: 2021-11-25T22:56:07.740623+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64141

# Query_time: 7.300167 Lock_time: 0.000403 Rows_sent: 0 Rows_examined: 29583

SET timestamp=1637852160;

select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

# Time: 2021-11-25T22:58:36.141562+08:00

# User@Host: root[root] @ [127.0.0.1] Id: 64141

# Query_time: 11.336944 Lock_time: 0.000852 Rows_sent: 0 Rows_examined: 37156 Thread_id: 64141 Errno: 1160 Killed: 1053 Bytes_received: 0 Bytes_sent: 0 Read_first: 3 Read_last: 0 Read_key: 5132 Read_next: 20528 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 4654 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2021-11-25T22:58:24.804618+08:00 End: 2021-11-25T22:58:36.141562+08:00

SET timestamp=1637852304;

select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

ITPub博客

MySQL慢查询日志相关设置

最新文章