理论探究篇-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的判断机制进行了总结，如下图所示：