詳解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>，下同：

lock> FLUSH TABLE WITH READ LOCK;
Query OK, 0 rows affected (0.00 sec)
query> SET profiling = 1, SESSION long_query_time=0.5;
Query OK, 0 rows affected, 1 warning (0.00 sec)
query> INSERT INTO t0 SELECT null, create_time, uuid FROM t1 LIMIT 1;
{此時hang住}
lock> UNLOCK TABLE;
query> {返回}
Query OK, 1 row affected (9.42 sec)
Records: 1 Duplicates: 0 Warnings: 0

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

再看一下具體的profile：

query> SHOW PROFILES;
+----------+------------+---------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+---------------------------------------------------------------+
| 1 | 9.41687900 | INSERT INTO t0 SELECT null, create_time, uuid FROM t1 LIMIT 1 |
+----------+------------+---------------------------------------------------------------+
1 row in set, 1 warning (0.00 sec)
query> SHOW PROFILE FOR QUERY 1;
+------------------------------+----------+
| Status | Duration |
+------------------------------+----------+
| starting | 0.000101 |
| checking permissions | 0.000009 |
| checking permissions | 0.000005 |
| Opening tables | 0.000016 |
| Waiting for global read lock | 9.412835 |
| Opening tables | 0.000540 |
| init | 0.000033 |
| System lock | 0.000014 |
| optimizing | 0.000006 |
| statistics | 0.000020 |
| preparing | 0.000016 |
| executing | 0.000004 |
| Sending data | 0.000241 |
| end | 0.000006 |
| query end | 0.002504 |
| closing tables | 0.000012 |
| freeing items | 0.000025 |
| logging slow query | 0.000009 |
| Opening tables | 0.000113 |
| System lock | 0.000362 |
| cleaning up | 0.000011 |
+------------------------------+----------+
21 rows in set, 1 warning (0.00 sec)

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

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

slow_log> SELECT start_time, query_time, lock_time, sql_text FROM mysql.slow_log;
Empty set (0.00 sec)

query> SELECT 9.41687900-9.412835;
+---------------------+
| 9.41687900-9.412835 |
+---------------------+
| 0.00404400 |
+---------------------+
1 row in set (0.00 sec)

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> SET SESSION long_query_time=0;
Query OK, 0 rows affected (0.00 sec)
lock> LOCK TABLE test.t0 WRITE;
Query OK, 0 rows affected (0.00 sec)
query> SELECT * FROM t0 LIMIT 1;
{此時hang住}
lock> LOCK TABLE test.t0 WRITE;
Query OK, 0 rows affected (0.00 sec)
query> {返回}
+----+---------------------+--------------------------------------+
| id | create_time | uuid |
+----+---------------------+--------------------------------------+
| 2 | 2017-11-14 15:13:33 | 994e4592-93b4-11e7-bff9-525400b3819a |
+----+---------------------+--------------------------------------+
1 row in set (28.89 sec)
slow_log> SELECT start_time, query_time, lock_time, sql_text FROM mysql.slow_log;
+----------------------------+-----------------+-----------------+----------------------------------+
| start_time | query_time | lock_time | sql_text |
+----------------------------+-----------------+-----------------+----------------------------------+
| 2017-11-15 17:13:12.252836 | 00:00:28.894675 | 00:00:28.894516 | SELECT * FROM t0 LIMIT 1 |
+----------------------------+-----------------+-----------------+----------------------------------+

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

tips：
某些場景下，一條十分簡單的sql也可能執行很長，被記錄到slow log，那麼可能就需要關注一下lock time是否很大了。

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

測試一下：

query> SET SESSION long_query_time=0;
Query OK, 0 rows affected (0.00 sec)
query> SELECT sysdate(), sleep(8), sysdate();
+---------------------+----------+---------------------+
| sysdate() | sleep(8) | sysdate() |
+---------------------+----------+---------------------+
| 2017-11-15 17:05:15 | 0 | 2017-11-15 17:05:23 |
+---------------------+----------+---------------------+
1 row in set (8.00 sec)

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

slow_log> SELECT start_time, query_time,lock_time,sql_text FROM mysql.slow_log;
+----------------------------+-----------------+-----------------+---------------------------------------+
| start_time | query_time | lock_time | sql_text |
+----------------------------+-----------------+-----------------+---------------------------------------+
| 2017-11-15 17:05:23.633771 | 00:00:08.000359 | 00:00:00.000000 | SELECT sysdate(), sleep(8), sysdate() |
+----------------------------+-----------------+-----------------+---------------------------------------+
1 row in set (0.00 sec)

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

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

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

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/29773961/viewspace-2147315/，如需轉載，請註明出處，否則將追究法律責任。

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

相關文章