MySQL慢查询时间分析
问题
mysql慢查询判断的起止时间是什么？包括了MDL锁、ROW锁的时间吗？从mysql的slow log中看输出了Query_time和Lock_time，感觉上应该是包括。
源码分析
Percona5.6.21
/*判断是否将query记入slow log中*/
log_slow_applicable{
ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query);
/*通过query_exec_time和后面提到server_status判断是否属于慢查询*/
}
/*通过server_status标记thd当前sql为慢查询*/
void update_server_status()
{
utime_after_query= current_utime();
if (utime_after_query > utime_after_lock + variables.long_query_time)
server_status|= SERVER_QUERY_WAS_SLOW;
}
/*获取query执行时间的方法，cur_utime - thd->utime_after_lock;
并且根据query执行时间是否大于thd->variables.long_query_timel来标记了thd的当前sql为慢查询*/
static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
{
ulonglong res;
#ifndef DBUG_OFF
if (thd->variables.query_exec_time != 0)
res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
thd->variables.query_exec_time : 0;
else
#endif
res= cur_utime - thd->utime_after_lock;
if (res > thd->variables.long_query_time)
thd->server_status|= SERVER_QUERY_WAS_SLOW;
else
thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
return res;
}
/*thd包括start_utime/utime_after_query/utime_after_lock*/
slow log的判断逻辑和输出的逻辑是不同的，所以导致困惑，只有当一个query执行时间（不包括锁等待的时间）>long_query_time的时候，才会判定会slow log；但是判定为slow log之后，输出包括Query_time（执行时间+锁等待时间），并且也会输出Lock_time时间。
所以会有这样的疑惑：为什么DBProxy记录的log时间很长，但是为什么没有在MySQL的slow log中记录呢？
if(log_slow_applicable(thd)){
log_slow_do(thd){
slow_log_print(thd, thd->query(), thd->query_length());
}
}
bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length)
{
if(current_utime < thd->start_utime)
{
query_utime= 0;
}
else
{
query_utime= (current_utime - thd->start_utime);
}
if(thd->utime_after_lock < thd->start_utime)
{
lock_utime= 0;
}
else
{
lock_utime= (thd->utime_after_lock - thd->start_utime);
}
}
SQL验证
Percona 5.6.34-79.1-log
CREATE TABLE `test` (
`id` int(11) NOT NULL DEFAULT '0',
`name` varchar(255) DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB
session1
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> update test set name="xx" where id=4;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
mysql> select sleep(5);
mysql> rollback;
Query OK, 0 rows affected (0.03 sec)
session2
mysql> update test set name="xx1" where id=4 and sleep(0.9);
Query OK, 0 rows affected (22.12 sec)
Rows matched: 0 Changed: 0 Warnings: 0
mysql> update test set name="xx1" where id=4 and sleep(1.1);
Query OK, 0 rows affected (15.38 sec)
Rows matched: 0 Changed: 0 Warnings: 0
针对session2查看mysql slow log，确认session2的第一个SQL是没有记录在慢查询中的，和源码分析是一致的。
# Time: 170125 7:14:39
# User@Host: guest[guest] @ localhost [127.0.0.1] Id: 5370
# Schema: test Last_errno: 0 Killed: 0
# Query_time: 15.378555 Lock_time: 14.274847 Rows_sent: 0 Rows_examined: 1 Rows_affected: 0
# Bytes_sent: 52
SET timestamp=1485328479;
update test set name="xx1" where id=4 and sleep(1.1);
MySQL社区版（5.7.17），😆，原谅我版本有点乱，MySQL社区版和Percona结果是一样，只是输出没有Percona的丰富，缺少了Rows_affected、Bytes_sent。
# Time: 2017-01-25T07:31:52.810785Z
# User@Host: root[root] @ localhost [] Id: 8
# Query_time: 5.422647 Lock_time: 4.319510 Rows_sent: 0 Rows_examined: 1
SET timestamp=1485329512;
update test set name='xx2' where id=1 and sleep(1.1);
结论
slow log的判断逻辑和输出的逻辑是不同的，所以导致困惑，只有当一个query执行时间（不包括锁等待的时间）>long_query_time的时候，才会判定会slow log；但是判定为slow log之后，输出包括Query_time（执行时间+锁等待时间），并且也会输出Lock_time时间。