• 博客访问: 810710
  • 博文数量: 155
  • 用 户 组: 普通用户
  • 注册时间: 2014-07-28 23:51
  • 认证徽章:
个人简介

很久前写的博文可能错误较多,仅供参考。 转载请注明出处: 作者:神谕。博客地址:http://blog.itpub.net/29773961/。 后续主要更新v公众号:fantasy-life-

文章分类

全部博文(155)

文章存档

2018年(6)

2017年(23)

2016年(38)

2015年(63)

2014年(25)

分类: MySQL

2017-11-15 18:25:39


详解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. query> SET profiling = 1SESSION 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

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. 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了。



作者微信公众号(持续更新)


阅读(594) | 评论(0) | 转发(0) |
给主人留下些什么吧!~~
评论热议
请登录后评论。

登录 注册