专栏首页idbaslow log判定是否会加上锁等待时间?

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

作者徐晨亮,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_time

0.1

min_examined_row_limit

0

log_queries_not_using_indexes

OFF

3.1 测试过程

session1

session2

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 一个比较另类的测试

session1

session2

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的入口是函数

insert会调用函数open_tables_for_query

open_tables_for_query又会调用open_tables

跑到这里打开表报错

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

这里是记录slow log的入口

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

lock tables会调用mysql_lock_tables

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

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

res= cur_utime - thd->utime_after_lock

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

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

参考 xcode源码调试文档

-The End-

本文分享自微信公众号 - yangyidba(yangyidba),作者:徐晨亮

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2019-07-27

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • MySQL 安装利器---Sandbox

    一 sandbox是什么? MySQL Sandbox是一个非常简单快捷的安装搭建MySQL实例的工具,它可以非常快速地满足我们对MySQL环境各种需求:单机实...

    用户1278550
  • 技术分享|delete 语句引发大量 sql 被kill 问题分析

    报警的意思是每分钟超过200个sql被kill,是一个严重告警级别,会打电话给DBA。大半夜报警的确令人不爽,那么如何解决这个问题呢?

    用户1278550
  • 死锁案例之五

    死锁其实是一个很有意思也很有挑战的技术问题,大概每个DBA和部分开发朋友都会在工作过程中遇见。关于死锁我会持续写一个系列的案例分析,希望能够对想了解死锁的朋友...

    用户1278550
  • 51Nod-1054-最长等差数列

    ACM模版 描述 ? 题解 额,最近不知道 51Nod51Nod 怎么了,一下子井喷了好多题,不过这个题就是 1055最长等差数列1055 最长等差数列 的一个...

    f_zyj
  • Jmeter接口测试实战-数据传递

    接口与接口之间没有关联的测试是缺乏意义和没有灵魂的,只有数据在不同接口之间传递才能勾画出业务场景重要的链路. 我们用较为通用的http/https协议,接口普遍...

    louiezhou001
  • 【USACO 2.3】Cow Pedigrees(DP)

    dp[i][j]=dp[lk][ln]*dp[rk][j-1-ln],max(lk,rk)=i-1。

    饶文津
  • 画图太丑拿不出手?有人做了套机器学习专用画图模板,还有暗黑模式

    论文、博客写好了,里面的图可怎么画?对于很多研究人员和开发者来说,内容的「可视化」是一个大问题。如果从头开始画,配色、空间布局都很伤脑筋,而且画丑了也拿不出手,...

    机器之心
  • 并行排序ShearSort ---[MPI , c++]

    Gxjun
  • 2019腾讯广告算法大赛入门-Part2(初赛生存篇)

    初赛A榜即将结束,同时组队时间也快要结束,对于还未组队的小伙伴,我的建议找些分数差不多的童鞋组队,自己的思维总是局限的,组队后不仅可以提分,还能交流学习。

    Coggle数据科学
  • 容器服务9月月报:TKE Kubernetes 1.14 版本全量上线

    随着全球云计算产业高速发展,越来越多的企业选择业务上云,为了能够为广大用户提供更好、更全面的产品功能与使用体验,我们正在不断努力中。9月份,我们在容器服务的产品...

    腾讯云原生

扫码关注云+社区

领取腾讯云代金券