详解MySQL慢日志 query_time start_time lock_time 的坑

发布时间：2022-03-26 06:36:26 所属栏目：MySql教程来源：互联网

导读：详解MySQL慢日志（下）选项参数篇：〇 long_query_time 场景：部分 binlog截取： 9：42：25 后，还有几个6：35：30的event 但是这些event如图中最后一条。 exec_time为11216，但并未被记录到slow log中。 long_query_time 为一个MySQL选项参数。这个

详解MySQL慢日志（下）选项参数篇：

〇 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

〇 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真正开始的时间。

（编辑：云计算网_泰州站长网）

【声明】本站内容均来自网络，其相关言论仅代表作者个人观点，不代表本站立场。若无意侵犯到您的权利，请及时与联系站长删除相关内容!

MySQL之日志管制	如何使用mysql索引
Anemometer图形化显示	mysql数据库explain命