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 否则就不是
三 手工测试案例
环境说明：
参数 | value |
|---|---|
long_query_time | 0.1 |
min_examined_row_limit | 0 |
log_queries_not_using_indexes | OFF |
3.1 测试过程
session1 | session2 |
|---|---|
begin;select * from t1 where id=1 for update; | |
- | select * from t1 where id=1 for update; |
rollback; | |
- | 1 row in set (9.61 sec) |
此时，并没有记录到slow log，也符合源码中的定义 |
3.2 一个比较另类的测试
session1 | session2 |
|---|---|
flush tables with read lock; | |
Query OK, 0 rows affected (0.00 sec) | |
- | select * from tx; |
- | Table 'xucl.tx' doesn't exist |
- | insert into tx values(1); |
几秒后 | |
unlock tables; | |
Query OK, 0 rows affected (0.00 sec) | |
- | ERROR 1146 (42S02): Table 'xucl.tx' doesn't exist |
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-