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源码调试文档

在此强烈推荐一下八怪的《深入MySQL主从复制32讲》知识专栏，想要深入学习MySQL的同学们千万不要错过了，扫描下方二维码可订阅

END

---

扫码加入MySQL技术Q群

（群号：650149401）

   

本文地址：https://blog.csdn.net/n88Lpo/article/details/97837727