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出现在你的慢日志里面。
最近工作事情比较多,抽空水一篇,今天就到这里吧。晚安。