捉虫日记 | MySQL 8.0从库某些情况下记录重放的CREATE TABLE、DROP TABLE语句到慢日志(slow log)

作者：卢文双 资深数据库内核研发

本文首发于 2023-11-30 20:47:35

https://dbkernel.com

问题描述

当主从复制采用 binlog 的行模式时，如果从库启用 slow_query_log、log_slow_replica_statements 且从库重放 CREATE TABLE、DROP TABLE 时因特殊情况（比如被从库其他 SQL 占用 MDL 锁）执行耗时较长，会被从库记录到慢日志（slow log），而 ALTER TABLE 却不会被记录到慢日志。

ALTER TABLE 等管理语句是否会记录到慢日志，受参数 slow_query_log、log_slow_admin_statements 控制。

本文基于 MySQL 8.0.30 版本。

复现步骤

1. 搭建主从复制

主（master）、从（replica）my.cnf 中启用 binlog 的行模式：

binlog_format=ROW # 行模式

2. 从库动态设置配置参数

set global long_query_time=0.0001;
# 当然，除了这种方法，还有另一种方法：
# 主库执行DROP TABLE db1.tbl 语句之前，在从库先用事务阻塞住 DROP TABLE db1.tbl 的重放（会处于 Waiting for table metadata lock 状态）：
# begin; select count(*) from db1.tbl for update;
# 等待几秒后（大于long_query_time的配置即可），再 commit

set global slow_query_log=on;
set global log_slow_replica_statements=on;

mysql> show variables like '%slow%';
+-----------------------------+----------------------------------------------------------+
| Variable_name               | Value                                                    |
+-----------------------------+----------------------------------------------------------+
| log_slow_admin_statements   | OFF                                                      |
| log_slow_extra              | OFF                                                      |
| log_slow_replica_statements | ON                                                       |
| log_slow_slave_statements   | ON                                                       |
| slow_launch_time            | 2                                                        |
| slow_query_log              | ON                                                       |
| slow_query_log_file         | /home/wslu/work/mysql/mysql80-data/s1-slave1/vm-slow.log |
+-----------------------------+----------------------------------------------------------+
7 rows in set (0.01 sec)

3. 主库执行 SQL 语句

CREATE TABLE db1.tbl(a int, b int);
DROP TABLE db1.tbl;

4. 查看从库慢日志

查看从库slow_query_log_file参数指定的慢日志文件，其中出现 DROP TABLE 语句：

# Time: 2023-11-30T09:36:32.202303+08:00
# User@Host: skip-grants user[] @  []  Id:    41
# Query_time: 0.060373  Lock_time: 0.000143 Rows_sent: 0  Rows_examined: 0
SET timestamp=1701308185;
CREATE TABLE `tbl` (
  `my_row_id` bigint unsigned NOT NULL AUTO_INCREMENT /*!80023 INVISIBLE */,
  `a` int DEFAULT NULL,
  `b` int DEFAULT NULL,
  PRIMARY KEY (`my_row_id`)
);
# Time: 2023-11-30T09:36:37.768072+08:00
# User@Host: skip-grants user[] @  []  Id:    41
# Query_time: 0.025328  Lock_time: 0.000089 Rows_sent: 0  Rows_examined: 0
SET timestamp=1701308197;
DROP TABLE `tbl` /* generated by server */;

初步分析

这与官方对 log_slow_slave_statements 参数的描述不符：

When the slow query log is enabled, log_slow_replica_statements enables logging for queries that have taken more than long_query_time seconds to execute on the replica. Note that if row-based replication is in use (binlog_format=ROW), log_slow_replica_statements has no effect. Queries are only added to the replica's slow query log when they are logged in statement format in the binary log, that is, when binlog_format=STATEMENT is set, or when binlog_format=MIXED is set and the statement is logged in statement format. Slow queries that are logged in row format when binlog_format=MIXED is set, or that are logged when binlog_format=ROW is set, are not added to the replica's slow query log, even if log_slow_replica_statements is enabled.

Setting log_slow_replica_statements has no immediate effect. The state of the variable applies on all subsequent START REPLICA statements. Also note that the global setting for long_query_time applies for the lifetime of the SQL thread. If you change that setting, you must stop and restart the replication SQL thread to implement the change there (for example, by issuing STOP REPLICA and START REPLICA statements with the SQL_THREAD option).

按照官方的描述，在 binlog_format 是行模式的情况下，即使启用log_slow_replica_statements 参数，从库重放时也不该产生慢日志。

补充说明：

按照上述同样的步骤执行 ALTER TABLE 语句，则不会记录到 slow log。

通过阅读手册及自行验证，ALTER TABLE 等管理语句是否记录到从库的 slow log 受参数log_slow_admin_statements控制。

log_slow_admin_statements

Include slow administrative statements in the statements written to the slow query log. Administrative statements include ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE.

代码解读

函数堆栈：

#0  Query_logger::slow_log_write (this=0xaaaaef99e760 <query_logger>, thd=0xffff3c291be0, query=0xffff34165cb8 "DROP TABLE `tbl` /* generated by server */",
    query_length=42, aggregate=false, lock_usec=0, exec_usec=0) at /home/wslu/work/mysql/mac-mysql-server/sql/log.cc:1334
#1  0x0000aaaaead81368 in log_slow_do (thd=0xffff3c291be0) at /home/wslu/work/mysql/mac-mysql-server/sql/log.cc:1643
#2  0x0000aaaaead813a0 in log_slow_statement (thd=0xffff3c291be0) at /home/wslu/work/mysql/mac-mysql-server/sql/log.cc:1660
#3  0x0000aaaaeb9ce438 in Query_log_event::do_apply_event (this=0xffff341ce540, rli=0xffff3402ad80,
    query_arg=0xffff34165cb8 "DROP TABLE `tbl` /* generated by server */", q_len_arg=42) at /home/wslu/work/mysql/mac-mysql-server/sql/log_event.cc:4884
#4  0x0000aaaaeb9cc840 in Query_log_event::do_apply_event (this=0xffff341ce540, rli=0xffff3402ad80)
    at /home/wslu/work/mysql/mac-mysql-server/sql/log_event.cc:4447
#5  0x0000aaaaeb9f43c4 in Log_event::do_apply_event_worker (this=0xffff341ce540, w=0xffff3402ad80)
    at /home/wslu/work/mysql/mac-mysql-server/sql/log_event.cc:1087
#6  0x0000aaaaebacb3a4 in Slave_worker::slave_worker_exec_event (this=0xffff3402ad80, ev=0xffff341ce540)
    at /home/wslu/work/mysql/mac-mysql-server/sql/rpl_rli_pdb.cc:1733
#7  0x0000aaaaebacda04 in slave_worker_exec_job_group (worker=0xffff3402ad80, rli=0xaaab2f98d4d0)
    at /home/wslu/work/mysql/mac-mysql-server/sql/rpl_rli_pdb.cc:2457
#8  0x0000aaaaebae84d4 in handle_slave_worker (arg=0xffff3402ad80) at /home/wslu/work/mysql/mac-mysql-server/sql/rpl_replica.cc:5913
#9  0x0000aaaaec8356f0 in pfs_spawn_thread (arg=0xffff784dd4e0) at /home/wslu/work/mysql/mac-mysql-server/storage/perfschema/pfs.cc:2942
#10 0x0000ffff928bd5c8 in start_thread (arg=0x0) at ./nptl/pthread_create.c:442
#11 0x0000ffff92925d1c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:79

最终会调用Query_logger::slow_log_write函数：

bool Query_logger::slow_log_write(THD *thd, const char *query,
                                  size_t query_length, bool aggregate,
                                  ulonglong lock_usec, ulonglong exec_usec) {
  assert(thd->enable_slow_log && opt_slow_log);

  if (!(*slow_log_handler_list)) return false;

  /* do not log slow queries from replication threads */
  if (thd->slave_thread && !opt_log_slow_replica_statements) return false; // ====> 关键位置

  /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
  char user_host_buff[MAX_USER_HOST_SIZE + 1];
  Security_context *sctx = thd->security_context();
  LEX_CSTRING sctx_user = sctx->user();
  LEX_CSTRING sctx_host = sctx->host();
  LEX_CSTRING sctx_ip = sctx->ip();
  size_t user_host_len =
      (strxnmov(user_host_buff, MAX_USER_HOST_SIZE, sctx->priv_user().str, "[",
                sctx_user.length ? sctx_user.str : "", "] @ ",
                sctx_host.length ? sctx_host.str : "", " [",
                sctx_ip.length ? sctx_ip.str : "", "]", NullS) -
       user_host_buff);
  ulonglong current_utime = my_micro_time();
  ulonglong query_utime, lock_utime;
  if (aggregate) {
    query_utime = exec_usec;
    lock_utime = lock_usec;
  } else if (thd->start_utime) {
    query_utime = (current_utime - thd->start_utime);
    lock_utime = thd->get_lock_usec();
  } else {
    query_utime = 0;
    lock_utime = 0;
  }

  bool is_command = false;
  if (!query) {
    is_command = true;
    const std::string &cn = Command_names::str_global(thd->get_command());
    query = cn.c_str();
    query_length = cn.length();
  }

  mysql_rwlock_rdlock(&LOCK_logger);

  bool error = false;
  for (Log_event_handler **current_handler = slow_log_handler_list;
       *current_handler;) {
    error |= (*current_handler++)
                 ->log_slow(thd, current_utime,
                            (thd->start_time.tv_sec * 1000000ULL) +
                                thd->start_time.tv_usec,
                            user_host_buff, user_host_len, query_utime,
                            lock_utime, is_command, query, query_length); // 写慢日志
  }

  mysql_rwlock_unlock(&LOCK_logger);

  return error;
}

结论

我查看了 8.0.31-8.0.35 版本的 change log，其中并无对DROP TABLE相关的 Bug Fix，说明该问题官方尚未修复。

可行的修改思路有两种：

1. 比较直接的方式是修改Query_logger::slow_log_write函数中的逻辑，添加额外的条件判断（见后文）。
2. 借鉴参数log_slow_admin_statements的处理逻辑。如果启用log_slow_admin_statements参数且管理语句执行时长大于 long_query_time，则会将其记录到慢日志，最终也会调用到Query_logger::slow_log_write函数；反之，如果未启用该参数，则不会记录管理语句到慢日志。这说明是在中间过程中判断并过滤的，本文不再展开说明。

公司同事向官方提交了 BUG，官方已经确认，其中的 patch 采用的思路 1：

MySQL Bugs: #113251: the slow log in slave is logged ,when binlog_format is row

--- a/sql/log.cc
+++ b/sql/log.cc
@@ -1295,6 +1295,9 @@ bool Query_logger::slow_log_write(THD *t
   /* do not log slow queries from replication threads */
   if (thd->slave_thread && !opt_log_slow_replica_statements) return false;

+  /*when binlog_format=MIXED is set, or that are logged when binlog_format=ROW is set, are not added to the replica's slow query log, even if log_slow_replica_statements is enabled.*/
+  if (thd->slave_thread && opt_log_slow_replica_statements && (thd->current_stmt_binlog_format == BINLOG_FORMAT_MIXED ||thd->current_stmt_binlog_format == BINLOG_FORMAT_ROW) ) return false;
+
   /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
   char user_host_buff[MAX_USER_HOST_SIZE + 1];
   Security_context *sctx = thd->security_context();

欢迎关注我的微信公众号【数据库内核】：分享主流开源数据库和存储引擎相关技术。