一个简单的sql,在慢日志中信息如下:

并且执行的语句很简单,比较奇怪了。

Lock_time:为0代表没有遇到MDL LOCK和ROW lock堵塞。
Rows_examined:为0代表没有在引擎层扫描数据。
Query_time: 180:执行时间比较长。

该语句查询没有扫描到任何数据,执行时间超过了3分钟,查看执行计划,虽然是全表扫描,但是表数据量只扫描到1行。

再次查询,发现并不慢,只是在某个时间执行的时候,花费了3分钟,该语句本身并不慢。

猜测:

(1)有没有可能是某个时间段,该表被锁住了,所以查询很慢,但是这个猜测并不成立,因为慢日志记录真实执行时间超过long_query_time的语句,不包含锁等待时间。

测试(一)

session 1

session 2

等待锁几秒后,将session1 提交,查看慢日志是否记录

发现慢日志并没有记录该sql

测试(二)

session 1

session2 ,在过几秒之后,将session 1提交

慢日志记录

结论:慢日志记录真实执行时间超过long_query_time的语句。

(2)既然不是锁等待,有没有可能锁超时报错,然后将锁等待时间记录到执行时间里面去了

锁超时有两个参数

innodb_lock_wait_timeout:innodb的dml操作的行级锁的等待时间。

lock_wait_timeout:数据结构ddl操作的锁的等待时间,代表MDL LOCK超时时间。

set global lock_wait_timeout=180;

set innodb_lock_wait_timeout=10;

测试(一)

session 1

session 2

session 3

查看慢日志,都记录进去了

测试(二)

session 1

session 2

慢日志中没有记录该慢sql

总结:

MySQL慢日志记录的是实际消耗的时间,不包含锁等待时间。

lock_wait_timeout参数,会导致锁超时异常的sql被误认为是慢sql,因为它将锁等待时间算成了真实执行时间。