slow log判定是否会加上锁等待时间？

作者徐晨亮，MySQL DBA，热衷于数据库优化，自动化运维及数据库周边工具开发，对MySQL源码有一定的兴趣.

一 前言

对MySQL DBA而言，我们经常遇到 slow log，本文通过源码和案例实践来抽丝剥茧，slow log判定是否会加上锁等待时间？

二 talk is cheap,show me the code

1.slow log判定逻辑：

static ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
{
  ulonglong res;

#ifndef DBUG_OFF
  if (thd->variables.query_exec_time != 0)
    res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
      thd->variables.query_exec_time : 0;
  else
#endif
    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;

  return res;
}

以上代码来自于percona 5.7.23版本 其中

res= cur_utime - thd->utime_after_lock

说明：T2(sql执行完成时间) - T1（获得锁的实际时间） = T（这个得出来的是SQL执行的实际时间），因此res也就是实际的执行时间。根据实际时间与变量的long_query_time比较:

超过long_query_time，那么判定为slow query 否则就不是

三 手工测试案例

环境说明：

3.1 测试过程

3.2 一个比较另类的测试

slow log输出如下：

# Time: 2019-07-05T04:27:42.785888Z
# User@Host: root[root] @ localhost []  Id:  3129
# Query_time: 12.035846  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1562300862;
insert into tx values(1);

神奇的是竟然记录到了slow log里面，下面根据debug到的源码进行说明这个问题

insert SQL的入口是函数

insert会调用函数open_tables_for_query

open_tables_for_query又会调用open_tables

跑到这里打开表报错

到这里SQL完成，返回给客户端信息

这里是记录slow log的入口

正常情况下，如果表存在那么会对表进行加锁

lock tables会调用mysql_lock_tables

mysql_lock_tables函数末尾会设置after_lock时间戳，也就是前面提到的utimeafter_lock

由于在打开表的时间就报错了，所以utime_after_lock即为0，这样根据公式

res= cur_utime - thd->utime_after_lock

直接由当前时间-0，超过long_query_time就被认定为slow query，也就记录在了slow log当中。为了便于理解，画成流程图如下：

最后，感谢高鹏老师的指点，尤其是入口函数的指点及思路分析。

参考 xcode源码调试文档

-The End-