Mysql資料庫Slow_log中的lock_Time和Query_time

姬子玉發表於2017-12-08
MySql資料庫

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

現象展示

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

fae69244bbe2f87993e9806ccb4bf08623a9fafb

或者：

e5445953d7710c45ada5d1bab2bf71fec485182d

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

問題復現

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

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

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

1ff4d75c33654f6a8b4f702b3acd22a0587b23ba

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

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

46fcb570734457dd2db6f80b3582d203075330ec

進行如下測試：

Session1：

534463011cbf354ec4776fddddc57a82d6d582be

Session1執行查詢，不提交，不回滾

Session2：

64826de56699e316b3ed0f29fbc3af0e4345fe36

Session2被阻塞

Session1：

1909c53d1552cc809c116b0a60178c1521f9be42

等待一段時間後Session1回滾（不要超過鎖等待超時時間）

Session2：

0c29b5fd7ed27db62ed0710ef4835f18af10b39e

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

Session3：

查詢mysql.slow_log，看下結果：

9b9338ec53a23f40ed7b1357603f63dbc7b616ad

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

測試2：設定long_query_time為5s

7f1fa2e886ff3c6c9695e9ba94686a00d5ad9fb3

重複測試1的測試：

Session1：

12efd0200b5be5e7a31365fb20c5878eb58c2c04

Session 1執行查詢，不提交不回滾

Session2：

5b8f31735431b00d20649578ff3cf4578e988bf6

Session2阻塞

Session1：

fc090b6243b3765b86590387f59b343549e4c2b0

等待一段時間後Session1回滾（不要超過鎖等待超時時間）

Session2：

1dbf3f4d780a168a2e2607a178be1ee947432c75

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

Session3：

查詢mysql.slow_log，看下結果：

8376f68f2605a6a96e4dfd8613de1ce0726bc5d6

從上圖可以看到，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的結果和執行時間：

e3ad8149443b8a325162d90fd20eafc47ef17a72

上圖可以大概判斷，select count(1) from MOCK_DATA where id<10000000 lock in share mode;的執行時間一般會大於小於15S且大於5S，

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

7e91ac40b675d8a713c7b070ae0659876a269829

進行如下測試：

Session1：

0de214bac0145ed94df00b97f1ba6a328df2a6ff

Session1執行查詢，不提交，不回滾

Session2：

291896bbda3ab24d69b92a14cf9e0b84b3877dd5

Session2被阻塞

Session1：

71366e4b15f66da9126ad0a82cc1688fe7ccf440

等待一段時間後Session1回滾（不要超過鎖等待超時時間）

Session2：

31d6c817ab23316e2c659f87b72cbe4100474211

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

Session3：

查詢mysql.slow_log，看下結果：

ac80cfc6e4f11bfa4cbd1d20a7628d8d245359af

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

測試2：設定long_query_time為5s

7f1fa2e886ff3c6c9695e9ba94686a00d5ad9fb3

重複測試1的測試：

Session1：

9ba6f742907da23703a837f8c20eb80ecbf43765

Session 1執行查詢，不提交不回滾

Session2：

10eb893fe8488c4b7975ecb378e35037fa974d56

Session2阻塞

Session1：

fc090b6243b3765b86590387f59b343549e4c2b0

等待一段時間後Session1回滾（不要超過鎖等待超時時間）

Session2：

c6f38a8b5660143c858852d83f78285387bb480b

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

Session3：

查詢mysql.slow_log，看下結果：

5bfc8605d2603a6a78ad20bc534d10c78a119efb

從上圖可以看到，最新測試的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的結果和執行時間：

104106f868ebd0fa2945e8fa5f11bc83f78f8aa5

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

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

d699d27ccdd3e851affa63134f5c9bdb1df0b865

進行如下測試：

Session1：

74010215c285b09f082a77125426c958efbdf6f6

Session1執行查詢，不提交，不回滾

Session2：

3b118cd15b179c4830dfd9de0559031f4900cd26

Session2被阻塞

Session1：

71366e4b15f66da9126ad0a82cc1688fe7ccf440

等待一段時間後Session1回滾（不要超過鎖等待超時時間）

Session2：

8fb014dc3678e48d042e85498252d62fcc605293

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

Session3：

查詢mysql.slow_log，看下結果：

98e39549e3def0bd276daa803cb68f2786ce15f9

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

測試2：設定long_query_time為1s

0001837f31066811a704108e4987b690ca1608c2

重複測試1的測試：

Session1：

080ad7121417b0f5385b58418cfdea3753420e73

Session 1執行查詢，不提交不回滾

Session2：

f8ccfdb513e61a14275e6d47749b7426000abb63

Session2阻塞

Session1：

fc090b6243b3765b86590387f59b343549e4c2b0

等待一段時間後Session1回滾（不要超過鎖等待超時時間）

Session2：

66f3c6411d3c3defee149339ab60d8563929dbb3

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

Session3：

查詢mysql.slow_log，看下結果：

ef385ea901d4062888a39a3ea859bef294b9b1ac

從上圖可以看到，最新測試的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中

原文連結


相關文章