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

04.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否则就不是

1、手工测试案例

环境说明：

测试过程

此时，并没有记录到slow log，也符合源码中的定义

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时间戳，也就是前面提到的utime_after_lock

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

res= cur_utime - thd->utime_after_lock           

直接由当前时间-0，超过long_query_time就被认定为slow query，也就记录在了slow log当中。

为了便于理解，化成流程图如下：

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

参考：

xcode源码调试文档

最后，给八怪小小打个广告，八怪专栏《深入理解MySQL主从原理32讲》上线了，想要深入学习MySQL的同学们千万不要错过了，地址：

http://t.cn/AilTRbys