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

1. lock> FLUSH TABLE WITH READ LOCK;
   
2. Query OK, 0 rows affected (0.00 sec)
   
3. 
   
4. query> SET profiling = 1, SESSION long_query_time=0.5;
   
5. Query OK, 0 rows affected, 1 warning (0.00 sec)
   
6. 
   
7. 
   
8. query> INSERT INTO t0 SELECT null, create_time, uuid FROM t1 LIMIT 1;
   
9. {此时hang住}
   
10. 
    
11. lock> UNLOCK TABLE;
    
12. 
    
13. query> {返回}
    
14. Query OK, 1 row affected (9.42 sec)
    
15. Records: 1 Duplicates: 0 Warnings: 0

此处看到，整条SQL花费了9.42秒完成，其中包括长时间的锁等待。

再看一下具体的profile：

1. query> SHOW PROFILES;
   
2. +----------+------------+---------------------------------------------------------------+
   
3. | Query_ID | Duration   | Query                                                         |
   
4. +----------+------------+---------------------------------------------------------------+
   
5. | 1        | 9.41687900 | INSERT INTO t0 SELECT null, create_time, uuid FROM t1 LIMIT 1 |
   
6. +----------+------------+---------------------------------------------------------------+
   
7. 1 row in set, 1 warning (0.00 sec)
   
8. 
   
9. query> SHOW PROFILE FOR QUERY 1;
   
10. +------------------------------+----------+
    
11. | Status                       | Duration |
    
12. +------------------------------+----------+
    
13. | starting                     | 0.000101 |
    
14. | checking permissions         | 0.000009 |
    
15. | checking permissions         | 0.000005 |
    
16. | Opening tables               | 0.000016 |
    
17. | Waiting for global read lock | 9.412835 |
    
18. | Opening tables               | 0.000540 |
    
19. | init                         | 0.000033 |
    
20. | System lock                  | 0.000014 |
    
21. | optimizing                   | 0.000006 |
    
22. | statistics                   | 0.000020 |
    
23. | preparing                    | 0.000016 |
    
24. | executing                    | 0.000004 |
    
25. | Sending data                 | 0.000241 |
    
26. | end                          | 0.000006 |
    
27. | query end                    | 0.002504 |
    
28. | closing tables               | 0.000012 |
    
29. | freeing items                | 0.000025 |
    
30. | logging slow query           | 0.000009 |
    
31. | Opening tables               | 0.000113 |
    
32. | System lock                  | 0.000362 |
    
33. | cleaning up                  | 0.000011 |
    
34. +------------------------------+----------+
    
35. 21 rows in set, 1 warning (0.00 sec)

可以看到，等待全局读锁花了9.412835s，总执行时间约为9.42。

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

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

1. query> SELECT 9.41687900-9.412835;
   
2. +---------------------+
   
3. | 9.41687900-9.412835 |
   
4. +---------------------+
   
5. | 0.00404400          |
   
6. +---------------------+
   
7. 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的总时间

1. query> SET SESSION long_query_time=0;
   
2. Query OK, 0 rows affected (0.00 sec)
   
3. 
   
4. lock> LOCK TABLE test.t0 WRITE;
   
5. Query OK, 0 rows affected (0.00 sec)
   
6. 
   
7. query> SELECT * FROM t0 LIMIT 1;
   
8. {此时hang住}
   
9. 
   
10. lock> LOCK TABLE test.t0 WRITE;
    
11. Query OK, 0 rows affected (0.00 sec)
    
12. 
    
13. query> {返回}
    
14. +----+---------------------+--------------------------------------+
    
15. | id | create_time         | uuid                                 |
    
16. +----+---------------------+--------------------------------------+
    
17. | 2  | 2017-11-14 15:13:33 | 994e4592-93b4-11e7-bff9-525400b3819a |
    
18. +----+---------------------+--------------------------------------+
    
19. 1 row in set (28.89 sec)
    
20. 
    
21. slow_log> SELECT start_time, query_time, lock_time, sql_text FROM mysql.slow_log;
    
22. +----------------------------+-----------------+-----------------+----------------------------------+
    
23. | start_time                 | query_time      | lock_time       | sql_text                         |
    
24. +----------------------------+-----------------+-----------------+----------------------------------+
    
25. | 2017-11-15 17:13:12.252836 | 00:00:28.894675 | 00:00:28.894516 | SELECT * FROM t0 LIMIT 1         |
    
26. +----------------------------+-----------------+-----------------+----------------------------------+

可以看到做一个简单查询，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结束的时间。


测试一下：

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

可以看到，该sql开始时间是17:05:15，结束时间是17:05:23
那么记录在slow log中，实际上是：

1. slow_log> SELECT start_time, query_time,lock_time,sql_text FROM mysql.slow_log;
   
2. +----------------------------+-----------------+-----------------+---------------------------------------+
   
3. | start_time                 | query_time      | lock_time       | sql_text                              |
   
4. +----------------------------+-----------------+-----------------+---------------------------------------+
   
5. | 2017-11-15 17:05:23.633771 | 00:00:08.000359 | 00:00:00.000000 | SELECT sysdate(), sleep(8), sysdate() |
   
6. +----------------------------+-----------------+-----------------+---------------------------------------+
   
7. 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/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/29773961/viewspace-2147315/