源码解析丨一次慢 SQL 排查
当long_query_time=1时（表 info 的 id 为主键），出现下面的慢日志，可能会让你吃惊
# Time: 2024-01-28T22:52:24.500491+08:00# User@Host: root[root] @ [127.0.0.1] Id: 8# Query_time: 7.760787 Lock_time: 7.757456 Rows_sent: 0 Rows_examined: 0use apple;SET timestamp=1706453536;delete from info where id < 10;
复制代码
环境信息
慢查询相关参数
greatsql> select * from performance_schema.global_variables where variable_name in('slow_query_log','log_output','slow_query_log_file','long_query_time','log_queries_not_using_indexes','log_slow_admin_statements','min_examined_row_limit','log_throttle_queries_not_using_indexes') order by variable_name;+----------------------------------------+-------------------------------------+| VARIABLE_NAME | VARIABLE_VALUE |+----------------------------------------+-------------------------------------+| log_output | FILE || log_queries_not_using_indexes | OFF || log_slow_admin_statements | OFF || log_throttle_queries_not_using_indexes | 0 || long_query_time | 1.000000 || min_examined_row_limit | 0 || slow_query_log | ON || slow_query_log_file | /root/local/8026/log/slow.log |+----------------------------------------+-------------------------------------+8 rows in set (10.49 sec)
复制代码
slow_query_log：慢日志开关
log_output：慢日志存储方式，FILE 或 TABLE
long_query_time：慢日志阈值
min_examined_row_limit：设置慢 SQL 的最小 examined 扫描行数，建议设置为 0，因为有 bug：https://bugs.mysql.com/bug.php?id=110804
log_queries_not_using_indexes：不使用索引的慢查询日志是否记录到索引
log_slow_admin_statements：在写入慢速查询日志的语句中包含慢速管理语句（create index,drop index,alter table,analyze table,check table,optimize table,repair table）默认是不会记录的
log_throttle_queries_not_using_indexes：用于限制每分钟输出未使用索引的日志数量。每分钟允许记录到 slow log 的且未使用索引的 sql 语句次数，配合 long_queries_not_using_indexes 开启使用。
log_slow_slave_statements：默认 OFF，是否开启主从复制中从库的慢查询
根本原因
一、慢日志写入大致流程
dispatch_command(thd)
thd->enable_slow_log = true // 初始化 enable_slow_log 为 true
thd->set_time // 设置开始时间
dispatch_sql_command
parse_sql // 语法解析
mysql_execute_command // 执行 SQL
lex->m_sql_cmd->execute // 常见的 CRUD 操作
thd->update_slow_query_status // 判断是否达到慢日志阈值。若为慢查询，则更新 thd 的 server_status 状态，为写 slow_log 作准备
log_slow_statement
log_slow_applicable // 判断是否写入慢日志
log_slow_do // 开始写入
slow_log_write
log_slow
write_slow
二、判断是否达到慢日志阈值
void THD::update_slow_query_status() { if (my_micro_time() > utime_after_lock + variables.long_query_time) server_status | = SERVER_QUERY_WAS_SLOW;}// my_micro_time() 获取当前系统时间点，单位为微妙// utime_after_lock 为MDL LOCK和row lock等待时间后的时间点，单位为微妙// variables.long_query_time 慢日志阈值long_query_time * 1000000 ，单位为微妙// 等价于：my_micro_time() - utime_after_lock > variables.long_query_time// 不包含锁等待时间
复制代码
void THD::update_slow_query_status() { if (my_micro_time() > start_utime + variables.long_query_time) server_status | = SERVER_QUERY_WAS_SLOW;}// 判别标准变成了：（语句执行结束的时间 - 语句开始执行时间） > 慢日志阈值// my_micro_time() 当前系统时间点，单位为微妙// start_utime：语句开始执行时间点，单位为微妙// variables.long_query_time 慢日志阈值long_query_time * 1000000 ，单位为微妙// 包含锁等待时间
复制代码
从上面可以看出慢日志的判断标准发生了根本变化
举例说明
greatsql> select * from info;+----+------+| id | name |+----+------+| 1 | 1 || 2 | 2 || 5 | 5 || 60 | 8 || 40 | 11 || 20 | 20 || 30 | 30 |+----+------+7 rows in set (0.05 sec)
greatsql> show create table info\G*************************** 1. row *************************** Table: infoCreate Table: CREATE TABLE `info` ( `id` int NOT NULL AUTO_INCREMENT, `name` int NOT NULL, PRIMARY KEY (`id`), UNIQUE KEY `uk_name` (`name`)) ENGINE=InnoDB AUTO_INCREMENT=61 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci1 row in set (0.02 sec)
复制代码
• 在 8.0.26 版本中，是不会记录 session2 中的delete from info where id < 10
• 在 8.0.32 版本中，会记录 session2 中的delete from info where id < 10
三、判断是否写入慢日志
void log_slow_statement(THD *thd, struct System_status_var *query_start_status) { if (log_slow_applicable(thd)) log_slow_do(thd, query_start_status);}
//----------------------------------------------------------------
bool log_slow_applicable(THD *thd) { DBUG_TRACE;
/* The following should never be true with our current code base, but better to keep this here so we don't accidently try to log a statement in a trigger or stored function */ if (unlikely(thd->in_sub_stmt)) return false; // Don't set time for sub stmt
if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;
/* Do not log administrative statements unless the appropriate option is set. */ if (thd->enable_slow_log && opt_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) return true; } return false;}
复制代码
若 log_slow_applicable(thd)返回值为 true，则执行 log_slow_do(thd, query_start_status)，写入慢日志
if (unlikely(thd->in_sub_stmt)) return false;if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;
a. 子查询，返回 false
b. 被 kill，返回 false
c. 解析出错，返回 false
d. 执行出错，返回 false
warn_no_index 表示 log_queries_not_using_indexes 开启且（未使用索引或未使用最优索引）
thd->server_status 该线程状态
SERVER_QUERY_NO_INDEX_USED 表示未使用索引
SERVER_QUERY_NO_GOOD_INDEX_USED 表示未使用最优索引
opt_log_queries_not_using_indexes 表示 log_queries_not_using_indexes 参数的值，默认 OFF
!(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))表示该语句不是 SHOW 相关的命令。CF_STATUS_COMMAND 常量表示执行的命令为 show 相关的命令。
log_this_query = ((thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index) && (thd->get_examined_row_count() >=thd->variables.min_examined_row_limit);
(thd->server_status & SERVER_QUERY_WAS_SLOW) 表示该 SQL 为慢查询
(thd->get_examined_row_count() >=thd->variables.min_examined_row_limit) 表示 SQL 的扫描数据行数不小于参数 min_examined_row_limit 的值，默认为 0
log_throttle_qni.log(thd, warn_no_index) 表示用来计算该条未使用索引的 SQL 是否需要写入到 slow log，计算需要使用到参数 log_throttle_queries_not_using_indexes , 该参数表明允许每分钟写入到 slow log 中的未使用索引的 SQL 的数量，默认值为 0，表示不限制
按照线上配置
log_throttle_queries_not_using_indexes = 0
log_queries_not_using_indexes = OFF
log_slow_admin_statements = OFF
min_examined_row_limit = 0
slow_query_log = ON
long_query_time = 1.000000
那么在 GreatSQL-8.0.26 中，是否写入到慢日志中，取决于thd->server_status & SERVER_QUERY_WAS_SLOW，即 SQL 执行总耗时-SQL 锁等待耗时>1 秒
那么在 GreatSQL-8.0.32 中，是否写入到慢日志中，取决于thd->server_status & SERVER_QUERY_WAS_SLOW，即 SQL 执行总耗时>1 秒
评论