在工作当中遇到关于MySQL慢查询日志的相关细节问题

之前写了一篇“MySQL慢查询日志总结“，总结了一些MySQL慢查询日志常用的相关知识，这里总结一下在工作当中遇到关于MySQL慢查询日志的相关细节问题，有些是释疑或自己有疑惑，自己测试验证、解惑方面的知识。此篇只是总结个人的一些经验，不足之处，敬请指正！

1： 为什么在慢查询日志里面出现Query_time小于long_query_time阀值的SQL语句呢？

例如，如下截图，long_query_time=5， 但是Query_time小于1秒的SQL都记录到慢查询日志当中了。

相信有些人遇到这个问题的时候觉得很奇怪，其实这个不是bug，而是你设置了系统变量log_queries_not_using_indexes ,这个系统变量开启后，

会将那些未使用索引的SQL也被记录到慢查询日志中，另外，full index scan的SQL也会被记录到慢查询日志。所以，当满足这些条件的SQL，即

使Query_time时间小于long_query_time的值，也会被记录到慢查询日志。

2： 使用日志分析工具mysqldumpslow分析有些日志非常慢，如何加快？

mysqldumpslow -s t -t 10 /var/lib/mysql/MyDB-slow.log

1: 出现这种情况是因为慢查询日志变得很大（个人遇到的案例，慢查询日志就有2G多了），所以，需要每天或每周切分慢查询日志。设置一个Crontab作业即可。

 /var/lib/mysql/DB-Server-slow.log.20181112

 /var/lib/mysql/DB-Server-slow.log.20181113

 /var/lib/mysql/DB-Server-slow.log.20181114

 /var/lib/mysql/DB-Server-slow.log.20181115

2: 开启了系统变量log_queries_not_using_indexes后，如果系统设计糟糕，未使用索引的SQL很多，那么这一类的日志可能会有很多，所以还有个特别的开关log_throttle_queries_not_using_indexes用于限制每分钟输出未使用索引的日志数量。

3：mysqldumpslow的生成报告中的Count、 Time、 Lock、Rows代表具体意思。

mysqldumpslow -s c -t 10 /var/lib/mysql/MyDB-slow.log  使用mysqldumpslow分析慢查询日志分析获取访问次数最多的10个SQL。

Count ：        表示这个SQL总共执行了195674次（慢查询日志中出现的次数）

Time            表示执行时间，后面括号里面的38s 表示这个SQL语句累计的执行耗费时间为38秒。其实就是单次执行的时间和总共执行消耗的时间的区别。

Lock            表示锁定时间，后面括号里面表示这些SQL累计的锁定时间为48s

Rows            表示返回的记录数，括号里面表示所有SQL语句累计返回记录数

然后我们看看慢查询日志的相关信息：

# Time: 2018-11-15T01:43:51.338167Z    

这个表示日志记录的时间，确切的说是SQL执行完的时间点。注意这个时间有可能跟系统当前时间不一致，它可能是UTC时间。这个要看系统变量log_timestamps是UTC还是system。 

mysql> show variables like 'log_timestamps';

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

| Variable_name  | Value |

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

| log_timestamps | UTC   |

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

1 row in set (0.01 sec)

mysql> set global log_timestamps=system;

Query OK, 0 rows affected (0.00 sec)

# User@Host: xxx[xxx] @  [xxx.xxx.xxx.xxx]  Id: 23781

客户端的账户信息，两个用户名（第一个是授权账户，第二个为登录账户），客户端IP地址，还有mysqld的线程ID。

# Query_time: 16.480118  Lock_time: 0.000239 Rows_sent: 1  Rows_examined: 348011

查询执行的信息，包括查询时长，锁持有时长，返回客户端的行数，优化器扫描行数。通常需要优化的就是最后一个内容，尽量减少SQL语句扫描的数据行数

#use xxx;

#SET timestamp=1542246231;

这个是时间戳，你可以将其转换为时间格式（注意时区），如下所示：

[root@mylnx02 ~]# date -d @1542246231

Thu Nov 15 09:43:51 CST 2018

[root@DB-Server ~]# date -d @1542246231

Wed Nov 14 20:43:51 EST 2018

4： 如何分析慢查询日志一段时间内的数据呢？

mysqldumpslow这款工具没有提供相关参数分析某个日期范围内的慢查询日志，也就是说没法提供精细的搜索、分析。如果要分析某段时间内的慢查询日志可以使用工具pt-query-digest 

如果实在需要使用mysqldumpslow分析某段时间内的慢查询SQL，可以借助awk命令的帮助。如下样例所示

#取出一天时间的慢查询日志

# awk '/# Time: 2018-11-14/,/# Time: 2018-11-15/' DB-Server-slow.log > DB-Server-slow.log.20181114

#取出2018-11-14号4点到6点之间两个小时的数据

#awk '/# Time: 2018-11-14T04/,/# Time: 2018-11-14T06/' DB-Server-slow.log > slow_04_06.log

5： 关于慢查询日志中query_time和lock_time的关系。

只有当一个SQL的执行时间（不包括锁等待的时间 lock_time）>long_query_time的时候，才会判定为慢查询SQL；但是判定为慢查询SQL之后，输出的Query_time包括了（执行时间+锁等待时间），并且也会输出Lock_time时间。当一个SQL的执行时间（排除lock_time）小于long_query_time的时候（即使他锁等待超过了很久），也不会记录到慢查询日志当中的。