详解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>,下同:
目前创新互联公司已为上千家的企业提供了网站建设、域名、雅安服务器托管、网站托管维护、企业网站设计、富顺网站维护等服务,公司将坚持客户导向、应用为本的策略,正道将秉承"和谐、参与、激情"的文化,与客户和合作伙伴齐心协力一起成长,共同发展。
-
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真正开始的时间。
tips:
一般OLTP场景下,大部分query_time都会很短。
但在某些糟糕的场景下,如某一条OLAP语句执行时间很长,如30分钟。
如果需要确认在某个时段的sql,在查询slow log时指定错误的start_time,可能就无法找到合适的sql了。
作者微信公众号(持续更新)
网站栏目:详解MySQL慢日志(上)query_time\start_time\lock_time的坑
本文路径:http://scyingshan.cn/article/jgggso.html