本文并不准备说明如何开启记录慢查询，只是将一些重要的部分进行解析。如何记录慢查询可以自行参考官方文档：

• 5.4.5 The Slow Query Log

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

一、慢查询中的时间

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

  while (gettimeofday(&t, NULL) != )
  {}
  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=x7fff28012820) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_class.h:3414
#1  0x0000000001760d6d in mysql_lock_tables (thd=x7fff28012820, tables=x7fff28c16b58, count=1, flags=) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/lock.cc:366
#2  0x000000000151dc1a in lock_tables (thd=x7fff28012820, tables=x7fff28c165b0, count=1, flags=) 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=x7fff28c16b50, thd=x7fff28012820, limit=18446744073709551615)
    at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_delete.cc:136
#4  0x00000000017c84ba in Sql_cmd_delete::execute (this=x7fff28c16b50, thd=x7fff28012820) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_delete.cc:1389
#5  0x00000000015a7814 in mysql_execute_command (thd=x7fff28012820, first_level=true) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_parse.cc:3729
#6  0x00000000015adcd6 in mysql_parse (thd=x7fff28012820, parser_state=x7ffff035b600) at /root/mysql5.7.14/percona-server-5.7.14-7/sql/sql_parse.cc:5836
#7  0x00000000015a1b95 in dispatch_command (thd=x7fff28012820, com_data=x7ffff035bd70, command=COM_QUERY)
    at /root/mysql5.7