数据库教程:slow log判定是否会加上锁等待时间？-计算机技术网

数据库教程:slow log判定是否会加上锁等待时间？

2021年9月15日下午3:34 • 数据库教程教学 • 阅读 1

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

一前言

对MySQL DBA而言，我们经常遇到 slow log，数据库技术: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的入口是函数

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