专栏首页数据库架构之美MySQL源码解析之slow log实现机制

MySQL源码解析之slow log实现机制

Mysql slow log提供了一种方式对数据库中慢查询进行记录并且对日志进行输出,以便于我们定位服务器性能问题。我们可能会简单的把它理解为记录所有执行时间超过long_query_time的查询,其实这仅仅是其中一个条件。下面我们从源码角度分析一下slow log的写入机制。

我们先来看几个slow log相关的服务器参数,这些参数用来控制慢日志记录的规则,具体意义我们后面再进行分析。

slow_query_log:

Slow log的开关,是否开启slow log慢日志记录

slow_query_log_file:

Slow log日志的路径

long_query_time:

慢查询的执行的时间阈值

min_examined_row_limit:

慢查询检查的行数阈值

log_queries_not_using_indexes:

不走索引的查询是否被记录

log_throttle_queries_not_using_indexes:

不走索引被记录的语句条数阈值

log_slow_admin_statements:

对服务器管理语句是否进行记录

先来看看源码逻辑。慢日志主逻辑位于log.cc中,如下图所示:

我们可以很容易看到log_slow_do()函数用于慢日志的记录,而if语句中的log_slow_applicable()函数则用来判断某个语句是否是慢日志,那么这个函数就很重要了。现在我们来具体看看这个函数。

我们看到log_slow_applicable()是个布尔型函数,返回值为true或者false。我们观察到出现了一个unlikely()函数,这是mysql中很常见的一个函数,在源码中找到了unlikely()函数的定义:

bool unlikely(bool expr)

{

return expr;

}

可以看到unlikely是个布尔型函数,如果传入值为真,返回真,传入值为假返回假。那么这个if语句其实就是判断某个语句如果是stmt类型的,则直接返回false,也就是不进行日志记录,其实注释也写得很清楚,对于一个trigger或者stored function这类预处理的语句,slow log不进行记录。

再往下看,我们看到三个bool型变量:warn_no_index,log_this_query,suppress_logging,它们通过一定的条件控制真假。最后这个if中判断suppress_logging(阻止记录日志)为假并且log_this_query(记录日志)为真时才返回true。然后再返回看看上面三个变量,源码中可以看到warn_no_index指示了服务器参数log_queries_not_using_index是否开启,翻译一下就是如果一个查询没有使用索引,warn_no_index为真。再看log_this_query变量,该变量为真的条件是warn_no_index为真并且SERVER_QUERY_WAS_SLOW为真并且get_examined_row_count() 大于等于 min_examined_row_limit变量值这三个条件同时满足。关于SERVER_QUERY_WAS_SLOW,我们看看如下代码段:

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;

可以看到SERVER_QUERY_WAS_SLOW是通过语句执行时间进行判断的。这里我们对语句执行的几个时间进行一个说明:

Query_time:语句总执行时间

Lock_time:语句锁消耗时间

Exec_time:语句实际执行时间(评判标准)

语句实际执行时间=语句总查询时间-语句锁消耗时间

cur_utime是调用gettimeofday()函数取得当前时间,utime_after_lock是语句执行过程中锁等待完成后的时间,所以res其实就是语句的实际执行时间(不包含锁等待的实际),当res大于long_query_time变量值时,SERVER_QUERY_WAS_SLOW为真。所以SERVER_QUERY_SLOW是时间判断条件。

再来看看get_examined_row_count() >= variables.min_examined_row_limit这个条件,get_examined_row_count()函数用来取某个查询扫描的行数,实际扫描行数超过min_examined_row_limit变量值也是log_this_query为真的一个条件。

所以根据上面的分析,log_this_query其实有三个条件:①语句实际执行时间超过long_query_time;②扫描的行数超过min_examined_row_limit限制;③在log_queries_not_using_index开启的情况下,如果没走索引会被记录。

我们看到后面其实还有个suppress_logging,这个函数用来控制不走索引的语句阈值之外的语句不被记录,如果不走索引的查询都记录到慢日志中会造成慢日志增长过快,suppress_logging用于设置一个阈值(log_throttle_queries_not_using_indexes参数值),低于这个阈值数目的查询会将完整信息进行记录,高于阈值的只记录总的执行信息而不记录每一条执行的细节。再来看看suppress_logging的实现:

... ...

函数先把suppress_current变量置为false,函数的第二个变量eligible参数其实对应着log_slow_applicable()函数代码中调用的log_throttle_qni.log(thd,warn_no_index)中的warn_no_index参数,当eligible(warn_no_index)为真并且inc_log_count(*rate)为真时计算一下语句的总体执行时间已经锁消耗时间,并且把suppress_current设为true。然后我们看一下inc_log_count(*rate)函数。在log.h中对该函数进行了定义:

函数很简单,就是对count值进行++操作,直到count>rate时返回true,所以其实该函数就是用于找到阈值临界点,rate可以理解为log_throttle_queries_not_using_indexes参数值(临界点),当count++到该阈值时,就suppress this log,只计算一个总的时间。

下面对slow log的机制进行实验验证(使用sbtest1表):

实验1:验证long_query_time

Set long_query_time=0.1

在对k列不创建索引和创建索引的情况下分别执行select k from sbtest1 order by k;慢日志中记录如下:

然后set long_query_time=0.6;在对k列不创建索引和创建索引的情况下分别执行select k from sbtest1 order by k;慢日志中记录并没有变化。

结论:其他条件不考虑的情况下,实验中不走索引执行了0.37秒,走索引执行了0.25秒,但都大于0.1秒,所以慢日志中记录了信息,long_query_time改为0.6秒后,走不走索引都没有记录,该实验验证了long_query_time的作用。

实验2:验证lock_time对慢日志的影响

long_query_time=0.6

会话1锁表

Lock table sbtest1 write;

会话2查询,发现一直在等待

Select k from sbtest1 order by k;

然后会话1释放锁之后会话2可以查询出结果:

Unlock tables;

然后观察慢日志记录情况,发现依旧是老的信息,没有新的信息出现:

然后set long_query_time=0.1

然后执行上述步骤锁表,再查询,发现慢日志输出了信息:

结论:slow log中的记录的时间query_time是包含锁等待lock_time的,虽然query_time=4.4秒,远远超过了第一次long_query_time设置的0.6秒,但是慢日志却没有信息输出。这也正好验证了前面说的评判是否是慢查询标准其实不是query_time,而且query_time-lock_time的差值,这个差值与long_query_time进行对比。所以有时候数据库有些查询慢是锁等待造成的,而这种情况是不会记录在slow log里的。

实验3:验证min_examined_row_limit(sbtest1表中有300000条记录)

set session long_query_time=0.1;

set session min_examined_row_limit=310000;

执行查询结果如下,慢日志中没有输出:

然后set session min_examined_row_limit=290000;

发现slow log产生了日志:

结论:因为long_query_time=0.1,而查询语句的执行时间肯定超过这个值,但是在session min_examined_row_limit=310000的情况下,slow log并没有记录日志,由此看出slow log的记录并不是只看long_query_time的,它会同时检查超时时间以及扫描的行数限制,如果两个限制都超出的情况下才进行记录。这与源码逻辑一致。

实验4:验证log_queries_not_using_indexes

set session min_examined_row_limit=0

set session long_query_time=0.6

set global log_queries_not_using_indexes=on;

存在索引的情况下执行查询,发现slow log中没有记录信息

然后删除索引,执行查询,发现slow log中记录了慢查询信息:

结论:log_queries_not_using_indexes参数指定了不使用索引的查询是否记录在慢查询里,默认为off,开启后slow log的日志信息会显著增加。如果开启后,即使满足long_query_time和min_examined_row_limit的限制,也依旧会向slow log中记录日志。

实验5:验证log_throttle_queries_not_using_indexes

set session min_examined_row_limit=0

set session long_query_time=0.6

set global log_queries_not_using_indexes=on;

set global log_throttle_queries_not_using_indexes=2;(默认为0)

然后执行三次查询,结果如下:

结论:log_throttle_queries_not_using_indexes参数指定了每分钟记录到slow log中未使用索引的语句数量,超过这个数量将不记录语句的具体信息,只记录语句的总数量和总体花费时间。

最后这个图对slow log的判断机制进行了总结,如下图所示:

本文分享自微信公众号 - 数据库架构之美(databasekernel),作者:数据库架构之美

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

原始发表时间:2019-06-30

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

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 理论探究篇-MySQL源码解析之slow log实现机制

    Mysql slow log提供了一种方式对数据库中慢查询进行记录并且对日志进行输出,以便于我们定位服务器性能问题。我们可能会简单的把它理解为记录所有执行时间超...

    数据库架构之美
  • 基于repmgr的postgresql主备高可用方案

    本文比较基础,主要介绍postgresql开源高可用工具repmgr的部署和使用,初学者可以根据本文步骤一步一步做下去,废话不多说,直接进入主题,本文以两台机器...

    数据库架构之美
  • Kubernetes容器平台架构简析

    Docker自2013年发行以来,得到了飞速的发展,直至今日已经成为了基础架构中必不可缺的一份子,也是构建企业云平台的有效手段。而作为容器编排及管理的利器的ku...

    数据库架构之美
  • 理论探究篇-MySQL源码解析之slow log实现机制

    Mysql slow log提供了一种方式对数据库中慢查询进行记录并且对日志进行输出,以便于我们定位服务器性能问题。我们可能会简单的把它理解为记录所有执行时间超...

    数据库架构之美
  • MySQL——SQL查询优化

    慢查询日志 slow_query_log 启动停止记录慢查询日志,默认不启动 slow_query_log_file 指定慢查询日志的存储路径以及文件,默认...

    羊羽shine
  • 开启MYSQL慢查询日志,监控有效率问题的SQL景下的并发测试

    jmeter技术研究
  • MySQL 慢查询日志配置与简析

    a. 如果slow_query_log参数值为OFF则表示没开启,如果为ON则表示开启

    授客
  • Python代码性能优化

    Python使用非常方便、灵活,因此很受欢迎。但正因为如此,导致实现同一功能时,Python代码有很多写法,但不同的写法有不同的性能。因此写Python代码要有...

    Tyan
  • Mysql慢查询操作梳理

    Mysql慢查询解释 MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_quer...

    洗尽了浮华
  • Redis应用之限制访问频率

      我们知道当网站的访问量突然很大的时候肯定会对服务器造成影响,甚至无法访问,如果是正常的访问那么很好说明业务量增大可以考虑系统的扩展,但是如果是搜索引擎爬虫频...

    用户4919348

扫码关注云+社区

领取腾讯云代金券