天天看点

源码解析MySQL慢日志slow_log记录相关函数与逻辑 源码解析MySQL慢日志记录相关函数与逻辑

源码解析MySQL慢日志记录相关函数与逻辑

操作环境

数据库版本:mysql-5.6.24 source code

操作系统版本:CentOS Linux release 7.6.1810 (Core)

以下主要函数的代码文件:

/mysql-5.6.24/sql/sql_class.h

/mysql-5.6.24/sql/sql_parse.cc

慢日志记录相关函数与逻辑

THD::update_server_status()函数

函数体

void update_server_status()

{

ulonglong end_utime_of_query= current_utime();

if (end_utime_of_query > utime_after_lock + variables.long_query_time)

server_status|= SERVER_QUERY_WAS_SLOW;

}

该函数主要进行慢查询的判断以及更新server_status,它判断慢查询的条件是:

end_utime_of_query > utime_after_lock + variables.long_query_time

其中:

end_utime_of_query来自于current_utime(),代码ulonglong end_utime_of_query= current_utime()进行了赋值。current_utime()是用来获取当前时间的,调用的是Linux操作系统(当前是linux系统)gettimeofday()函数。

utime_after_lock:这个值是指该SQL锁之后的时间,把SQL等待锁之后的时间作为真正的执行开始时间。假设SQL执行开始时间是1598532179899361(微秒),锁定时间假设进行了20秒(long_query_time为1秒)。而此处的utime_after_lock的值是1598532179899361+20秒的时间。这样变相的说明了,慢日志记录的SQL在进行耗时判断时,是不记录锁的(而MDL锁的时间是计算在内的,具体原因后面尝试讨论)。

variables.long_query_time:这是我们设置的long_query_time的时间。

所以这个函数主要是判断SQL的执行完成的时间加上long_query_time是否超过了当前时间(end_utime_of_query),以此判断是否是慢SQL,如果超过,则执行 server_status|= SERVER_QUERY_WAS_SLOW进行按位或且赋值运算(相当于server_status=server_status|SERVER_QUERY_WAS_SLOW),其中Mysql代码中定义SERVER_QUERY_WAS_SLOW值为2048,server_status是不确定的,会根据我们的SQL和使用方式进行赋值,我们测试时此处是2,则它们进行计算后,server_status值为2050(下面的log_slow_applicable()函数会用到)。

log_slow_statement()函数

void log_slow_statement(THD *thd)

DBUG_ENTER("log_slow_statement");

if (log_slow_applicable(thd))

log_slow_do(thd);

DBUG_VOID_RETURN;

update_server_status()函数判断完之后,继续执行,后面会执行log_slow_statement()函数,这个函数主要逻辑是:通过log_slow_applicable()判断该慢SQL是否可以记录到慢SQL里(具体逻辑下面说明),如果log_slow_applicable(thd)是true,则执行 log_slow_do(thd);

log_slow_applicable()函数

bool (THD *thd)

DBUG_ENTER("log_slow_applicable");

if (unlikely(thd->in_sub_stmt))

DBUG_RETURN(false); // Don't set time for sub stmt

if (thd->enable_slow_log)

bool warn_no_index= ((thd->server_status &

​ (SERVER_QUERY_NO_INDEX_USED |

​ SERVER_QUERY_NO_GOOD_INDEX_USED)) &&

​ opt_log_queries_not_using_indexes &&

​ !(sql_command_flags[thd->lex->sql_command] &

​ CF_STATUS_COMMAND));

bool log_this_query= ((thd->server_status & SERVER_QUERY_WAS_SLOW) ||

​ warn_no_index) &&

​ (thd->get_examined_row_count() >=

​ thd->variables.min_examined_row_limit);

bool suppress_logging= log_throttle_qni.log(thd, warn_no_index);

if (!suppress_logging && log_this_query)

DBUG_RETURN(true);

DBUG_RETURN(false);

该函数先判断是否开启了慢日志记录(if (thd->enable_slow_log)),如果开启,则进行如下判断:

一:判断warn_no_index是true还是false,主要判断:

​ 1, 使用thd->server_status和(SERVER_QUERY_NO_INDEX_USED|SERVER_QUERY_NO_GOOD_INDEX_USED)的值进行二进制的"位与&"运算,判断是否没有使用索引或者没有使用GOOD INDEX。其中SERVER_QUERY_NO_GOOD_INDEX_USED 值为16,SERVER_QUERY_NO_INDEX_USED值为32,thd->server_status前面已经计算过是2050。最终的运算式是:2050&(32|16),值为0。

​ 2,opt_log_queries_not_using_indexes 确认MySQL Server是否开启了log_queries_not_using_indexes参数。此处未开启,值为0。

​ 3,sql_command_flags[thd->lex->sql_command]和CF_STATUS_COMMAND)进行二进制的"位与&"运算,判断SQL的命令flag是否是CF_STATUS_COMMAND,然后进行"逻辑非 !"运算,其中sql_command_flags[thd->lex->sql_command]的值是变化的,会根据SQL类型不同而不同,此处由于我们使用的测试命令是show processlist,其值为4,CF_STATUS_COMMAND值为1U << 2(十进制是4)。最终的运算式是:4&4,值为4。进行"逻辑非 !"运算后是false。MySQL用这个条件来过滤admin_statements(slow log的参数log_slow_admin_statements)。只有当log_slow_admin_statements打开时,admin_statements进行比较时它才会为true。

最终的运算式是:0&&0&&false,值为false,这三个条件是"逻辑与&&"的关系,也就是三个条件必须全部是true,最终的warn_no_index才是true。

二:判断log_this_query是true还是false,主要判断:

​ 1,使用(thd->server_status & SERVER_QUERY_WAS_SLOW) 与warn_no_index的值进行"逻辑或||"运算。先对thd->server_status 和 SERVER_QUERY_WAS_SLOW两个的值进行二进制的"位与&"运算,其中thd->server_status值前面已经计算过为2050,SERVER_QUERY_WAS_SLOW值为2048,最终的运算式是:2050&2048,值为2048。然后再与warn_no_index进行"逻辑或||"运算,由于warn_no_index前面已经得出是false。2048||false的值为true。也就是这个表达式(thd->server_status & SERVER_QUERY_WAS_SLOW) ||warn_no_index)的值为true。

​ 2,使用thd->get_examined_row_count()与thd->variables.min_examined_row_limit比较,确认前者大于等于后者。这个主要是为了判断当前的慢查询的检索行数是否大于MySQL Server设置的变量min_examined_row_limit。由于我们测试时,min_examined_row_limit变量值并未进行设置,所以variables.min_examined_row_limit的值为0,此处表达式的结果为true。

最终的运算式是:true&&true,值为true。

三:判断是否要对慢日志进行suppress_logging,这个对应的MySQL server的log_throttle_queries_not_using_indexes 参数,由于我们测试时,其值并未设置,所以此处表达式的结果为false。

以上3个条件判断完成后,进行return的判断:

由于suppress_logging 值为false,所以!suppress_logging 值为true。log_this_query也是为true。最终条件成立,函数log_slow_applicable()函数返回true。

log_slow_do()函数

void log_slow_do(THD *thd)

DBUG_ENTER("log_slow_do");

THD_STAGE_INFO(thd, stage_logging_slow_query);

thd->status_var.long_query_count++;

if (thd->rewritten_query.length())

slow_log_print(thd,

​ thd->rewritten_query.c_ptr_safe(),

​ thd->rewritten_query.length());

else

slow_log_print(thd, thd->query(), thd->query_length());

log_slow_applicable(thd)返回为true,进入log_slow_do()函数。该函数主要进行慢日志的写入操作。这个函数会调用slow_log_print()函数。

至此,一个SQL的慢日志判断过程完成。