slow log判定是否會加上鎖等待時間？

一 前言

對MySQL DBA而言，我們經常遇到 slow log，本文通過源碼和案例實踐來抽絲剝繭，slow log判定是否會加上鎖等待時間？

二 talk is cheap,show me the code

1.slow log判定邏輯：

1. static ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
2. {
3. ulonglong res;
4. #ifndef DBUG_OFF
5. if (thd->variables.query_exec_time != 0)
6. res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
7. thd->variables.query_exec_time : 0;
8. else
9. #endif
10. res= cur_utime - thd->utime_after_lock;
11. if (res > thd->variables.long_query_time)
12. thd->server_status|= SERVER_QUERY_WAS_SLOW;
14. thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
15. return res;
16. }

以上代碼來自于percona 5.7.23版本 其中

1. res= cur_utime - thd->utime_after_lock

說明：T2(sql執行完成時間) - T1（獲得鎖的實際時間） = T（這個得出來的是SQL執行的實際時間），是以res也就是實際的執行時間。根據實際時間與變量的long_query_time比較:

超過long_query_time，那麼判定為slow query 否則就不是

三 手工測試案例

環境說明：

參數	value
long_query_time	0.1
min_examined_row_limit
log_queries_not_using_indexes	OFF

3.1 測試過程

session1	session2
begin;select * from t1 where id=1 for update;
-	select * from t1 where id=1 for update;
rollback;
	1 row in set (9.61 sec)
此時，并沒有記錄到slow log，也符合源碼中的定義

3.2 一個比較另類的測試

flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)
	select * from tx;
	Table 'xucl.tx' doesn't exist
	insert into tx values(1);
幾秒後
unlock tables;
	ERROR 1146 (42S02): Table 'xucl.tx' doesn't exist

slow log輸出如下：

1. # Time: 2019-07-05T04:27:42.785888Z
2. # User@Host: root[root] @ localhost [] Id: 3129
3. # Query_time: 12.035846 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
4. SET timestamp=1562300862;

神奇的是竟然記錄到了slow log裡面，下面根據debug到的源碼進行說明這個問題

insert SQL的入口是函數

insert會調用函數open_tables_for_query

open_tables_for_query又會調用open_tables

跑到這裡打開表報錯

到這裡SQL完成，傳回給用戶端資訊 

這裡是記錄slow log的入口

正常情況下，如果表存在那麼會對表進行加鎖

lock tables會調用mysql_lock_tables

mysql_lock_tables函數末尾會設定after_lock時間戳，也就是前面提到的utimeafter_lock

由于在打開表的時間就報錯了，是以utime_after_lock即為0，這樣根據公式