MySQL源码解析: slow log

Posted 2021-04-04 步出夏门行

通常理解mysql slow log是记录所有执行时间超过log_query_time的查询，其实这只是其中的一个条件。下面先看看slow log相关的配置参数。

slow_query_log	是否启用慢日志。
log_output	general log和slow log的输出目标。允许取值TABLE、FILE、NONE，默认FILE。若取值为NONE，即使slow_query_log=ON也不会写慢日志。
slow_query_log_file	如果log_output=FILE，该系统参数决定慢日志文件位置。
long_query_time	决定一个query是否slow的时间阈值(默认10，单位s)。 当一个查询耗时超过long_query_time，服务器会增加Slow_queries状态变量。 查询耗时采用real time，而不是CPU time。因此一个SQL可能在服务器负载较轻时在阈值之下，而负载较重时在阈值之上。 该值最小可以为0，即变相支持毫秒级别，可以设置为0.001表示1ms。 为避免日志过多，官方手册建议该阈值不要小于1s，很小的值仅适用于测试环境或生产环境短时间开启。
min_examined_row_limit	默认值0。查询扫描的行数小于该值则不会被记录到slow log。
log_queries_not_using_indexes	默认OFF。如果启用了该参数且慢日志开启，表示期望所有查询都通过索引。即使SQL耗时在long_query_time以内，不走索引也会被记入慢日志。 但该选项并不一定表示查询没有用到索引。比如一个全索引扫描的查询可能被记入慢查询日志，因为该索引可能没有用于过滤条件。
log_throttle_queries_not_using_indexes	默认值0表示无限制。如果启用了log_queries_not_using_indexes，则log_throttle_queries_not_using_indexes限制每分钟写入慢日志的不走索引查询条数，避免慢日志记录太多。
log_slow_admin_statements	默认值OFF。慢日志是否记录管理语句，如ALTER TABLE、CREATE INDEX、REPARE TABLE、DROP INDEX等。

 

慢查询日志的主要逻辑：

mysql_8.0.22/sql/log.cc

Query_logger query_logger; ...... bool log_slow_applicable(THD *thd) {   DBUG_TRACE;   //xk> 对于一个trigger或stored function这类预处理语句不记慢日志。   /*     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。     /*     Do not log administrative statements unless the appropriate option is     set.   */   //xk> 根据系统参数设置确定是否判定为慢SQL   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; }   /**   Unconditionally writes the current statement (or its rewritten version if it   exists) to the slow query log.   @param thd                   thread handle   @param query_start_status  Pointer to a snapshot of thd->status_var taken at the start of execution。 */ //xk> 慢日志中SQL执行耗时不记SQL开始执行之前的阻塞等待时间。 void log_slow_do(THD *thd, struct System_status_var *query_start_status) {   THD_STAGE_INFO(thd, stage_logging_slow_query); //xk> 增加状态变量计数   thd->status_var.long_query_count++;  //xk> 如果SQL语句被重写了   if (thd->rewritten_query().length())     query_logger.slow_log_write(thd, thd->rewritten_query().ptr(),                                 thd->rewritten_query().length(),                                 query_start_status);   else  //xk> 如果是原始SQL语句     query_logger.slow_log_write(thd, thd->query().str, thd->query().length,                                 query_start_status); }   /**   Check whether we need to write the current statement to the slow query   log. If so, do so. This is a wrapper for the two functions above;   most callers should use this wrapper.  Only use the above functions   directly if you have expensive rewriting that you only need to do if   the query actually needs to be logged (e.g. SP variables / NAME_CONST   substitution when executing a PROCEDURE).   A digest of suppressed statements may be logged instead of the current   statement.     @param thd                   thread handle   @param query_start_status  Pointer to a snapshot of thd->status_var taken at the start of execution */ 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); }

log_slow_statement()函数只是log_slow_do()函数的简单封装。log_slow_applicable()函数判断某个语句是否需要记入慢日志，log_slow_do()则实现写入慢日志这个操作。

调用栈跟踪如下：

#4 File_query_log::write_slow() #3 Log_to_file_event_handler::log_slow() #2 Query_logger::slow_log_write() #1 log_slow_do()

File_query_log::write_slow()负责具体写文件，第一个参数THD *thd是连接处理线程的指针，根据这个顺藤摸瓜可以自定义输出很多内容了。

MySQL官方也意识到慢查询日志提供的诊断信息太少，MySQL 8.0.14引入了log_slow_extra系统变量，可以往慢日志文件中写入更多慢SQL信息，比如该SQL创建了多少临时表，这些信息基本也都是根据THD指针捞出来的：