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

背景

生產(chǎn)環(huán)境中 select count(*) from table 語(yǔ)句執(zhí)行很慢，已經(jīng)遠(yuǎn)超 long_query_time 參數(shù)定義的慢查詢時(shí)間值，但是卻沒(méi)有記錄到慢日志中。

在測(cè)試環(huán)境也很容易復(fù)現(xiàn)出該問(wèn)題，慢查詢?nèi)罩敬_實(shí)沒(méi)有記錄 select count(*) 語(yǔ)句。

慢查詢相關(guān)參數(shù)設(shè)置如下：

slow_query_log=1#開(kāi)啟慢查詢?nèi)罩?slow_query_log_file=/mydata/3306/log/mysql.slow.log#慢查詢?nèi)罩疚募夸?log_queries_not_using_indexes=1#開(kāi)啟記錄未使用索引的SQL
log_slow_admin_statements=1#開(kāi)啟記錄管理語(yǔ)句
log_slow_slave_statements=1#開(kāi)啟主從復(fù)制中從庫(kù)的慢查詢
log_throttle_queries_not_using_indexes=10#限制每分鐘寫入慢日志的未用索引的SQL的數(shù)量
long_query_time=2#定義慢查詢的SQL執(zhí)行時(shí)長(zhǎng)
min_examined_row_limit=100#該SQL檢索的行數(shù)小于100則不會(huì)記錄到慢日志

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

因此，慢查詢?nèi)罩静粦?yīng)該沒(méi)有記錄到執(zhí)行時(shí)間超過(guò)long_query_time 的 select count(*) 語(yǔ)句。

慢查詢?nèi)罩驹创a剖析

為了一探到底，在 MySQL 源碼中找到了以下記錄慢查詢?nèi)罩镜南嚓P(guān)函數(shù)，本文所涉及的 MySQL 數(shù)據(jù)庫(kù)版本為 8.0.32。

sql_class.cc 文件中的 update_slow_query_status 函數(shù)：

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

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

log.cc 文件中的 log_slow_applicable 和 log_slow_statement 函數(shù)：

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 是否滿足記錄慢查詢?nèi)罩镜臈l件：

server_status 標(biāo)記為 SERVER_QUERY_WAS_SLOW或warn_no_index（沒(méi)有使用索引）;

該 SQL 檢索的行數(shù) >= min_examined_row_limit 參數(shù)定義的行數(shù)。

如果該 SQL 同時(shí)滿足以上記錄慢查詢?nèi)罩镜臈l件，那么則調(diào)用 log_slow_do 函數(shù)寫慢查詢?nèi)罩尽?/p>

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

MySQL 源碼調(diào)試

在 MySQL 源碼的 debug 環(huán)境中，開(kāi)啟 gdb 調(diào)試，對(duì)相關(guān)函數(shù)打下斷點(diǎn)，這樣便可以通過(guò)跟蹤源碼弄清楚一條 SQL 記錄慢查詢?nèi)罩具^(guò)程中函數(shù)和變量的情況。

(gdb)bTHD::update_slow_query_status
(gdb)blog_slow_applicable
// 在客戶端執(zhí)行一條 SQL：select count(*) from user_test，跟蹤源碼執(zhí)行到 update_slow_query_status函數(shù)時(shí)，可以發(fā)現(xiàn)這時(shí)候這條SQL的執(zhí)行時(shí)長(zhǎng)已經(jīng)超過(guò)了long_query_time參數(shù)值，并且把這條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 函數(shù)時(shí)，可以發(fā)現(xiàn)函數(shù) thd->get_examined_row_count() 的返回值為 0。也就是說(shuō)這條 SQL 檢索的行數(shù)為 0 行，小于當(dāng)前設(shè)置的 min_examined_row_limit 參數(shù)值 100，所以這條 SQL 沒(méi)有記錄到慢查詢?nèi)罩局小６褩Ｐ畔⒓按蛴∽兞枯敵鋈缦拢?/p>

(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() 當(dāng)前返回值
$4=0
(gdb)pthd->variables.min_examined_row_limit//打印 min_examined_row_limit 變量值
$5=100

原因

通過(guò)跟蹤源碼，可以查明 select count(*) from table 語(yǔ)句沒(méi)有寫入到慢日志中是因?yàn)?MySQL 把此類 SQL 的檢索行數(shù)計(jì)算為 0 行，小于 min_examined_row_limit 參數(shù)值。

因此，把 min_examined_row_limit 參數(shù)設(shè)置為 0 后，再次執(zhí)行 select count(*)，可以看到在慢查詢?nèi)罩局?，這條 SQL 執(zhí)行完成后就被記錄了。且慢查詢?nèi)罩局械男畔@示這條 SQL 檢索的行數(shù)為 0 行，返回的行數(shù)為 1 行。

所以要想把慢的 select count(*) 記錄到慢查詢?nèi)罩局校琺in_examined_row_limit 這個(gè)參數(shù)必須保持為默認(rèn)值 0。

但是生產(chǎn)環(huán)境中一般會(huì)開(kāi)啟 log_queries_not_using_indexes 參數(shù)，為了避免慢查詢?nèi)罩居涗洐z索行數(shù)較少的全表掃描的 SQL，需要設(shè)置 min_examined_row_limit 為某個(gè)大于 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 存儲(chǔ)引擎中，每次執(zhí)行 select count(*) from table 都會(huì)遍歷全表或二級(jí)索引然后統(tǒng)計(jì)行數(shù)，不應(yīng)該把 Rows_examined 計(jì)算成 0。

MySQL 官方確認(rèn) #110804

結(jié)語(yǔ)

雖然現(xiàn)在的 MySQL 數(shù)據(jù)庫(kù)大多數(shù)部署在云上或者使用了數(shù)據(jù)庫(kù)管理平臺(tái)收集慢查詢，慢查詢?nèi)罩究赡懿皇鞘走x的排查問(wèn)題 SQL 的方法。

但是對(duì)于沒(méi)有額外配置慢查詢監(jiān)控的 MySQL，慢查詢?nèi)罩救匀皇且粋€(gè)非常好的定位慢 SQL 的方法，配合 pt-query-digest 工具使用分析某段時(shí)間的 TOP SQL 也十分方便。

并且數(shù)據(jù)庫(kù)管理平臺(tái)收集的慢查詢數(shù)據(jù)需要額外的數(shù)據(jù)庫(kù)存放，一般都會(huì)設(shè)置保留一段時(shí)間，如果要回溯更早的慢 SQL 就只能通過(guò)慢查詢?nèi)罩玖恕?/p>

審核編輯：劉清