操作环境
数据库版本：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()判断时认为是慢日志。
