MySQL慢查询日志详解

一、慢查询日志

慢查询日记用于记录 SQL 语句查询时间大于 long_query_time 参数中定义的时间，并且需要至少检查 min_examined_row_limit 行。DBA 可以通过慢查询日志来找出有问题的 SQL 语句，对其进行优化。MySQL 慢查询日志默认关闭状态，所以需要通过开启 slow_query_log 参数来记录慢查询日志，并通过 long_query_time 参数定义记录慢查询日志的阈值才可开始使用慢查询日志的功能，long_query_time 参数的单位是毫秒。

另外，数据库还提供了一些控制参数来决定是否将查询写入慢查询日志：

• 开启 log-queries-not-using-indexes 参数，表示未使用索引的查询也被记录到慢查询日志；
• 开启 log_slow_admin_statements 参数，表示记录管理语句到慢查询日志；
• 设置 min_examined_row_limit 参数，表示查询最少需要扫描的行大于参数值才会记录到慢查询日志。

这几个参数都可以动态开启。

当慢查询日志被启用时，服务器会将输出写入 log_output 系统变量所指定的任何目的地。如果你启用了该日志，服务器会打开日志文件并向其写入启动信息。然而，除非选择 FILE 作为日志输出目标，否则不会对查询日志记录到文件。如果目的地是 NONE，即使启用了慢查询日志，服务器也不会写入慢查询。如果没有选择 FILE 作为输出目标，则设置日志文件名对日志记录没有影响。

慢查询日志记录方式默认是在文件中，从 MySQL 5.1 开始支持记录到表中，这使得用户的查询更加方便和直观，如果想使用表记录慢查询日志需要管理员定义 log_output 参数。另外，同一般查询日志一样，慢查询日志可以直接删除，删除后在不重启服务器的情况下，需要执行 flush logs 语句重建日志文件。

在 MySQL 5.7.2 之后，如果设置了慢日志是写到文件里，需要设置 log_timestamps（默认是 UTC 时间，比中国区晚 8 小时，需要设置为系统时间 log_timestamps=SYSTEM）来控制写入到慢日志文件里面的时区（该参数同时影响 general 日志和 error 日志）。如果设置慢日志是写入到数据库中，该参数将不产生作用。

慢查询日志内容

如果启用了慢查询日志并选择 FILE 作为输出目的地，则写入日志的每个语句都是以＃字符开头的行，并具有这些字段（单行上的所有字段）：

Query_time

语句执行时间，以秒为单位。

Lock_time

语句获取锁的时间，以秒为单位。

Rows_sent

发送到客户端的行数。

Rows_examined

MySQL Server 层检查的行数（不计算存储引擎内部的任何处理）。一条 SQL 语句（存在多表关联或子查询）执行过程中从引擎层每返回一条记录到 Server 层后，Server 层就会累加 examined_row_count 变量，也就是语句执行过程中需要扫描的实际数据行，扫描行数越多越糟糕。

除了上面几个字段，还会有查询账号、主机、执行时间等信息。

写入慢查询日志文件的每条语句前面都有一个 SET 语句，其中包括一个时间戳，表明慢查询语句被记录的时间（发生在语句执行完毕之后）。

根据这些信息来分析此 SQL 语句哪里出了问题。当开始使用慢查询功能后可能随着慢查询日志的越来越大，分析起来就不是那么容易了，这个时候就可以使用 MySQL 内置的 mysqldumpslow 工具来进行分析。

NOTE

写入慢查询日志中的语句中的密码由 MySQL 重写，不符合纯文本的字面意思。

二、慢查询记录机制

如果我们将语句的执行时间定义为：实际消耗时间 = 实际执行时间 + 锁等待消耗时间

那么 long_query_time 实际上界定的是实际执行时间，所以有些情况下虽然语句实际消耗的时间很长，但是是因为锁等待时间较长而引起的，那么实际上这种语句也不会记录到慢查询。概括来说就是语句实际执行时间（消耗时间 – 锁等待时间）大于 long_query_time 参数定义的时间时就会记录到慢查询日志。比如 long_query_time 参数定义为 2 秒，但一条 SQL 语句消耗时间时 10 秒，但等待锁时间时 9 秒，实际执行时间是 1 秒，由于实际执行时间小于 long_query_time 参数定义的值，所以是不会记录到慢查询日志。这里的语句是指每一条 SQL 语句，并不是以一个事务为单位。

我们看一下 log_slow_applicable 函数的代码片段：

这里实际上清楚的说明了上面的观点，是不是慢查询就是通过这个函数进行的判断的，非常重要。

可以清晰的看到如下公式：

res（实际执行时间） = cur_utime（实际消耗时间） – thd->utime_after_lock（锁等待消耗时间）

实际上在慢查询中记录的正是：

• Query_time：实际消耗时间
• Lock_time：锁等待消耗时间

但是是否记录慢查询，其评判标准却是实际执行时间，也就是 Query_time – Lock_time。

其中锁等待消耗时间（Lock_time）大概包括如下几种类型：

三、mysqldumpslow 工具介绍

MySQL 慢查询日志包含有关执行时间长的查询的信息（请参见“慢查询日志”），mysqldumpslow 解析 MySQL 慢查询日志文件并打印其汇总信息。

通常，mysqldumpslow 可以组合类似的查询，除了数字和字符串数据值的特定值。它将“抽象”这些值 N 和 S 显示汇总输出时。该 -a 和 -n 选项可以用来修改值抽象行为。

[options]

-a：不要将所有数字抽象为 N 和字符串抽象为 S。

-n：抽象数字至少包含指定的数字。

-g pattern：只显示与模式匹配的语句，大小写不敏感。

-h host_name：用于 *-slow.log 文件名的 MySQL 服务器的主机名，该值可以包含通配符，默认值为* （全部匹配）。

-r：反转排序顺序。

-s sort_type：如何排序输出，值 sort_type 应从以下列表中选择。

t：按查询总时间排序。

l：按查询总锁定时间排序。

r：按总发送行排序。

c：按计数排序。

at：按查询时间或平均查询时间排序。

al：按平均锁定时间排序。

ar：按平均行发送排序。

默认情况下，mysqldumpslow 按平均查询时间（相当于 -s at）排序。

-t N：是 top n 的意思，即为返回前面多少条的数据。

-v：详细模式。

案例说明

仅显示 2 条结果集，且按照查询总时间排序，且过滤 group by 语句；使用 mysqldumpslow 的分析结果不会显示具体完整的 sql 语句。

1. 假如真正的 sql 语句是“SELECT * FROM sms_send WHERE service_id=10 GROUP BY content LIMIT 0, 1000”

mysqldumpslow 显示的结果会是：

2. 如果我们再执行一条“SELECT * FROM sms_send WHERE service_id=20 GROUP BY content LIMIT 10000, 1000”

mysqldumpslow 显示的结果会是：

虽然这两条语句条件不一样。

• 一个是 server_id=10，一个是 server_id=20
• 一个是 LIMIT 0, 1000，一个是 LIMIT 10000, 1000

但是 mysqldumpslow 分析会认为这是一种类型的语句，会合并显示。

结果分析

Count 会告诉我们这种类型的语句执行了几次，Time 是指这类型的语句最大执行时间和执行总共花费的时间。

这里结果告诉我们执行了 2 次，最大时间是 2.79s，总共花费时间 5s，lock 时间 0s，单次返回的结果数是 1 条记录，2 次总共返回 2 条记录 m。

Rows=1.0 (2) 是按照以下逻辑展示的：是指在 Count: 2 次数总共返回了 2 条记录集；row=1.0 显示（2）/ Count: 2，如果此时 Count 是 3，那么 row 的计算方式是 Rows=2/3，Rows=0.67。

主要功能是，统计不同慢 SQL 的：Count->出现次数，Time->执行最长时间，Time->累计总耗费时间，Lock->等待锁的时间，Rows->发送给客户端的行总数，Rows->扫描的行总数。

<参考>

https://www.jianshu.com/p/1ffadf29d6c0

https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

喜欢 (5)赏

[资助本站您就扫码 谢谢]

分享 (0)