一條本該記錄到慢日志的SQL是如何被漏掉的？

背景

生產環(huán)境中 select count(*) from table 語句執(zhí)行很慢，已經遠超 long_query_time 參數定義的慢查詢時間值，但是卻沒有記錄到慢日志中。

在測試環(huán)境也很容易復現(xiàn)出該問題，慢查詢日志確實沒有記錄 select count(*) 語句。

慢查詢相關參數設置如下：

slow_query_log=1#開啟慢查詢日志
slow_query_log_file=/mydata/3306/log/mysql.slow.log#慢查詢日志文件目錄
log_queries_not_using_indexes=1#開啟記錄未使用索引的SQL
log_slow_admin_statements=1#開啟記錄管理語句
log_slow_slave_statements=1#開啟主從復制中從庫的慢查詢
log_throttle_queries_not_using_indexes=10#限制每分鐘寫入慢日志的未用索引的SQL的數量
long_query_time=2#定義慢查詢的SQL執(zhí)行時長
min_examined_row_limit=100#該SQL檢索的行數小于100則不會記錄到慢日志

select count(*) 執(zhí)行原理可以總結如下：InnoDB 存儲引擎在執(zhí)行 select count(*) 時，Server 層遍歷讀取 InnoDB 層的二級索引或主鍵，然后按行計數。

因此，慢查詢日志不應該沒有記錄到執(zhí)行時間超過long_query_time 的 select count(*) 語句。

慢查詢日志源碼剖析

為了一探到底，在 MySQL 源碼中找到了以下記錄慢查詢日志的相關函數，本文所涉及的 MySQL 數據庫版本為 8.0.32。

sql_class.cc 文件中的 update_slow_query_status 函數：

voidTHD::update_slow_query_status(){
if(my_micro_time()>start_utime+variables.long_query_time)
server_status|=SERVER_QUERY_WAS_SLOW;
}

my_micro_time 函數返回的是當前時間，如果當前時間大于這條 SQL 執(zhí)行的開始時間加 long_query_time 參數定義的時長，則更新這條 SQL 的 server_status 為 SERVER_QUERY_WAS_SLOW。

log.cc 文件中的 log_slow_applicable 和 log_slow_statement 函數：

boollog_slow_applicable(THD*thd){
......

boolwarn_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));
boollog_this_query=
((thd->server_status&SERVER_QUERY_WAS_SLOW)||warn_no_index)&&
(thd->get_examined_row_count()>=thd->variables.min_examined_row_limit);

//Thedocssayslowqueriesmustbecountedevenwhenthelogisoff.
if(log_this_query)thd->status_var.long_query_count++;

/*
Donotlogadministrativestatementsunlesstheappropriateoptionis
set.
*/
if(thd->enable_slow_log&&opt_slow_log){
boolsuppress_logging=log_throttle_qni.log(thd,warn_no_index);

if(!suppress_logging&&log_this_query)returntrue;
}
returnfalse;
}

判斷該 SQL 是否滿足記錄慢查詢日志的條件：

server_status 標記為 SERVER_QUERY_WAS_SLOW或warn_no_index（沒有使用索引）;

該 SQL 檢索的行數 >= min_examined_row_limit 參數定義的行數。

如果該 SQL 同時滿足以上記錄慢查詢日志的條件，那么則調用 log_slow_do 函數寫慢查詢日志。

voidlog_slow_statement(THD*thd){
if(log_slow_applicable(thd))log_slow_do(thd);
}

MySQL 源碼調試

在 MySQL 源碼的 debug 環(huán)境中，開啟 gdb 調試，對相關函數打下斷點，這樣便可以通過跟蹤源碼弄清楚一條 SQL 記錄慢查詢日志過程中函數和變量的情況。

(gdb)bTHD::update_slow_query_status
(gdb)blog_slow_applicable
// 在客戶端執(zhí)行一條 SQL：select count(*) from user_test，跟蹤源碼執(zhí)行到 update_slow_query_status函數時，可以發(fā)現(xiàn)這時候這條SQL的執(zhí)行時長已經超過了long_query_time參數值，并且把這條SQL的server_status更新為SERVER_QUERY_WAS_SLOW。
查看堆棧信息如下：
(gdb)bt
#0THD::update_slow_query_status(this=0x7f7d6000dcb0)at/root/gdb_mysql/mysql-8.0.32/sql/sql_class.cc:3217
#10x000000000329ddaaindispatch_command(thd=0x7f7d6000dcb0,com_data=0x7f7dc43f1a00,command=COM_QUERY)at/root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:2422
#20x000000000329a7d3indo_command(thd=0x7f7d6000dcb0)at/root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:1439
#30x00000000034b925finhandle_connection(arg=0xc966100)at/root/gdb_mysql/mysql-8.0.32/sql/conn_handler/connection_handler_per_thread.cc:302
#40x00000000051e835cinpfs_spawn_thread(arg=0xc9c0940)at/root/gdb_mysql/mysql-8.0.32/storage/perfschema/pfs.cc:2986
#50x00007f7ddff35ea5instart_thread()from/lib64/libpthread.so.0
#60x00007f7dde95db0dinclone()from/lib64/libc.so.6
(gdb)n
3218server_status|=SERVER_QUERY_WAS_SLOW;
(gdb)n
3219}

跟蹤源碼執(zhí)行到 log_slow_applicable 函數時，可以發(fā)現(xiàn)函數 thd->get_examined_row_count() 的返回值為 0。也就是說這條 SQL 檢索的行數為 0 行，小于當前設置的 min_examined_row_limit 參數值 100，所以這條 SQL 沒有記錄到慢查詢日志中。堆棧信息及打印變量輸出如下：

(gdb)bt
#0log_slow_applicable(thd=0x7f7d6000dcb0)at/root/gdb_mysql/mysql-8.0.32/sql/log.cc:1592
#10x00000000038ce8c5inlog_slow_statement(thd=0x7f7d6000dcb0)at/root/gdb_mysql/mysql-8.0.32/sql/log.cc:1661
#20x000000000329dff7indispatch_command(thd=0x7f7d6000dcb0,com_data=0x7f7dc43f1a00,command=COM_QUERY)at/root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:2456
#30x000000000329a7d3indo_command(thd=0x7f7d6000dcb0)at/root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:1439
#40x00000000034b925finhandle_connection(arg=0xc966100)at/root/gdb_mysql/mysql-8.0.32/sql/conn_handler/connection_handler_per_thread.cc:302
#50x00000000051e835cinpfs_spawn_thread(arg=0xc9c0940)at/root/gdb_mysql/mysql-8.0.32/storage/perfschema/pfs.cc:2986
#60x00007f7ddff35ea5instart_thread()from/lib64/libpthread.so.0
#70x00007f7dde95db0dinclone()from/lib64/libc.so.6

(gdb)pthd->get_examined_row_count()//打印 thd->get_examined_row_count() 當前返回值
$4=0
(gdb)pthd->variables.min_examined_row_limit//打印 min_examined_row_limit 變量值
$5=100

原因

通過跟蹤源碼，可以查明 select count(*) from table 語句沒有寫入到慢日志中是因為 MySQL 把此類 SQL 的檢索行數計算為 0 行，小于 min_examined_row_limit 參數值。

因此，把 min_examined_row_limit 參數設置為 0 后，再次執(zhí)行 select count(*)，可以看到在慢查詢日志中，這條 SQL 執(zhí)行完成后就被記錄了。且慢查詢日志中的信息顯示這條 SQL 檢索的行數為 0 行，返回的行數為 1 行。

所以要想把慢的 select count(*) 記錄到慢查詢日志中，min_examined_row_limit 這個參數必須保持為默認值 0。

但是生產環(huán)境中一般會開啟 log_queries_not_using_indexes 參數，為了避免慢查詢日志記錄檢索行數較少的全表掃描的 SQL，需要設置 min_examined_row_limit 為某個大于 0 的值。

#User@Host:root[root]@localhost[]Id:8
#Query_time:2.833550Lock_time:0.000013Rows_sent:1Rows_examined:0
usetestdb;
SETtimestamp=1681844004;
selectcount(*)fromuser_test;

提交 BUG

在 InnoDB 存儲引擎中，每次執(zhí)行 select count(*) from table 都會遍歷全表或二級索引然后統(tǒng)計行數，不應該把 Rows_examined 計算成 0。

MySQL 官方確認 #110804

結語

雖然現(xiàn)在的 MySQL 數據庫大多數部署在云上或者使用了數據庫管理平臺收集慢查詢，慢查詢日志可能不是首選的排查問題 SQL 的方法。

但是對于沒有額外配置慢查詢監(jiān)控的 MySQL，慢查詢日志仍然是一個非常好的定位慢 SQL 的方法，配合 pt-query-digest 工具使用分析某段時間的 TOP SQL 也十分方便。

并且數據庫管理平臺收集的慢查詢數據需要額外的數據庫存放，一般都會設置保留一段時間，如果要回溯更早的慢 SQL 就只能通過慢查詢日志了。

審核編輯：劉清