源碼解析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的慢日志判斷過程完成。