MySQL Slow Log，我劝你善良~

AsiaYe

发布于 2022-12-07 09:08:28

3790

发布于 2022-12-07 09:08:28

文章被收录于专栏：DBA随笔

MySQL Slowlog，我劝你善良~

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

背景介绍

一般情况下，线上环境的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:

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

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

场景分析

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

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中随便执行几条命令。注意，真的是随便执行。。。

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的慢日志：

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出现在你的慢日志里面。

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

本文参与腾讯云自媒体同步曝光计划，分享自微信公众号。

原始发表：2022-11-11，如有侵权请联系 cloudcommunity@tencent.com 删除

sql