操作环境
数据库版本: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:
执行请求2:
由于请求1持有MDL锁未释放,请求2被阻塞,处于Waiting for table metadata lock状态,此时的long_query_time为10S:
回滚请求1,此时请求2执行完成,查看慢日志记录情况:
此时,慢日志并未记录请求2的alter操作。
场景2:MDL请求被KILL
重复"MDL请求正常执行完"章节的请求1和请求2,当请求2阻塞超过10S时,手动终止alter 操作,查看慢日志的记录情况:
此时,慢日志记录了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_lock_tables()函数会调用 THD::set_time_after_lock,mysql_lock_tables()函数调用THD::set_time_after_lock的位置在函数的最后,如下:
场景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()判断时认为是慢日志。