Mysql 慢日志查询小于1000ms显示0s问题排查

Mysql 慢日志查询<1000ms显示0s问题排查

在描述问题之前，先温习下Mysql 慢日志的知识。

Mysql慢日志是Mysql用来记录统计执行耗时超过long_query_time 指标的sql日志。long_query_time 可设置0-10，支持小数点，单位秒s。

慢日志对于Sql优化有着重大的意义，那么，如何开启慢日志？

1.开启慢日志记录
-- 显示慢日志是否开启，ON 表示开启，OFF表示关闭
show VARIABLES like 'slow_query_log';
-- 设置全局变量，开启慢日志记录，1表示开启，0表示关闭。
set global slow_query_log=1;

-- 显示慢日志是否开启，慢日志文件路径
show variables like 'slow_query%';
-- 显示慢SQL记录日志文件
show variables like 'slow_query_log_file';

2.设置慢SQL统计指标
-- 显示慢日志统计指标-阈值 ， 单位秒s
show variables like 'long_query_time%';
-- 设置慢日志统计指标-阈值 ， 单位秒s
set global long_query_time=1;
-- linux端查看慢日志文件
sudo more /usr/local/mysql/data/mysql-slow.log

-- 查看慢日志-表记录
select * from slow_log;

3.设置记录方式
-- 显示慢SQL记录日志方式，TABLE表示只记录在show_log， FILE表示只记录在$slow_query_log_file文件中，TABLE,FILE表示同时记录在table和file中。
show variables like '%log_output%';

-- 设置将慢日志记录在表
set global log_output='TABLE';

-- 睡眠时间，测试慢sql是否记录。
select sleep(2);

问题排查：

前天使用阿里云RDS Mysql 5.6 查看数据库慢日志时，发现好多慢日志统计出来的时间，都是0s。如图：

于是查了查Mysql的官方文档https://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html  注意官网下的这段话：

对于慢日志写入日志文件的方式，写入的执行耗时包含微秒部分，精确度达到微秒。对于慢日志写入table表的方式，只会记录整数部分，不会记录微秒部分。

也就是说，其实我们常常看到的2s非2秒，而是2000ms-3000ms之间的某一个值。而0s即是long_query_time-1000ms之间的某个值。

不过这个问题，只存在Mysql 5.7以下版本，在Mysql5.7的版本中已经解决了。看下图：

我在Mysql5.7中将慢日志统计阈值设置成2s，大于2s的慢日志都统计进来。发现query_time列已经精确到纳秒级别的精度了。