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;
}
AI 代码解读
以上代码来自于percona 5.7.23版本
其中
res= cur_utime - thd->utime_after_lock
AI 代码解读
说明：
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);
AI 代码解读
神奇的是竟然记录到了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
AI 代码解读
直接由当前时间-0，超过long_query_time就被认定为slow query，也就记录在了slow log当中。
为了便于理解，化成流程图如下：
最后，感谢八怪高鹏老师的指点，尤其是入口函数的指点及思路分析
参考： xcode源码调试文档
最后，给八怪小小打个广告，八怪专栏《深入理解MySQL主从原理32讲》上线了，想要深入学习MySQL的同学们千万不要错过了，地址：http://t.cn/AilTRbys
