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

源码解析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的慢日志判断过程完成。