詳解MySQL慢日誌（上）query_time\start_time\lock_time 的坑

詳解MySQL慢日誌（下） 選項 引數篇：
http://blog.itpub.net/29773961/viewspace-2147352/


〇 long_query_time

場景：
如下圖，該圖為部分 binlog擷取：
9：42：25 後，還有幾個6：35：30的event


但是這些event如圖中最後一條。
exec_time為11216，但並未被記錄到slow log中。

long_query_time 為一個MySQL選項引數。
這個引數不用說了，記錄超過執行時間超過該值以上的SQL。
但這個坑在於：是按真正執行的時間（real time），不包括等待鎖的時間。

舉個簡單的例子：
如果long_query_time設定為1秒
一個insert被lock了10秒，執行只耗了0.5秒，那麼不會被記錄到慢日誌。


測試，以下分為三個會話，分別被命名為 lock>， query>， slow_log>，下同：

此處看到，整條SQL花費了9.42秒完成，其中包括長時間的鎖等待。

再看一下具體的profile：

可以看到，等待全域性讀鎖花了9.412835s，總執行時間約為9.42。

再在slow_log表中查一下……什麼都沒有：

tips：
此時SQL執行時間為0.00404400s，故沒有被記錄到slow log中。
也可以解釋圖中，某些event執行了3個小時，但又無法在slow log中查詢到。




〇 lock_time與query_time
為slow log中所記錄的兩個屬性：
lock_time：waiting for xxx lock的時間
query_time：real time + lock time的總時間

可以看到做一個簡單查詢，query_time也很長：
實際上query_time記錄的是lock_time + real time。
query_time ≥ lock_time

〇 start_time
為slow log中所記錄的屬性：
start_time：看字面意思很容易會被誤認為“sql開始的時間”…
但實際上記錄的是sql結束的時間。


測試一下：

可以看到，該sql開始時間是17:05:15，結束時間是17:05:23
那麼記錄在slow log中，實際上是：

可以看到，start_time實際上是sql執行完成的時間。
真正的開始時間計算的方法也很簡單：
start_time - query_time 即為sql真正開始的時間。


tips：
一般OLTP場景下，大部分query_time都會很短。
但在某些糟糕的場景下，如某一條OLAP語句執行時間很長，如30分鐘。
如果需要確認在某個時段的sql，在查詢slow log時指定錯誤的start_time，可能就無法找到合適的sql了。



作者微信公眾號（持續更新）