操作環境
資料庫版本：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添加索引(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等變量的初始化或者設定。也不是目前問題需要關注的函數。
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執行rollback後，請求2停留在斷點處，堆棧如下：
可以看到，mysql_lock_tables()函數會調用 THD::set_time_after_lock，mysql_lock_tables()函數調用THD::set_time_after_lock的位置在函數的最後，如下：
在該場景下，當請求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()判斷時認為是慢日志。