MySQL 慢查询记录原理和内容解析

背景

本文并不准备说明如何开启记录慢查询，只是将一些重要的部分进行解析。

如何记录慢查询可以自行参考官方文档：

• 5.4.5 The Slow Query Log

本文使用 Percona 版本来开启参数 log_slow_verbosity，得到了更详细的慢查询信息。通常情况下信息没有这么多，但是一定是包含关系，本文也会使用 Percona 的参数解释说明一下这个参数的含义。

一、慢查询中的时间

实际上慢查询中的时间就是时钟时间，是通过操作系统的命令获得的时间，如下是 Linux 中获取时间的方式：

while (gettimeofday(&t, NULL) != 0)
 {}
 newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
return newtime;

实际上就是通过 OS 的 API gettimeofday 函数获得的时间。

二、慢查询记录的依据

1. long_query_time：如果执行时间超过本参数设置记录慢查询。

2.
log_queries_not_using_indexes：如果语句未使用索引记录慢查询。

3. log_slow_admin_statements：是否记录管理语句。(如 ALTER TABLE,ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE.)

本文主要讨论 long_query_time 参数的含义。

三、long_query_time 参数的具体含义

如果我们将语句的执行时间定义为如下：

实际消耗时间 = 实际执行时间+锁等待消耗时间

那么 long_query_time 实际上界定的是实际执行时间，所以有些情况下虽然语句实际消耗的时间很长但是是因为锁等待时间较长而引起的，那么实际上这种语句也不会记录到慢查询。

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

res= cur_utime - thd->utime_after_lock;
if(res > thd->variables.long_query_time)
 thd->server_status|= SERVER_QUERY_WAS_SLOW;
else
 thd->server_status&= ~SERVER_QUERY_WAS_SLOW;

这里实际上清楚的说明了上面的观点，是不是慢查询就是通过这个函数进行的判断的，非常重要。我可以清晰的看到如下公式：

• res（实际执行时间）= cur_utime（实际消耗时间）- thd->utime_after_lock( 锁等待消耗时间) 实际上在慢查询中记录的正是
• Query_time：实际消耗时间
• Lock_time：锁等待消耗时间

但是是否是慢查询其评判标准却是实际执行时间及 Query_time - Lock_time

其中锁等待消耗时间（Lock_time）我现在已经知道的包括：

1. MySQL 层 MDL LOCK 等待消耗的时间。(Waiting for table metadata lock)

2. MySQL 层 MyISAM 表锁消耗的时间。(Waiting for table level lock)

3. InnoDB 层 行锁消耗的时间。

四、MySQL 是如何记录锁时间

我们可以看到在公式中 utime_after_lock（锁等待消耗时间 Lock_time）的记录也就成了整个公式的关键，那么我们试着进行 debug。

1. MySQL 层 utime_after_lock 的记录方式

不管是 MDL LOCK 等待消耗的时间还是 MyISAM 表锁消耗的时间都是在 MySQL 层记录的，实际上它只是记录在函数 mysql_lock_tables 的末尾会调用的 THD::set_time_after_lock 进行的记录时间而已如下：

void set_time_after_lock()
{
 utime_after_lock= my_micro_time();
 MYSQL_SET_STATEMENT_LOCK_TIME(m_statement_psi, (utime_after_lock - start_utime));
}

那么这里可以解析为代码运行到 mysql_lock_tables 函数的末尾之前的所有的时间都记录到 utime_after_lock 时间中，实际上并不精确。但是 MDL LOCK 的获取和 MyISAM 表锁的获取都包含在里面。所以即便是 select 语句也可能会看到 Lock_time 并不为 0。下面是部分栈帧：

#0 THD::set_time_after_lock (this=0x7fff28012820) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_class.h:3414
#1 0x0000000001760d6d in mysql_lock_tables (thd=0x7fff28012820, tables=0x7fff28c16b58, count=1, flags=0) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/lock.cc:366
#2 0x000000000151dc1a in lock_tables (thd=0x7fff28012820, tables=0x7fff28c165b0, count=1, flags=0) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_base.cc:6700
#3 0x00000000017c4234 in Sql_cmd_delete::mysql_delete (this=0x7fff28c16b50, thd=0x7fff28012820, limit=18446744073709551615)
 at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_delete.cc:136

2. InnoDB 层的行锁的 utime_after_lock 记录方式

InnoDB 引擎层调用通过 thd_set_lock_wait_time 调用 thd_storage_lock_wait 函数完成的，部分栈帧如下：

#0 thd_storage_lock_wait (thd=0x7fff2c000bc0, value=9503561) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_class.cc:798
#1 0x00000000019a4b2a in thd_set_lock_wait_time (thd=0x7fff2c000bc0, value=9503561)
 at /root/mysql5.7.14/percona-server-5.7.14-7/storage/innobase/handler/ha_innodb.cc:1784
#2 0x0000000001a4b50f in lock_wait_suspend_thread (thr=0x7fff2c088200) at /root/mysql5.7.14/percona-server-5.7.14-7/storage/innobase/lock/lock0wait.cc:363
#3 0x0000000001b0ec9b in row_mysql_handle_erro