MySQL的Slow_log如何记录SQL的MDL锁耗时

操作环境

数据库版本:mysql-5.6.24 source code

操作系统版本:CentOS Linux release 7.6.1810 (Core)

现象

MySQL的慢日志判断逻辑是根据utime_after_lock 加上long_query_time的值与end_utime_of_query时间做比较判断的,要分析MDL锁在MySQL的慢日志中的记录逻辑,先看如下2个测试场景:

场景1:MDL请求正常执行完

执行请求1:

MySQL的Slow_log如何记录SQL的MDL锁耗时

执行请求2:

MySQL的Slow_log如何记录SQL的MDL锁耗时

由于请求1持有MDL锁未释放,请求2被阻塞,处于Waiting for table metadata lock状态,此时的long_query_time为10S:

MySQL的Slow_log如何记录SQL的MDL锁耗时
回滚请求1,此时请求2执行完成,查看慢日志记录情况:

MySQL的Slow_log如何记录SQL的MDL锁耗时

MySQL的Slow_log如何记录SQL的MDL锁耗时

此时,慢日志并未记录请求2的alter操作。

场景2:MDL请求被KILL

重复"MDL请求正常执行完"章节的请求1和请求2,当请求2阻塞超过10S时,手动终止alter 操作,查看慢日志的记录情况:

MySQL的Slow_log如何记录SQL的MDL锁耗时

MySQL的Slow_log如何记录SQL的MDL锁耗时

此时,慢日志记录了alter操作。并且query time为7分52秒,lock_time为0。

推测

通过上面的测试,MDL请求耗时在特定情况会计入慢日志,通过之前文章的慢日志函数分析,最终判断SQL是否是慢日志的函数为THD::update_server_status(),这里面起到关键作用的是utime_after_lock 变量。也就是上面的2种行为对应了utime_after_lock 的2种变化,当"MDL请求正常执行完"时,utime_after_lock 在SQL的执行过程中重新(较SQL开始时的初始化的赋值)做了赋值,而当"MDL请求被KILL"时,utime_after_lock 没有进行新的赋值。导致在进入THD::update_server_status()函数时,出现两种不同的现象。

调试分析

为了验证上面的推测,在该函数设置断点,复现2个现象,查看运行到该函数时,utime_after_lock 的变化:

场景1:MDL请求执行完

请求2添加索引(alter table)开始执行时间:21:00:55

请求1回滚(rollback)时间:21:1:14

THD::update_server_status()函数utime_after_lock值:21:1:14

当MDL请求正常执行完时,虽然请求2被请求1的元数据锁阻塞了很久(21:1:14减去21:00:55),但是当请求1回滚后,请求2的alter操作执行到THD::update_server_status()函数时,其utime_after_lock为21:1:14,并不是请求2的开始执行时间。

场景2:MDL请求被KILL

请求2添加索引(alter table)开始执行时间:20:52:23

请求2终止时间:20:53:10

THD::update_server_status()函数utime_after_lock值:20:52:24

当MDL请求被kill时,虽然请求2被请求1的元数据锁阻塞了很久(20:53:10减去20:52:23),但是当请求2被kill后,请求2执行到THD::update_server_status()函数时,其utime_after_lock为20:52:24,并不是请求2的终止执行时间,而与请求2的开始执行时间相近。

通过这两个结果的对比,也进一步的证明了之前推测的结论,也就导致被kill的 query会出现在慢日志中。

找到关键函数

对源码进行检索,MySQL中有三个函数会对utime_after_lock 的值进行改变:

thd_storage_lock_wait():

void thd_storage_lock_wait(THD *thd, long long value)

{

thd->utime_after_lock+= value;

}

调试该函数,发现该函数是引擎层调用,由于MDL并未进入引擎层,这不是当前问题需要关注的函数。

THD::set_time():

inline void set_time()

{

start_utime= utime_after_lock= my_micro_time();

if (user_time.tv_sec || user_time.tv_usec)

{

start_time= user_time;

}

else

my_micro_time_to_timeval(start_utime, &start_time);

#ifdef HAVE_PSI_THREAD_INTERFACE

PSI_THREAD_CALL(set_thread_start_time)(start_time.tv_sec);

#endif

}

inline void set_time(const struct timeval *t)

{

start_time= user_time= *t;

start_utime= utime_after_lock= my_micro_time();

#ifdef HAVE_PSI_THREAD_INTERFACE

PSI_THREAD_CALL(set_thread_start_time)(start_time.tv_sec);

#endif

}

调试该函数,该函数主要用于线程以及请求开始、执行过程中的start_utime、utime_after_lock等变量的初始化或者设置。也不是当前问题需要关注的函数。

THD::set_time_after_lock():

void set_time_after_lock()

{

utime_after_lock= my_micro_time();

MYSQL_SET_STATEMENT_LOCK_TIME(m_statement_psi, (utime_after_lock - start_utime));

}

调试该函数,该函数会在mysql_lock_tables()函数进行调用,这属于MySQL server层的调用,是判断MDL的utime_after_lock赋值问题要关注的函数

对THD::set_time_after_lock设置断点

通过对THD::set_time_after_lock函数设置断点,复现场景1与场景2,结果如下:

场景1:MDL请求正常执行完

在该场景下,当请求1执行rollback后,请求2停留在断点处,堆栈如下:

MySQL的Slow_log如何记录SQL的MDL锁耗时

可以看到,mysql_lock_tables()函数会调用 THD::set_time_after_lock,mysql_lock_tables()函数调用THD::set_time_after_lock的位置在函数的最后,如下:

MySQL的Slow_log如何记录SQL的MDL锁耗时

场景2:MDL请求被KILL

在该场景下,当请求2被kill query后,请求2直接终止并提示ERROR 1317 (70100): Query execution was interrupted,不会触发断点。

结论

通过测试验证,MDL在特殊情况下计入慢日志的主要原因是没有运行到mysql_lock_tables()函数的 thd->set_time_after_lock()操作,导致utime_after_lock变量没有被正确赋值。以至于在做慢日志判断时,使用的依然是较早的(SQL开始初始化时)的utime_after_lock,导致THD::update_server_status()判断时认为是慢日志。

上一篇:MYSQL8.0 源码安装调试环境


下一篇:MYSQL SUBQUERY执行过程