当前位置： 移动技术网 > IT编程>数据库>Mysql > slow log判定是否会加上锁等待时间？

slow log判定是否会加上锁等待时间？

2020年07月14日  | 移动技术网IT编程  | 我要评论

作者徐晨亮，MySQL DBA，知数堂学员。热衷于数据库优化，自动化运维及数据库周边工具开发，对MySQL源码有一定的兴趣。

一 前言

对MySQL DBA而言，我们经常遇到 slow log，本文通过源码和案例实践来抽丝剥茧，slow log判定是否会加上锁等待时间？

二 talk is cheap,show me the code

1.slow log判定逻辑：

static 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;	
}

以上代码来自于percona 5.7.23版本 其中

res= cur_utime - thd->utime_after_lock

说明：T2(sql执行完成时间) - T1（获得锁的实际时间） = T（这个得出来的是SQL执行的实际时间），因此res也就是实际的执行时间。根据实际时间与变量的long_query_time比较:

超过long_query_time，那么判定为slow query 否则就不是

三 手工测试案例

环境说明：

参数value
long_query_time0.1
min_examined_row_limit0
log_queries_not_using_indexesOFF

3.1 测试过程

session1session2
begin;select * from t1 where id=1 for update;
-select * from t1 where id=1 for update;
rollback;
-1 row in set (9.61 sec)
此时，并没有记录到slow log，也符合源码中的定义

3.2 一个比较另类的测试

session1session2
flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)
-select * from tx;
-Table 'xucl.tx' doesn't exist
-insert into tx values(1);
几秒后
unlock tables;
Query OK, 0 rows affected (0.00 sec)
-ERROR 1146 (42S02): Table 'xucl.tx' doesn't exist

slow log输出如下：

# Time: 2019-07-05T04:27:42.785888Z	
# User@Host: root[root] @ localhost []  Id:  3129	
# Query_time: 12.035846  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0	
SET timestamp=1562300862;	
insert into tx values(1);

神奇的是竟然记录到了slow log里面，下面根据debug到的源码进行说明这个问题

insert SQL的入口是函数

640?wx_fmt=jpeg

insert会调用函数open_tables_for_query

640?wx_fmt=jpeg

open_tables_for_query又会调用open_tables

640?wx_fmt=jpeg

640?wx_fmt=jpeg

跑到这里打开表报错

640?wx_fmt=jpeg

到这里SQL完成，返回给客户端信息 

640?wx_fmt=jpeg

这里是记录slow log的入口

640?wx_fmt=jpeg

正常情况下，如果表存在那么会对表进行加锁

640?wx_fmt=jpeg

lock tables会调用mysql_lock_tables

640?wx_fmt=jpeg

mysql_lock_tables函数末尾会设置after_lock时间戳，也就是前面提到的utimeafter_lock

640?wx_fmt=jpeg

由于在打开表的时间就报错了，所以utime_after_lock即为0，这样根据公式

res= cur_utime - thd->utime_after_lock

直接由当前时间-0，超过long_query_time就被认定为slow query，也就记录在了slow log当中。为了便于理解，画成流程图如下：

640?wx_fmt=png

最后，感谢八怪高鹏老师的指点，尤其是入口函数的指点及思路分析

参考： 


在此强烈推荐一下八怪的《深入MySQL主从复制32讲》知识专栏，想要深入学习MySQL的同学们千万不要错过了，扫描下方二维码可订阅

640?wx_fmt=png


END



640?wx_fmt=png

640?wx_fmt=png




640?wx_fmt=gif


扫码加入MySQL技术Q群

（群号：650149401）

   

640?wx_fmt=jpeg




本文地址：https://blog.csdn.net/n88Lpo/article/details/97837727

您可能感兴趣的文章:

如对本文有疑问， 点击进行留言回复！！

相关文章:

验证码：
最近更新的文章
大家感兴趣的文章
移动技术网