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