From 7dcf56b2442a46879d3a04a304e2a7a355cf62d2 Mon Sep 17 00:00:00 2001 From: Venkatesh Prasad Venugopal Date: Fri, 19 Feb 2021 12:58:44 +0530 Subject: [PATCH] Bug #102647: Replica sql_thread getting stuck due to MASTER_DELAY Problem ------- The replication applier thread in a multi-threaded replica randomly gets stuck in Waiting until MASTER_DELAY seconds after master executed event and doesn't apply any transaction for a long time when the replica is configured with MASTER_DELAY. Background ---------- After the bugfix of BUG#17326020 (commit: 3f6ed37f), when the receiver thread reconnects to its source using GTID auto positioning while in the middle of a transaction, it leaves the partial transaction on the relaylog as is and will fully retrieve the same transaction again. While doing so, the receiver thread, as per GTID auto-position protocol will write master's FORMAT_DESCRIPTION_EVENT with log_pos != 0 into the relay log after each (re)connection. This FORMAT_DESCRIPTION_EVENT shall look like below in the relay log. ===BEGIN=== # at 4 #210215 16:18:05 server id 1 end_log_pos 123 CRC32 0x1120fc25 Start: binlog v 4, server v 5.7.32-35-debug-log created 210215 16:18:05 # This Format_description_event appears in a relay log and was generated by the slave thread. # at 123 #210215 16:18:05 server id 1 end_log_pos 154 CRC32 0xa29c149c Previous-GTIDs # [empty] # at 154 #700101 5:30:00 server id 1111 end_log_pos 0 CRC32 0x93c56c74 Rotate to mysql-bin.000001 pos: 4 # at 201 #210215 14:19:18 server id 1111 end_log_pos 123 CRC32 0x25802c3f Start: binlog v 4, server v 5.7.32-35-debug-log created 210215 14:19:18 at startup ROLLBACK/*!*/; BINLOG ' jjUqYA9XBAAAdwAAAHsAAAAAAAQANS43LjMyLTM1LWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAACONSpgEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA AT8sgCU= '/*!*/; # at 320 #210215 16:18:05 server id 0 end_log_pos 367 CRC32 0xdd12fd05 Rotate to mysql-bin.000001 pos: 154 # at 367 ===END=== When the applier thread starts applying the FORMAT_DESCRIPTION_EVENT (at position 201), it checks if it is in the middle of a group. If it is, it will queue to the current worker a QUERY(ROLLBACK) event to make the worker gracefully finish its work before starting to apply the new (complete) copy of the group, and only after that it will let the MTS coordinator to apply the ROTATE_LOG_EVENT (at position 320) in synchronous mode. Analysis -------- In our tests, it was observed that the replication applier thread got stuck when it was applying the Query_log_event (ROLLBACK) as part of handling the partial relay log event. On further investigation, it was found that the Query_log_event (for BEGIN/ROLLBACK) created by the applier thread had the current time as its timestamp. As a result, the delay function `slave_sleep()` slept for MASTER_DELAY seconds since the event timestamp was less than the evaluated current timestamp. Fix --- Make the BEGIN/ROLLBACK query to execute with same timestamp as that of the master's FORMAT_DESCRIPTION_EVENT in `coord_handle_partial_binlogged_transaction()` function. This patch additionally also adds a .cnf file for the test `rpl_mts_gtids_restart_slave_io_lost_trx.test` so that the test is not skipped on MTR runs with default options. --- .../rpl_gtids_restart_slave_io_lost_trx.test | 35 ++++++ ...slave_io_lost_trx_with_master_delay.result | 104 ++++++++++++++++++ ..._gtids_restart_slave_io_lost_trx-slave.opt | 1 - ...pl_mts_gtids_restart_slave_io_lost_trx.cnf | 12 ++ ...rt_slave_io_lost_trx_with_master_delay.cnf | 12 ++ ...t_slave_io_lost_trx_with_master_delay.test | 11 ++ sql/rpl_slave.cc | 14 +++ 7 files changed, 188 insertions(+), 1 deletion(-) create mode 100644 mysql-test/suite/rpl/r/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.result delete mode 100644 mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx-slave.opt create mode 100644 mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx.cnf create mode 100644 mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.cnf create mode 100644 mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.test diff --git a/mysql-test/extra/rpl_tests/rpl_gtids_restart_slave_io_lost_trx.test b/mysql-test/extra/rpl_tests/rpl_gtids_restart_slave_io_lost_trx.test index 902c6361d66..c54614736b1 100644 --- a/mysql-test/extra/rpl_tests/rpl_gtids_restart_slave_io_lost_trx.test +++ b/mysql-test/extra/rpl_tests/rpl_gtids_restart_slave_io_lost_trx.test @@ -10,6 +10,11 @@ # IO thread right after queuing an event of a given type, starting the IO # thread again to fully retrieve the partially received transaction. # +# Additionally, this test also tests partial transactions with MASTER_DELAY +# configured and verifies that the applier thread doesn't wait for MASTER_DELAY +# when the receiver thread is restarted in the middle of a transaction, if MTS +# and GTID autoposition protocol. To test this, set $master_delay_test=1 and +# source this file. --source include/have_gtid.inc @@ -33,6 +38,14 @@ CREATE TABLE t1(i INT) ENGINE=InnoDB; # their replicated versions in the slave's relaylog). FLUSH LOGS; --source include/sync_slave_sql_with_master.inc + +# Test for MASTER_DELAY with partial transactions. +if ($master_delay_test) +{ + --source include/stop_slave.inc + CHANGE MASTER TO MASTER_DELAY=5; + --source include/start_slave.inc +} SET @save_debug=@@global.debug; # @@ -85,6 +98,28 @@ while ($i <= 5) --source include/stop_slave_io.inc } --source include/wait_for_slave_io_to_stop.inc + + if ($master_delay_test) + { + # Sleep for slightly more than MASTER_DELAY seconds. + --sleep 8 + + # When MASTER_DELAY is set we don't expect the applier thread to + # wait while it is processing the source's Format_description_event + # as part of handling partial transaction in the relay log. + START SLAVE IO_THREAD; + + --let $assert_text= Assert that the applier thread is not waiting for MASTER_DELAY seconds. + --let $assert_cond= [SELECT COUNT(*) FROM INFORMATION_SCHEMA.PROCESSLIST WHERE STATE = "Waiting until MASTER_DELAY seconds after master executed event"] = 0 + --source include/assert.inc + + # Reset MASTER_DELAY. + --source include/stop_slave.inc + CHANGE MASTER TO MASTER_DELAY=0; + + # Start only the applier thread + --source include/start_slave_sql.inc + } # Remove the debug point and restart the slave threads SET GLOBAL DEBUG= @save_debug; diff --git a/mysql-test/suite/rpl/r/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.result b/mysql-test/suite/rpl/r/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.result new file mode 100644 index 00000000000..78ce84da543 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.result @@ -0,0 +1,104 @@ +include/master-slave.inc +Warnings: +Note #### Sending passwords in plain text without SSL/TLS is extremely insecure. +Note #### Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information. +[connection master] +CREATE TABLE t1(i INT) ENGINE=InnoDB; +FLUSH LOGS; +include/sync_slave_sql_with_master.inc +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY=5; +include/start_slave.inc +SET @save_debug=@@global.debug; +SET GLOBAL DEBUG='d,stop_io_after_reading_gtid_log_event'; +BEGIN; +INSERT INTO t1 VALUES (1); +SET @v= 1 * 100; +INSERT INTO t1 VALUES (@v); +COMMIT; +include/wait_for_slave_io_to_stop.inc +START SLAVE IO_THREAD; +include/assert.inc [Assert that the applier thread is not waiting for MASTER_DELAY seconds.] +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY=0; +include/start_slave_sql.inc +SET GLOBAL DEBUG= @save_debug; +include/start_slave_io.inc +INSERT INTO t1 VALUES (1); +include/sync_slave_sql_with_master.inc +include/diff_tables.inc [master:t1, slave:t1] +SET GLOBAL DEBUG='d,stop_io_after_reading_query_log_event'; +BEGIN; +INSERT INTO t1 VALUES (2); +SET @v= 2 * 100; +INSERT INTO t1 VALUES (@v); +COMMIT; +include/wait_for_slave_io_to_stop.inc +START SLAVE IO_THREAD; +include/assert.inc [Assert that the applier thread is not waiting for MASTER_DELAY seconds.] +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY=0; +include/start_slave_sql.inc +SET GLOBAL DEBUG= @save_debug; +include/start_slave_io.inc +INSERT INTO t1 VALUES (2); +include/sync_slave_sql_with_master.inc +include/diff_tables.inc [master:t1, slave:t1] +include/stop_slave_sql.inc +SET GLOBAL DEBUG='d,stop_io_after_reading_xid_log_event'; +BEGIN; +INSERT INTO t1 VALUES (3); +SET @v= 3 * 100; +INSERT INTO t1 VALUES (@v); +COMMIT; +include/wait_for_slave_io_to_stop.inc +START SLAVE IO_THREAD; +include/assert.inc [Assert that the applier thread is not waiting for MASTER_DELAY seconds.] +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY=0; +include/start_slave_sql.inc +SET GLOBAL DEBUG= @save_debug; +include/start_slave_io.inc +include/start_slave_sql.inc +Warnings: +Note 3083 Replication thread(s) for channel '' are already runnning. +INSERT INTO t1 VALUES (3); +include/sync_slave_sql_with_master.inc +include/diff_tables.inc [master:t1, slave:t1] +BEGIN; +INSERT INTO t1 VALUES (4); +SET @v= 4 * 100; +INSERT INTO t1 VALUES (@v); +COMMIT; +include/sync_slave_sql_with_master.inc +include/stop_slave_io.inc +include/wait_for_slave_io_to_stop.inc +START SLAVE IO_THREAD; +include/assert.inc [Assert that the applier thread is not waiting for MASTER_DELAY seconds.] +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY=0; +include/start_slave_sql.inc +SET GLOBAL DEBUG= @save_debug; +include/start_slave_io.inc +INSERT INTO t1 VALUES (4); +include/sync_slave_sql_with_master.inc +include/diff_tables.inc [master:t1, slave:t1] +SET GLOBAL DEBUG='d,stop_io_after_reading_user_var_log_event'; +BEGIN; +INSERT INTO t1 VALUES (5); +SET @v= 5 * 100; +INSERT INTO t1 VALUES (@v); +COMMIT; +include/wait_for_slave_io_to_stop.inc +START SLAVE IO_THREAD; +include/assert.inc [Assert that the applier thread is not waiting for MASTER_DELAY seconds.] +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY=0; +include/start_slave_sql.inc +SET GLOBAL DEBUG= @save_debug; +include/start_slave_io.inc +INSERT INTO t1 VALUES (5); +include/sync_slave_sql_with_master.inc +include/diff_tables.inc [master:t1, slave:t1] +DROP TABLE t1; +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx-slave.opt b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx-slave.opt deleted file mode 100644 index 378129c9a4c..00000000000 --- a/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx-slave.opt +++ /dev/null @@ -1 +0,0 @@ ---slave-parallel-workers=2 --slave-transaction-retries=0 diff --git a/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx.cnf b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx.cnf new file mode 100644 index 00000000000..d3f494d569d --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx.cnf @@ -0,0 +1,12 @@ +!include ../my.cnf + +[mysqld.1] +gtid-mode = ON +enforce-gtid-consistency = ON + + +[mysqld.2] +gtid-mode = ON +enforce-gtid-consistency = ON +slave_parallel_workers = 2 +slave_transaction_retries = 0 diff --git a/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.cnf b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.cnf new file mode 100644 index 00000000000..d3f494d569d --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.cnf @@ -0,0 +1,12 @@ +!include ../my.cnf + +[mysqld.1] +gtid-mode = ON +enforce-gtid-consistency = ON + + +[mysqld.2] +gtid-mode = ON +enforce-gtid-consistency = ON +slave_parallel_workers = 2 +slave_transaction_retries = 0 diff --git a/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.test b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.test new file mode 100644 index 00000000000..55c77daa1f7 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_mts_gtids_restart_slave_io_lost_trx_with_master_delay.test @@ -0,0 +1,11 @@ +# === Purpose === +# +# This test verifies that the applier thread doesn't wait for MASTER_DELAY +# when the receiver thread is restarted in the middle of a transaction if the server +# is configured with MTS and GTID autoposition. +# +# === References === +# Bug #102647: Replica sql_thread getting stuck due to MASTER_DELAY + +--let $master_delay_test=1 +--source extra/rpl_tests/rpl_gtids_restart_slave_io_lost_trx.test diff --git a/sql/rpl_slave.cc b/sql/rpl_slave.cc index 53f43aec6d8..3df1ac33e07 100644 --- a/sql/rpl_slave.cc +++ b/sql/rpl_slave.cc @@ -5110,6 +5110,13 @@ static bool coord_handle_partial_binlogged_transaction(Relay_log_info *rli, ((Query_log_event*) begin_event)->db= ""; begin_event->common_header->data_written= 0; begin_event->server_id= ev->server_id; + /* + This event is not generated on source server and is only specific to + replicas. So, we don't want this BEGIN query to respect MASTER_DELAY. + Make the timestamp to be same as that of the FORMAT_DESCRIPTION_EVENT + event which triggered this. + */ + begin_event->common_header->when= ev->common_header->when; /* We must be careful to avoid SQL thread increasing its position farther than the event that triggered this QUERY(BEGIN). @@ -5137,6 +5144,13 @@ static bool coord_handle_partial_binlogged_transaction(Relay_log_info *rli, ((Query_log_event*) rollback_event)->db= ""; rollback_event->common_header->data_written= 0; rollback_event->server_id= ev->server_id; + /* + This event is not generated on source server and is only specific to + replicas. So, we don't want this ROLLBACK query to respect MASTER_DELAY. + Make the timestamp to be same as that of the FORMAT_DESCRIPTION_EVENT event + which triggered this. + */ + rollback_event->common_header->when= ev->common_header->when; /* We must be careful to avoid SQL thread increasing its position farther than the event that triggered this QUERY(ROLLBACK).