Mysql資料庫Slow_log中的lock_Time和Query_time

作者：手辨

實為吾之愚見,望諸君酌之!聞過則喜，與君共勉 

說明：主要用簡單的例子來說明，slow log裡的lock_time和query_time的關系，得出的結論是：

當一個sql的執行時間（排除lock_time）大于long_query_time的時候，才會被記錄到slow log中，并且query_time是累計了lock_time的（如果有lock_time），大概真正的執行時間需要減去lock_time的時間，當一個sql的執行時間（排除lock_time）小于long_query_time的時候（即使他鎖等待了3個小時），也不會記錄到slow log中的，故鎖等待的時間并不決定記不記錄slow log，下面的測試多是基于自建mysql進行

現象展示

有時在查slow log的資訊時，可能會遇到，下面這種情況：

或者：

上面的資訊，都出現了lock_time的時間很長的情況，并且sql的執行時間（query_time）也會出現時間很長的情況

問題複現

建構測試資料，手動造成鎖等待，複現下這類問題

現象1：無自建主鍵的鎖等待

無自建主鍵測試資料，locking Reads的結果和執行時間：

上圖可以大概判斷，select count(1) from MOCK_DATA for update;的執行時間一般會大于小于15S且大于5S

測試1：:設定long_query_time為15s：

進行如下測試：

Session1：

Session1執行查詢，不送出，不復原

Session2：

Session2被阻塞

等待一段時間後Session1復原（不要超過鎖等待逾時時間）

Session2執行完成，執行時間是28.95sec

Session3：

查詢mysql.slow_log，看下結果：

沒有看到session2執行的for update操作的sql

測試2：設定long_query_time為5s

重複測試1的測試：

Session 1執行查詢，不送出不復原

Session2阻塞

Session2執行完成，執行時間是47.66sec

從上圖可以看到，session2執行的for update操作的sql記錄下來了，其中執行時間（query_time）是47s，在這47s裡，鎖定的時間（lock_time）是38s

結論：

當一個無自建主鍵的sql的執行時間（排除lock_time）大于long_query_time的時候，才會被記錄到slow log中，并且query_time是累計了lock_time的，大概真正的執行時間需要減去lock_time的時間才是（該測試中，執行時間=47s-38s=9s，這個計算可能會有偏差），當一個sql的執行時間（排除lock_time）小于long_query_time的時候（即使他鎖等待了3個小時），就不會記錄到slow log中

現象2：有自建主鍵的鎖等待

有自建主鍵測試資料，locking Reads的結果和執行時間：

上圖可以大概判斷，select count(1) from MOCK_DATA where id<10000000 lock in share

mode;的執行時間一般會大于小于15S且大于5S，

Session2執行完成，執行時間是31.04sec

沒有看到最新測試的session2執行的for update操作的sql，隻有之前測試的那條記錄

Session2執行完成，執行時間是1min 0.40sec

從上圖可以看到，最新測試的session2執行的for update操作的sql記錄下來了，其中執行時間（query_time）是1分鐘，在這1分鐘裡，鎖定的時間（lock_time）是51s

當使用主鍵查詢的一個sql的執行時間（排除lock_time）大于long_query_time的時候，才會被記錄到slow log中，并且query_time是累計了lock_time的，大概真正的執行時間需要減去lock_time的時間，當一個sql的執行時間（排除lock_time）小于long_query_time的時候（即使他鎖等待了3個小時），就不會記錄到slow log中

現象3：secondary index的鎖等待

Secondary index測試資料，locking

Reads的結果和執行時間：

上圖可以大概判斷，select count(1) from MOCK_DATA where ram_num=7 for update;的執行時間一般會大于小于10S且大于1S，

測試1：:設定long_query_time為10s：

Session2執行完成，執行時間是1min

44.02sec

測試2：設定long_query_time為1s

Session2執行完成，執行時間是1min 6.66sec

從上圖可以看到，最新測試的session2執行的for update操作的sql記錄下來了，其中執行時間（query_time）是1分06秒，在這1分06秒裡，鎖定的時間（lock_time）是1分02秒

當使用secondary index查詢的一個sql的執行時間（排除lock_time）大于long_query_time的時候，才會被記錄到slow log中，并且query_time是累計了lock_time的，大概真正的執行時間需要減去lock_time的時間，當一個sql的執行時間（排除lock_time）小于long_query_time的時候（即使他鎖等待了3個小時），就不會記錄到slow log中