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

詳解MySQL慢日志（下） 選項(xiàng) 參數(shù)篇：
http://blog.itpub.net/29773961/viewspace-2147352/


〇 long_query_time

場景：
如下圖，該圖為部分 binlog截?。?/span>
9：42：25 后，還有幾個(gè)6：35：30的event


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

long_query_time 為一個(gè)MySQL選項(xiàng)參數(shù)。
這個(gè)參數(shù)不用說了，記錄超過執(zhí)行時(shí)間超過該值以上的SQL。
但這個(gè)坑在于：是按真正執(zhí)行的時(shí)間（real time），不包括等待鎖的時(shí)間。

舉個(gè)簡單的例子：
如果long_query_time設(shè)置為1秒
一個(gè)insert被lock了10秒，執(zhí)行只耗了0.5秒，那么不會(huì)被記錄到慢日志。 測試，以下分為三個(gè)會(huì)話，分別被命名為 lock>， query>， slow_log>，下同：

此處看到，整條SQL花費(fèi)了9.42秒完成，其中包括長時(shí)間的鎖等待。

再看一下具體的profile：

可以看到，等待全局讀鎖花了9.412835s，總執(zhí)行時(shí)間約為9.42。

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

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




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

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

〇 start_time
為slow log中所記錄的屬性：
start_time：看字面意思很容易會(huì)被誤認(rèn)為“sql開始的時(shí)間”…
但實(shí)際上記錄的是sql結(jié)束的時(shí)間。 測試一下：

可以看到，該sql開始時(shí)間是17:05:15，結(jié)束時(shí)間是17:05:23
那么記錄在slow log中，實(shí)際上是：

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


tips：
一般OLTP場景下，大部分query_time都會(huì)很短。
但在某些糟糕的場景下，如某一條OLAP語句執(zhí)行時(shí)間很長，如30分鐘。
如果需要確認(rèn)在某個(gè)時(shí)段的sql，在查詢slow log時(shí)指定錯(cuò)誤的start_time，可能就無法找到合適的sql了。
作者微信公眾號(hào)（持續(xù)更新）