• 进入"运维那点事"后,希望您第一件事就是阅读“关于”栏目,仔细阅读“关于Ctrl+c问题”,不希望误会!

MySQL慢查询日志详解

MySQL 彭东稳 6年前 (2017-05-19) 21723次浏览 已收录 0个评论

一、慢查询日志

慢查询日记用于记录 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)大概包括如下几种类型:

  • MySQL 层 MDL LOCK 等待消耗的时间(Waiting for table metadata lock)。
  • MySQL 层 MyISAM 表锁消耗的时间(Waiting for table level lock)。
  • InnoDB 层行锁消耗的时间。

现在我们知道了决定是否记录慢查询日志相关的参数和机制,但还有几个小问题也需要注意,如下:

1. 长时间未提交的事务(事务中 SQL 语句执行很快)是否会记录慢查询日志

结论是不会,上面也说了是否记录慢查询日志是以语句为单位,而不是事务为单位。只要事务中的执行语句的实际执行时间没有大于 long_query_time 参数值就不会记录慢查询日志。

2. DML 语句执行时间超过 long_query_time 参数值,但是回滚了,是否会记录慢查询日志

结论是会,被回滚的 DML 语句,如果超过了 long_query_time 参数值,是会被记录到慢查询日志。

另外,如果一个事务中有多条语句,其中部分语句超过了 long_query_time 参数值,部分没有超过;那么只会记录超过 long_query_time 参数值的语句,而没有超过 long_query_time 参数值的语句是不会记录到慢查询日志的,虽然他们在同一个事务中。这也说明慢查询记录是以语句为单位,而不是事务为单位。

NOTE

除了需要注意 SQL 获取锁的时间不计入执行时间外,将 SQL 语句写入慢查询日志也是在执行完慢查询语句并释放所有锁后,因此日志顺序可能与执行顺序不同。

三、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)

您必须 登录 才能发表评论!