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

2019-12-27 20:00:09 浏览数 (1)

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的判断机制进行了总结,如下图所示:

0 人点赞