From 88c7a58ecf231865492729f892f6aafe72cafdad Mon Sep 17 00:00:00 2001 From: Sujatha Date: Wed, 12 May 2021 18:03:45 +0530 Subject: [PATCH] MDEV-22530: Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server. Problem: ======== Aborting OPTIMIZE TABLE still logs in binary logs and replicates to the Slave server. "Optimize table" command under execution, is killed by using "Ctrl-C" as shown below. MariaDB [test]> optimize table t2; ^CCtrl-C -- query killed. Continuing normally. In spite of query execution being interrupted the query gets written to binary log. Analysis: ======== Admin command execution logic is not handling KILL command, hence it ignores the KILL command and completes its execution. Fix: === Check for thread killed notification, during admin command execution and handle it. If thread kill occurs prior to any table modification the query will not be written to binary log. If kill happens after at least one table is modified then the query will be written to binary log. Ex: command in execution is 'OPTIMIZE TABLE t1,t2' and the thread kill happens after t1 table is modified then 'OPTIMIZE TABLE t1,t2' will be written to binary log as admin commands will not make the slave to diverge from master. --- .../binlog/r/binlog_admin_cmd_kill.result | 40 ++++++++ .../suite/binlog/t/binlog_admin_cmd_kill.test | 95 +++++++++++++++++++ sql/sql_admin.cc | 10 +- 3 files changed, 144 insertions(+), 1 deletion(-) create mode 100644 mysql-test/suite/binlog/r/binlog_admin_cmd_kill.result create mode 100644 mysql-test/suite/binlog/t/binlog_admin_cmd_kill.test diff --git a/mysql-test/suite/binlog/r/binlog_admin_cmd_kill.result b/mysql-test/suite/binlog/r/binlog_admin_cmd_kill.result new file mode 100644 index 00000000000..a2eb7ee5c0a --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_admin_cmd_kill.result @@ -0,0 +1,40 @@ +# +# Kill OPTIMIZE command prior to table modification +# +RESET MASTER; +CREATE TABLE t1 (f INT) ENGINE=INNODB; +CREATE TABLE t2 (f INT) ENGINE=INNODB; +connect con1,127.0.0.1,root,,test,$MASTER_MYPORT,; +connection con1; +SET debug_sync='admin_command_kill_before_modify SIGNAL ready_to_be_killed WAIT_FOR master_cont'; +OPTIMIZE TABLE t1,t2; +connection default; +SET debug_sync='now WAIT_FOR ready_to_be_killed'; +KILL THD_ID; +SET debug_sync = 'reset'; +disconnect con1; +include/show_binlog_events.inc +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 # Gtid # # GTID #-#-# +master-bin.000001 # Query # # use `test`; CREATE TABLE t1 (f INT) ENGINE=INNODB +master-bin.000001 # Gtid # # GTID #-#-# +master-bin.000001 # Query # # use `test`; CREATE TABLE t2 (f INT) ENGINE=INNODB +DROP TABLE t1,t2; +FLUSH LOGS; +# +# Kill OPTIMIZE command after table modification +# +CREATE TABLE t1 (f INT) ENGINE=INNODB; +CREATE TABLE t2 (f INT) ENGINE=INNODB; +connect con1,127.0.0.1,root,,test,$MASTER_MYPORT,; +connection con1; +SET debug_sync='admin_command_kill_after_modify SIGNAL ready_to_be_killed WAIT_FOR master_cont'; +OPTIMIZE TABLE t1,t2; +connection default; +SET debug_sync='now WAIT_FOR ready_to_be_killed'; +KILL THD_ID; +SET debug_sync = 'reset'; +disconnect con1; +DROP TABLE t1,t2; +FLUSH LOGS; +FOUND 1 /OPTIMIZE TABLE t1,t2/ in mysqlbinlog.out diff --git a/mysql-test/suite/binlog/t/binlog_admin_cmd_kill.test b/mysql-test/suite/binlog/t/binlog_admin_cmd_kill.test new file mode 100644 index 00000000000..9b248097ae2 --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_admin_cmd_kill.test @@ -0,0 +1,95 @@ +# ==== Purpose ==== +# +# Test verifies that when an admin command execution is interrupted by KILL +# command it should stop its execution. The admin command in binary log should +# contain only the list of tables which have successfully executed admin +# command prior to kill. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Create two table t1,t2. +# 1 - Execute OPTIMIZE TABLE t1,t2 command. +# 2 - Using debug sync mechanism kill OPTIMIZE TABLE command at a stage +# where it has not optimized any table. +# 3 - Check that OPTIMIZE TABLE command is not written to binary log. +# 4 - Using debug sync mechanism hold the execution of OPTIMIZE TABLE after +# t1 table optimization. Now kill the OPTIMIZE TABLE command. +# 5 - Observe the binlog output, the OPTIMIZE TABLE command should display `t1,t2`. +# 6 - Please note that, we binlog the entire query even if at least one +# table is modified as admin commands are safe to replicate and they will +# not make the slave to diverge. +# +# ==== References ==== +# +# MDEV-22530: Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server. +# +--source include/have_log_bin.inc +--source include/have_debug.inc +--source include/have_debug_sync.inc +--source include/have_innodb.inc + +--echo # +--echo # Kill OPTIMIZE command prior to table modification +--echo # +RESET MASTER; + +CREATE TABLE t1 (f INT) ENGINE=INNODB; +CREATE TABLE t2 (f INT) ENGINE=INNODB; + +--connect(con1,127.0.0.1,root,,test,$MASTER_MYPORT,) +--connection con1 +SET debug_sync='admin_command_kill_before_modify SIGNAL ready_to_be_killed WAIT_FOR master_cont'; +--send OPTIMIZE TABLE t1,t2 + +--connection default +SET debug_sync='now WAIT_FOR ready_to_be_killed'; +--let $thd_id= `SELECT ID FROM INFORMATION_SCHEMA.PROCESSLIST WHERE INFO LIKE '%OPTIMIZE TABLE %'` + +# Now kill. +--replace_result $thd_id THD_ID +eval KILL $thd_id; + +SET debug_sync = 'reset'; +--disconnect con1 + +--source include/show_binlog_events.inc +DROP TABLE t1,t2; + +FLUSH LOGS; + +--echo # +--echo # Kill OPTIMIZE command after table modification +--echo # + +CREATE TABLE t1 (f INT) ENGINE=INNODB; +CREATE TABLE t2 (f INT) ENGINE=INNODB; + +--connect(con1,127.0.0.1,root,,test,$MASTER_MYPORT,) +--connection con1 +SET debug_sync='admin_command_kill_after_modify SIGNAL ready_to_be_killed WAIT_FOR master_cont'; +--send OPTIMIZE TABLE t1,t2 + +--connection default +SET debug_sync='now WAIT_FOR ready_to_be_killed'; +--let $thd_id= `SELECT ID FROM INFORMATION_SCHEMA.PROCESSLIST WHERE INFO LIKE '%OPTIMIZE TABLE %'` + +# Now kill. +--replace_result $thd_id THD_ID +eval KILL $thd_id; + +SET debug_sync = 'reset'; +--disconnect con1 + +DROP TABLE t1,t2; +let $binlog_file= query_get_value(SHOW MASTER STATUS, File, 1); +FLUSH LOGS; + +--let $MYSQLD_DATADIR= `select @@datadir` +--exec $MYSQL_BINLOG $MYSQLD_DATADIR/$binlog_file > $MYSQLTEST_VARDIR/tmp/mysqlbinlog.out + +--let SEARCH_PATTERN= OPTIMIZE TABLE t1,t2 +--let SEARCH_FILE= $MYSQLTEST_VARDIR/tmp/mysqlbinlog.out +--source include/search_pattern_in_file.inc + +--remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog.out diff --git a/sql/sql_admin.cc b/sql/sql_admin.cc index 2b3593388bb..21afa1154f6 100644 --- a/sql/sql_admin.cc +++ b/sql/sql_admin.cc @@ -446,6 +446,7 @@ static bool mysql_admin_table(THD* thd, TABLE_LIST* tables, int compl_result_code; bool need_repair_or_alter= 0; wait_for_commit* suspended_wfc; + bool is_table_modified= false; DBUG_ENTER("mysql_admin_table"); DBUG_PRINT("enter", ("extra_open_options: %u", extra_open_options)); @@ -496,6 +497,10 @@ static bool mysql_admin_table(THD* thd, TABLE_LIST* tables, bool open_for_modify= org_open_for_modify; DBUG_PRINT("admin", ("table: '%s'.'%s'", table->db, table->table_name)); + DEBUG_SYNC(thd, "admin_command_kill_before_modify"); + + if (thd->is_killed()) + break; strxmov(table_name, db, ".", table->table_name, NullS); thd->open_options|= extra_open_options; table->lock_type= lock_type; @@ -1192,6 +1197,8 @@ send_result_message: { if (trans_commit_stmt(thd)) goto err; + if (!is_table_modified) + is_table_modified= true; } close_thread_tables(thd); thd->release_transactional_locks(); @@ -1214,8 +1221,9 @@ send_result_message: if (protocol->write()) goto err; + DEBUG_SYNC(thd, "admin_command_kill_after_modify"); } - if (is_cmd_replicated && !thd->lex->no_write_to_binlog) + if (is_table_modified && is_cmd_replicated && !thd->lex->no_write_to_binlog) { if (write_bin_log(thd, TRUE, thd->query(), thd->query_length())) goto err;