详解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
详解MySQL慢日志(上)query_time\start_time\lock_time 的坑

但是这些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. query > SET profiling = 1 ,  SESSION long_query_time = 0 . 5 ;
  4. Query OK , 0 rows affected , 1 warning ( 0 . 00 sec )


  5. query > INSERT INTO t0 SELECT null , create_time , uuid FROM t1 LIMIT 1 ;
  6. { 此时hang住 }

  7. lock > UNLOCK TABLE ;

  8. query > { 返回 }
  9. Query OK , 1 row affected ( 9 . 42 sec )
  10. 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. query > SHOW PROFILE FOR QUERY 1 ;
  9. + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - +
  10. | Status                          | Duration |
  11. + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - +
  12. | starting                          | 0 . 000101 |
  13. | checking permissions         | 0 . 000009 |
  14. | checking permissions            | 0 . 000005 |
  15. | Opening tables                 | 0 . 000016 |
  16. | Waiting for global read lock | 9 . 412835 |
  17. | Opening tables                 | 0 . 000540 |
  18. | init                             | 0 . 000033 |
  19. | System lock                    | 0 . 000014 |
  20. | optimizing                      | 0 . 000006 |
  21. | statistics                      | 0 . 000020 |
  22. | preparing                       | 0 . 000016 |
  23. | executing                        | 0 . 000004 |
  24. | Sending data                     | 0 . 000241 |
  25. | end                                   | 0 . 000006 |
  26. | query end                        | 0 . 002504 |
  27. | closing tables                 | 0 . 000012 |
  28. | freeing items                     | 0 . 000025 |
  29. | logging slow query            | 0 . 000009 |
  30. | Opening tables                     | 0 . 000113 |
  31. | System lock                     | 0 . 000362 |
  32. | cleaning up                         | 0 . 000011 |
  33. + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - +
  34. 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. lock > LOCK TABLE test . t0 WRITE ;
  4. Query OK , 0 rows affected ( 0 . 00 sec )

  5. query > SELECT * FROM t0 LIMIT 1 ;
  6. { 此时hang住 }

  7. lock > LOCK TABLE test . t0 WRITE ;
  8. Query OK , 0 rows affected ( 0 . 00 sec )

  9. query > { 返回 }
  10. + - - - - + - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +
  11. | id | create_time          | uuid                                          |
  12. + - - - - + - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +
  13. | 2   | 2017-11-14 15:13:33 | 994e4592-93b4-11e7-bff9-525400b3819a |
  14. + - - - - + - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +
  15. 1 row in set ( 28 . 89 sec )

  16. slow_log > SELECT start_time , query_time , lock_time , sql_text FROM mysql . slow_log ;
  17. + - - - - - - - - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +
  18. | start_time                   | query_time        | lock_time       | sql_text                                |
  19. + - - - - - - - - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +
  20. | 2017-11-15 17:13:12 . 252836 | 00:00:28 . 894675 | 00:00:28 . 894516 | SELECT * FROM t0 LIMIT 1           |
  21. + - - - - - - - - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +

可以看到做一个简单查询,query_time也很长:
实际上query_time记录的是lock_time + real time。
query_time ≥ 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. query > SELECT sysdate ( ) , sleep ( 8 ) , sysdate ( ) ;
  4. + - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - +
  5. | sysdate ( )           | sleep ( 8 ) | sysdate ( )               |
  6. + - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - +
  7. | 2017-11-15 17:05:15 | 0         | 2017-11-15 17:05:23 |
  8. + - - - - - - - - - - - - - - - - - - - - - + - - - - - - - - - - + - - - - - - - - - - - - - - - - - - - - - +
  9. 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了。
作者微信公众号(持续更新)
详解MySQL慢日志(上)query_time\start_time\lock_time 的坑


当前标题:详解MySQL慢日志(上)query_time\start_time\lock_time的坑
网页网址:http://myzitong.com/article/jgggso.html