path: root/mysql-test/suite/rpl/t/rpl_delayed_slave.test

# ==== Purpose ====
#
# Test the time-delayed replication feature, i.e.,
# CHANGE MASTER TO MASTER_DELAY=X:
#
#  - Verify that slave has executed the events after but not before the
#    delay timeout.
#
#  - Verify that delay is correct when slave is already lagging
#    due to slow queries.
#
#  - Verify that Seconds_Behind_Master is greater than or equal to the
#    delay if the slave still has unprocessed events in the relay log
#    and more time than the delay has elapsed since the last event was
#    executed on the master.
#
#  - Verify that STOP SLAVE works instantly even during a delay, and
#    that it does not cause the waited-for event to be executed too
#    early on slave.
#
#  - Verify that changing back to no delay works.
#
#  - Verify that RESET SLAVE sets the delay to 0.
#
#  - Verify that setting a bad value for the delay gives an error.
#
# ==== Implementation ====
#
# We run the slave with 10 seconds lag.
#
# In general, to test that a query has not been executed by the slave
# before this time, we wait until the slave IO thread has received the
# event, and then 5 seconds more, and check that the table has not
# been updated.  To test that a query has been executed after this
# time, we wait 10 seconds more.
#
# To simulate that the slave lags due to slow queries, we invoke a
# stored function that executes SLEEP if @@gloval.server_id==2. This
# requires that we run with binlog_format=STATEMENT.
#
# ==== Related Bugs and Worklogs ====
#
# WL#344: Time-delayed replication
# BUG#28760: Simulating a replication lag
# [duplicate] BUG#22072: configurable delayed replication
# [duplicate] BUG#21639: Add Replication Delay parameter
# BUG#56442: Slave executes delayed statements when STOP SLAVE is issued
#
# ==== Issues with this Test Case ====
#
# The test is inherently timing-sensitive (i.e., contains races) and
# is likely to fail sporadically on a loaded host.
#
# The test takes a long time; it sleeps for around 20*10 seconds.

--source include/big_test.inc
--source include/not_valgrind.inc
--source include/master-slave.inc
# Needed so that sleeps get executed in the slave SQL thread.
--source include/have_binlog_format_statement.inc


call mtr.add_suppression("Unsafe statement written to the binary log using statement format");
--connection slave
call mtr.add_suppression("Unsafe statement written to the binary log using statement format");
--source include/stop_slave.inc
CHANGE MASTER TO MASTER_USE_GTID=NO;
--source include/start_slave.inc
--connection master


# We assume that any simple operation takes zero time, with an error
# margin of $time1 seconds. Hence, if we run with a delay of $time2
# seconds, we expect that:
#  - If we execute a query on master and wait $time1 seconds, then the
#    query has been copied to slave but not yet executed.
#  - If we execute a query on master and wait $time3 seconds, then the
#    query has been executed.
--let $time1= 10
if (`SELECT '$max_query_execution_time' > 0`) {
  --let $time1= $max_query_execution_time
}
--let $time2= `SELECT 2 * $time1`
--let $time3= `SELECT 3 * $time1`


--echo [on master]
CREATE TABLE t1 (a VARCHAR(100), b INT);
INSERT INTO t1 VALUES ("zero", 0);


--echo ==== Normal setup ====

--echo [on slave]
--sync_slave_with_master

--source include/stop_slave.inc

--echo # CHANGE MASTER TO MASTER_DELAY = 2*T
--disable_query_log
eval CHANGE MASTER TO MASTER_DELAY = $time2;
--enable_query_log

--source include/start_slave.inc

--let $assert_text= SHOW SLAVE STATUS should return the same delay that we set with CHANGE MASTER
--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = $time2
--source include/rpl_assert.inc

--echo [on master]
--connection master
INSERT INTO t1 VALUES ('normal setup', 1);

--let $query_number= 1
--source include/delayed_slave_wait_on_query.inc


--echo ==== Slave lags "naturally" after master ====

--echo [on master]
--connection master

--disable_query_log
--echo # CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * T); ELSE RETURN 0; END IF; END
--eval CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * $time1); ELSE RETURN 0; END IF; END
--enable_query_log

INSERT INTO t1 SELECT delay_on_slave(3), 2;

--save_master_pos
INSERT INTO t1 VALUES ('slave is already lagging: this statement should execute immediately', 3);
INSERT INTO t1 SELECT delay_on_slave(2), 4;

--echo [on slave]
--source include/sync_slave_io_with_master.inc
--echo # sleep 1*T
--sleep $time1

--let $assert_text= No query executed
--let $assert_cond= MAX(b) = 1 FROM t1
--source include/rpl_assert.inc

--let $assert_text= Status should be 'Waiting until MASTER_DELAY...'
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%"
--source include/rpl_assert.inc

--echo # wait for first query to execute
--sync_with_master

--echo # sleep 1*T
--sleep $time1

--let $assert_text= Second query executed
--let $assert_cond= MAX(b) = 3 FROM t1
--source include/rpl_assert.inc

let $parallel= `SELECT @@GLOBAL.slave_parallel_threads`;
if (!$parallel)
{
  let $assert_text= Status should be executing third query (i.e., 'User sleep');
  let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "User sleep";
  source include/rpl_assert.inc;
}

--echo # sleep 2*T
--sleep $time2

--let $assert_text= Third query executed
--let $assert_cond= MAX(b) = 4 FROM t1
--source include/rpl_assert.inc

--let $assert_text= Status should be 'Has read all relay log...'
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%"
--source include/rpl_assert.inc


--echo ==== Seconds_Behind_Master ====

--echo # Bring slave to sync.
--source include/stop_slave.inc
CHANGE MASTER TO MASTER_DELAY = 0;
--source include/start_slave.inc

--connection master
INSERT INTO t1 VALUES ('Syncing slave', 5);
--sync_slave_with_master

--source include/stop_slave.inc
--echo # CHANGE MASTER TO MASTER_DELAY = 2*T
--disable_query_log
eval CHANGE MASTER TO MASTER_DELAY = $time2;
--enable_query_log
--source include/start_slave.inc

# Ensure that slave has started properly
--connection master
INSERT INTO t1 VALUES ('Syncing slave', 5);
--save_master_pos
--sync_slave_with_master

--connection master
INSERT INTO t1 VALUES (delay_on_slave(1), 6);
--save_master_pos
--connection slave

--echo # sleep 1*T
--sleep $time1

--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] >= 0 AND <1> < $time2
--let $assert_text= Seconds_Behind_Master should be between 0 and the 2*T
--source include/rpl_assert.inc

--echo # sleep 1*T
--sleep $time1

--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] >= $time2
--let $assert_text= Seconds_Behind_Master should be at least 2*T
--source include/rpl_assert.inc

--sync_with_master


--echo ==== STOP SLAVE / START SLAVE + DML ====

# Set up a longer delay.
--source include/stop_slave.inc

--echo # CHANGE MASTER TO MASTER_DELAY = 3*T
--disable_query_log
eval CHANGE MASTER TO MASTER_DELAY = $time3;
--enable_query_log

--source include/start_slave.inc

--echo [on master]
--connection master
INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7);

--echo [on slave]
--connection slave
--echo # sleep 1*T
--sleep $time1
--let $timestamp_before_stop= `SELECT UNIX_TIMESTAMP()`
--let $relay_log_pos_before_stop= query_get_value(SHOW SLAVE STATUS, Relay_Log_Pos, 1)
--source include/stop_slave.inc

--let $assert_text= STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish
--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
--source include/rpl_assert.inc

--let $assert_text= SQL thread position should not increase after STOP SLAVE
--let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] = $relay_log_pos_before_stop
--source include/rpl_assert.inc

--let $assert_text= Query should not be executed after STOP SLAVE
--let $assert_cond= MAX(b) = 6 FROM t1
--source include/rpl_assert.inc

--let $assert_text= Status should be '' after STOP SLAVE
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = ""
--source include/rpl_assert.inc

--source include/start_slave.inc

--let $assert_text= START SLAVE should finish quickly
--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
--source include/rpl_assert.inc

--let $query_number= 7
--source include/delayed_slave_wait_on_query.inc


--echo ==== STOP SLAVE / START SLAVE + DDL ====

--echo This verifies BUG#56442

--echo [on master]
--connection master
CREATE TABLE t_check_dml_not_executed_prematurely (a INT);
--source include/save_master_pos.inc

--echo [on slave]
--connection slave
--echo # sleep 1*T
--sleep $time1

--let $timestamp_before_stop= `SELECT UNIX_TIMESTAMP()`
--let $relay_log_pos_before_stop= query_get_value(SHOW SLAVE STATUS, Relay_Log_Pos, 1)
--source include/stop_slave.inc

--let $assert_text= STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish
--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
--source include/rpl_assert.inc

--let $assert_text= SQL thread position should not increase after STOP SLAVE
--let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] = $relay_log_pos_before_stop
--source include/rpl_assert.inc

--let $assert_text= Query should not be executed after STOP SLAVE
--let $assert_cond= COUNT(*) = 0 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely"
--source include/rpl_assert.inc

--let $assert_text= Status should be '' after STOP SLAVE
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = ""
--source include/rpl_assert.inc

--source include/start_slave.inc

--let $assert_text= START SLAVE should finish quickly
--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
--source include/rpl_assert.inc

--echo # sleep 1*T
--sleep $time1

--let $assert_text= DDL Query should not be executed after START SLAVE
--let $assert_cond= COUNT(*) = 0 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely"
--source include/rpl_assert.inc

--let $assert_text= Status should be 'Waiting until MASTER_DELAY...'
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%"
--source include/rpl_assert.inc

--echo # sleep 1*T
--sleep $time1

--echo # sync with master (with timeout 1*T)
--source include/sync_with_master.inc

--let $assert_text= DDL Query should be executed
--let $assert_cond= COUNT(*) = 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely"
--source include/rpl_assert.inc

--let $assert_text= Status should be 'Has read all relay log...'
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%"
--source include/rpl_assert.inc

--source include/check_slave_is_running.inc


--echo ==== Change back to no delay ====

--echo [on slave]
--connection slave
--source include/stop_slave.inc
CHANGE MASTER TO MASTER_DELAY = 0;

--let $assert_text= Delay should be 0 when we set it to 0
--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 0
--source include/rpl_assert.inc

--source include/start_slave.inc

--echo [on master]
--connection master
INSERT INTO t1 VALUES ('change back to no delay', 8);

--echo [on slave]
--source include/sync_slave_io_with_master.inc
--echo # sleep 1*T
--sleep $time1

--let $assert_text= Query should be executed
--let $assert_cond= MAX(b) = 8 FROM t1
--source include/rpl_assert.inc

--let $assert_text= Status should be 'Slave has read all relay log...'
--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" Like "Slave has read all relay log%"
--source include/rpl_assert.inc


--echo ==== Reset delay with RESET SLAVE ====

--source include/stop_slave.inc
CHANGE MASTER TO MASTER_DELAY = 71;
--source include/start_slave.inc

--let $assert_text= Delay should be 71 when we set it to 71
--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 71
--source include/rpl_assert.inc

--source include/stop_slave.inc
--let $master_use_gtid_option= No
--source include/reset_slave.inc
--echo [on master]
--connection master
RESET MASTER;
--echo [on slave]
--connection slave
--source include/start_slave.inc

--let $assert_text= Delay should be 0 after RESET SLAVE
--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 0
--source include/rpl_assert.inc


--echo ==== Set an invalid value for the delay ====

--source include/stop_slave.inc

--echo # Expect error for setting negative delay
--error ER_PARSE_ERROR
CHANGE MASTER TO MASTER_DELAY = -1;

--echo # Expect that it's ok to set delay of 2^31-1
CHANGE MASTER TO MASTER_DELAY = 2147483647;
--echo # Expect error for setting delay between 2^31 and 2^32-1
--error ER_MASTER_DELAY_VALUE_OUT_OF_RANGE
CHANGE MASTER TO MASTER_DELAY = 2147483648;

--echo # Expect error for setting delay to nonsense
--error ER_PARSE_ERROR
CHANGE MASTER TO MASTER_DELAY = blah;

# todo: CHANGE MASTER TO MASTER_DELAY = 999999999999999999999999999
# should give error

CHANGE MASTER TO MASTER_DELAY = 0;
--source include/start_slave.inc


--echo ==== Clean up ====

--echo [on master]
--connection master
DROP TABLE t1, t_check_dml_not_executed_prematurely;
DROP FUNCTION delay_on_slave;

--echo [on slave]
--sync_slave_with_master
SELECT @@GLOBAL.slave_parallel_mode;
SELECT @@GLOBAL.slave_parallel_threads;

--source include/rpl_end.inc