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

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

再看一下具体的profile：

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

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

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_time也很长：
实际上query_time记录的是lock_time + real time。
query_time ≥ lock_time

〇 start_time
为slow log中所记录的属性：
start_time：看字面意思很容易会被误认为“sql开始的时间”…
但实际上记录的是sql结束的时间。 测试一下：

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

可以看到，start_time实际上是sql执行完成的时间。
真正的开始时间计算的方法也很简单：
start_time - query_time 即为sql真正开始的时间。


tips：
一般OLTP场景下，大部分query_time都会很短。
但在某些糟糕的场景下，如某一条OLAP语句执行时间很长，如30分钟。
如果需要确认在某个时段的sql，在查询slow log时指定错误的start_time，可能就无法找到合适的sql了。
作者微信公众号（持续更新）