MySQL Slow Log,我劝你善良~

2022-12-07 09:08:28 浏览数 (1)

MySQL Slowlog,我劝你善良~

今天在测试一个线上功能的时候,发现了slowlog的一个特点,之前从来没遇到。这里分享一下。

01

背景介绍

一般情况下,线上环境的MySQL实例都会开启slow log来收集MySQL的慢日志,用来分析业务应用中的慢SQL,达到优化SQL的目的。

收集慢SQL,有几个参数肯定是需要设置的:

slow_query_log=on:

这个参数代表开启慢日志的收集。如果要关闭,设置为off

long_query_time=xxx:

其中,xxx是一个数字,单位是秒,一般线上环境会根据业务的情况来设置,1~10s都有可能,当然,也有可能设置为0,代表收集全量的业务日志。

一旦业务的SQL执行时间超过这个阈值,MySQL会递增global status中的slow_queries全局变量,然后再把慢日志写入到slow query log中。

log_queries_not_using_indexes=on:

这个参数的字面意思很好理解,代表将所有没有使用索引的慢查询都记录下来。

但是实际情况是,即使一个查询用到了索引,但是这个索引并没有过滤掉任何数据,而是返回了表里面所有的数据,这个查询也会被记录到表里面。

slow_query_log_file=/dir:

这个参数很好理解,就是慢日志的保存路径。

有了上面的基础,我们来看今天的案例。

02

场景分析

首先,我们开启这两个参数,代表收集所有的慢日志:

代码语言:javascript复制
mysql> set global slow_query_log=on;
Query OK, 0 rows affected (0.00 sec)

mysql> set global long_query_time= 0;
Query OK, 0 rows affected (0.00 sec)

然后我们在MySQL中随便执行几条命令。注意,真的是随便执行。。。

代码语言:javascript复制
mysql> delete database test;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'database test' at line 1
mysql> exit
Bye

mysql> testtesttestttttttttttttttttttt--------ttt;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'testtesttestttttttttttttttttttt--------ttt' at line 1
mysql>
mysql> exit

这两条可能根本就不是能够正常执行的命令。。。

查看MySQL的慢日志:

代码语言:javascript复制
mysqld, Version: 5.7.24 (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2022-11-09T08:54:58.240129Z
# User@Host: root[root] @  [172.17.0.1]  Id:  4343
# Query_time: 0.002451  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1667984098;
set global slow_query_log=on;
# Time: 2022-11-09T08:55:01.149621Z
# User@Host: root[root] @  [172.17.0.1]  Id:  4343
# Query_time: 0.002791  Lock_time: 0.000289 Rows_sent: 5  Rows_examined: 1026
SET timestamp=1667984107;
delete database test;
# Time: 2022-11-09T08:55:09.597576Z
# User@Host: root[root] @  [172.17.0.1]  Id:  4343
# Query_time: 0.000019  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1667984303;
testtesttestttttttttttttttttttt--------ttt;
# Time: 2022-11-09T08:58:25.771920Z
# User@Host: root[root] @ localhost []  Id:  4346
# Query_time: 0.000019  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1667984305;
# administrator command: Quit;

这个结果,多少有点离谱。这种"SQL"根本无法执行,即使记录到慢日志中,也没有任何意义。如果我们用pt-query-digest这种工具去解析慢日志,在前端展示慢SQL结果的时候,确实看着不那么优雅美观。

如何避免这个问题?

出现这种情况,都是SQL本身在解析器阶段词法解析或者语法解析的时候,就出现错误了,解析的过程非常快。

那么我们其实可以给long_query_time设置一个更加合理的值来杜绝这种现象。例如0.01秒,设置为0.01秒意味着只有执行时间大于10ms的SQL才会被收集到,大概率可以过滤掉这种SQL,但是如果你想收集全量日志,有些业务SQL可能也就漏掉了。

所以这个值设置多少最好呢?其实还是看你业务关注的慢日志阈值。这篇文章主要告诉大家,设置为0,就会出现这种看起来比较离谱的错误SQL出现在你的慢日志里面。

最近工作事情比较多,抽空水一篇,今天就到这里吧。晚安。

0 人点赞