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

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

作者簡介：徐晨亮，MySQL DBA，熱衷于資料庫優化，自動化運維及資料庫周邊工具開發，對MySQL源碼有一定的興趣

一、前言

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

二、talk is cheap,show me the code

1.slow log判定邏輯：

static ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
{
  ulonglong res;
#ifndef DBUG_OFF
  if (thd->variables.query_exec_time != 0)
    res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
      thd->variables.query_exec_time : 0;
  else
#endif
    res= cur_utime - thd->utime_after_lock;
  if (res > thd->variables.long_query_time)
    thd->server_status|= SERVER_QUERY_WAS_SLOW;
  else
    thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
  return res;
}           

以上代碼來自于percona 5.7.23版本

其中

res= cur_utime - thd->utime_after_lock           

說明：

T2(sql執行完成時間) - T1（獲得鎖的實際時間） = T（這個得出來的是SQL執行的實際時間），是以res也就是實際的執行時間

根據實際時間與變量的long_query_time比較：

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

1、手工測試案例

環境說明：

測試過程

此時，并沒有記錄到slow log，也符合源碼中的定義

2、一個比較另類的測試

另類測試

slow log輸出如下：

# Time: 2019-07-05T04:27:42.785888Z
# User@Host: root[root] @ localhost [] Id: 3129
# Query_time: 12.035846 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1562300862;
insert into tx values(1);           

神奇的是竟然記錄到了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時間戳，也就是前面提到的utime_after_lock

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

res= cur_utime - thd->utime_after_lock           

直接由目前時間-0，超過long_query_time就被認定為slow query，也就記錄在了slow log當中。

為了便于了解，化成流程圖如下：

最後，感謝八怪高鵬老師的指點，尤其是入口函數的指點及思路分析

參考：

xcode源碼調試文檔

最後，給八怪小小打個廣告，八怪專欄《深入了解MySQL主從原理32講》上線了，想要深入學習MySQL的同學們千萬不要錯過了，位址：

http://t.cn/AilTRbys