diff --git a/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc index 5d04d14edf3..ffdcb7f60bb 100644 --- a/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc +++ b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc @@ -10,21 +10,32 @@ # - After one and a half delay, check the status. It should not be # delaying and the query should be executed. # +# # ==== Usage ==== # +# --let $query_number= 4 # --source extra/rpl_tests/delayed_slave_wait_on_query.inc +# +# Parameters: +# $query_number +# The value of the 'b' column in t1 for the row inserted by the query +# we are waiting for. connection master; + --echo [on slave] --let $slave_timeout= $time1 - --source include/sync_slave_io_with_master.inc --echo # sleep 1*T --sleep $time1 ---echo # Expect query not executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Query $query_number should not be executed +--let $assert_cond= MAX(b) < $query_number 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 # sleep 1*T --sleep $time1 @@ -32,8 +43,13 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1; --echo # sync with master (with timeout 1*T) --source include/sync_with_master.inc ---echo # Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Query $query_number should be executed +--let $assert_cond= MAX(b) = $query_number 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 + --source include/check_slave_is_running.inc diff --git a/mysql-test/include/rpl_assert.inc b/mysql-test/include/rpl_assert.inc new file mode 100644 index 00000000000..d9963e8e782 --- /dev/null +++ b/mysql-test/include/rpl_assert.inc @@ -0,0 +1,118 @@ +# ==== Purpose ==== +# +# Check if a condition holds, fail with debug info if not. +# +# The condition is parsed before executed. The following constructs +# are supported: +# +# [SQL STATEMENT, COLUMN, ROW] +# The square bracket is replaced by the result from SQL STATEMENT, +# in the given COLUMN and ROW. +# +# <1> +# This is a shorthand for the result of the first executed square +# bracket. <2> is a shorthand for the second executed square +# bracket, and so on. +# +# ==== Usage ==== +# +# --let $assert_text= Relay_Log_Pos must be smaller than pos. +# --let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] >= $min_pos AND <1> <= $max_pos +# [--let $assert_quiet= 1] +# [--let $rpl_debug= 1] +# --source include/rpl_assert.inc +# +# Parameters: +# +# $assert_text +# Text that describes what is being checked. By default, this text +# is written to the query log. +# +# $assert_cond +# Condition to check. See above for details about the format. The +# condition will be executed as `SELECT $assert_cond`. Note: this +# condition is parsed using SQL statements, quoted inside single +# quotes, so it must not contain single quotes itself (use double +# quotes for strings). +# +# $assert_quiet +# Do not print $assert_text to the query log. +# +# $rpl_debug +# Print extra debug info. + + +if ($rpl_debug) +{ + --echo # debug: assert_text='$assert_text' assert_cond='$assert_cond' +} + +# Sanity-check input +if (`SELECT "$assert_text" = ""`) +{ + --die ERROR IN TEST: the mysqltest variable rpl_test must be set +} + +# Evaluate square brackets in cond. +--let $_rpl_assert_substmt_number= 1 +--let $_rpl_interpolated_cond= $assert_cond +--let $_rpl_assert_lbracket= `SELECT LOCATE('[', '$_rpl_interpolated_cond')` +while ($_rpl_assert_lbracket) +{ + # Get position of right bracket + --let $_rpl_assert_rbracket= `SELECT LOCATE(']', '$_rpl_interpolated_cond')` + if (!$_rpl_assert_rbracket) + { + --echo BUG IN TEST: Mismatching square brackets in assert_cond: '$assert_cond' + --die BUG IN TEST: Mismatching square brackets in $assert_cond + } + # Get sub-statement and result of it + --let $_rpl_assert_substmt= `SELECT SUBSTRING('$_rpl_interpolated_cond', $_rpl_assert_lbracket + 1, $_rpl_assert_rbracket - $_rpl_assert_lbracket - 1)` + --let $_rpl_assert_substmt_result= query_get_value($_rpl_assert_substmt) + if ($rpl_debug) + { + --echo # debug: sub-statement='$_rpl_assert_substmt' result='$rpl_assert_result' + } + # Replace sub-statement by its result + --let $_rpl_interpolated_cond= `SELECT REPLACE('$_rpl_interpolated_cond', '[$_rpl_assert_substmt]', '$_rpl_assert_substmt_result')` + # Replace result references by result + --let $_rpl_interpolated_cond= `SELECT REPLACE('$_rpl_interpolated_cond', '<$_rpl_assert_substmt_number>', '$_rpl_assert_substmt_result')` + + --let $_rpl_assert_lbracket= `SELECT LOCATE('[', '$_rpl_interpolated_cond')` + + --inc $_rpl_assert_substmt_number +} + +if ($rpl_debug) +{ + --echo # debug: interpolated_cond='$_rpl_interpolated_cond' +} + +# Execute. +--let $_rpl_assert_result= `SELECT $_rpl_interpolated_cond` + +if ($rpl_debug) +{ + --echo # debug: result='$_rpl_assert_result' +} + +# Check. +if (!$_rpl_assert_result) +{ + --echo ######## Test assertion failed: $assert_text ######## + --echo Dumping debug info: + --source include/show_rpl_debug_info.inc + --echo Assertion text: '$assert_text' + --echo Assertion condition: '$assert_cond' + --echo Assertion condition, interpolated: '$_rpl_interpolated_cond' + --echo Assertion result: '$_rpl_assert_result' + --die Test assertion failed in rpl_assertion.inc +} + +if (!$assert_quiet) +{ + --echo # Asserted this: $assert_text +} + +--let $assert_text= +--let $assert_cond= diff --git a/mysql-test/suite/rpl/r/rpl_delayed_slave.result b/mysql-test/suite/rpl/r/rpl_delayed_slave.result index 75b263b61e0..1aad398bbc9 100644 --- a/mysql-test/suite/rpl/r/rpl_delayed_slave.result +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave.result @@ -3,153 +3,146 @@ include/master-slave.inc call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); [on master] -CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); +CREATE TABLE t1 (a VARCHAR(100), b INT); +INSERT INTO t1 VALUES ("zero", 0); ==== Normal setup ==== [on slave] include/stop_slave.inc # CHANGE MASTER TO MASTER_DELAY = 2*T -# Checking that delay is what we set it to -# Expect status to be '' -SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1; -STATE - include/start_slave.inc +# Asserted this: SHOW SLAVE STATUS should return the same delay that we set with CHANGE MASTER [on master] -INSERT INTO t1(a) VALUES ('normal setup'); +INSERT INTO t1 VALUES ('normal setup', 1); [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect query not executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# Asserted this: Query 1 should not be executed +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' # sleep 1*T # sync with master (with timeout 1*T) include/wait_for_slave_param.inc [Relay_Master_Log_File] include/wait_for_slave_param.inc [Exec_Master_Log_Pos] -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -normal setup 1 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Query 1 should be executed +# Asserted this: Status should be 'Has read all relay log...' include/check_slave_is_running.inc ==== Slave lags "naturally" after master ==== [on master] # 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 -INSERT INTO t1(a) SELECT delay_on_slave(3); +INSERT INTO t1 SELECT delay_on_slave(3), 2; Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. -INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately'); -INSERT INTO t1(a) SELECT delay_on_slave(2); +INSERT INTO t1 VALUES ('slave is already lagging: this statement should execute immediately', 3); +INSERT INTO t1 SELECT delay_on_slave(2), 4; Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect no query executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -normal setup 1 -Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# Asserted this: No query executed +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' # wait for first query to execute # sleep 1*T -# Expect second query executed and status is executing third query (i.e., 'User sleep') -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -slave is already lagging: this statement should execute immediately 3 -Slave_SQL_Running_State='User sleep'; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread +# Asserted this: Second query executed +# Asserted this: Status should be executing third query (i.e., 'User sleep') # sleep 2*T -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -0 4 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Third query executed +# Asserted this: Status should be 'Has read all relay log...' ==== Seconds_Behind_Master ==== # Bring slave to sync. include/stop_slave.inc CHANGE MASTER TO MASTER_DELAY = 0; include/start_slave.inc -INSERT INTO t1(a) VALUES ('Syncing slave'); +INSERT INTO t1 VALUES ('Syncing slave', 5); include/stop_slave.inc # CHANGE MASTER TO MASTER_DELAY = 2*T include/start_slave.inc -INSERT INTO t1(a) VALUES (delay_on_slave(1)); +INSERT INTO t1 VALUES (delay_on_slave(1), 6); Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. # sleep 1*T +# Asserted this: Seconds_Behind_Master should be between 0 and the 2*T # sleep 1*T -==== STOP SLAVE and START SLAVE ==== +# Asserted this: Seconds_Behind_Master should be at least 2*T +==== STOP SLAVE / START SLAVE + DML ==== include/stop_slave.inc # CHANGE MASTER TO MASTER_DELAY = 3*T include/start_slave.inc -# Checking that delay is what we set it to [on master] -INSERT INTO t1(a) VALUES ('stop slave and start slave'); +INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7); [on slave] # sleep 1*T -SET @before_stop_slave= UNIX_TIMESTAMP(); include/stop_slave.inc -# STOP SLAVE finished in time. -# Expect query not executed and status is '' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -0 6 -Slave_SQL_Running_State=''; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread +# Asserted this: STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish +# Asserted this: SQL thread position should not increase after STOP SLAVE +# Asserted this: Query should not be executed after STOP SLAVE +# Asserted this: Status should be '' after STOP SLAVE include/start_slave.inc -# START SLAVE finished in time. +# Asserted this: START SLAVE should finish quickly [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect query not executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -0 6 -Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# Asserted this: Query 7 should not be executed +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' # sleep 1*T # sync with master (with timeout 1*T) include/wait_for_slave_param.inc [Relay_Master_Log_File] include/wait_for_slave_param.inc [Exec_Master_Log_Pos] -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -stop slave and start slave 7 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Query 7 should be executed +# Asserted this: Status should be 'Has read all relay log...' +include/check_slave_is_running.inc +==== STOP SLAVE / START SLAVE + DDL ==== +This verifies BUG#56442 +[on master] +CREATE TABLE t_check_dml_not_executed_prematurely (a INT); +include/save_master_pos.inc +[on slave] +# sleep 1*T +include/stop_slave.inc +# Asserted this: STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish +# Asserted this: SQL thread position should not increase after STOP SLAVE +# Asserted this: Query should not be executed after STOP SLAVE +# Asserted this: Status should be '' after STOP SLAVE +include/start_slave.inc +# Asserted this: START SLAVE should finish quickly +# sleep 1*T +# Asserted this: DDL Query should not be executed after START SLAVE +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' +# sleep 1*T +# sync with master (with timeout 1*T) +include/wait_for_slave_param.inc [Relay_Master_Log_File] +include/wait_for_slave_param.inc [Exec_Master_Log_Pos] +# Asserted this: DDL Query should be executed +# Asserted this: Status should be 'Has read all relay log...' include/check_slave_is_running.inc ==== Change back to no delay ==== [on slave] include/stop_slave.inc CHANGE MASTER TO MASTER_DELAY = 0; -# Expect delay is 0. -SQL_Delay='0' +# Asserted this: Delay should be 0 when we set it to 0 include/start_slave.inc [on master] -INSERT INTO t1(a) VALUES ('change back to no delay'); +INSERT INTO t1 VALUES ('change back to no delay', 8); [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -change back to no delay 8 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Query should be executed +# Asserted this: Status should be 'Slave has read all relay log...' ==== Reset delay with RESET SLAVE ==== include/stop_slave.inc CHANGE MASTER TO MASTER_DELAY = 71; include/start_slave.inc -# Expect delay is 71 -SQL_Delay='71' +# Asserted this: Delay should be 71 when we set it to 71 include/stop_slave.inc RESET SLAVE; [on master] RESET MASTER; [on slave] include/start_slave.inc -# Expect delay is 0 -SQL_Delay='0' -==== Set a bad value for the delay ==== +# Asserted this: Delay should be 0 after RESET SLAVE +==== Set an invalid value for the delay ==== include/stop_slave.inc # Expect error for setting negative delay CHANGE MASTER TO MASTER_DELAY = -1; @@ -166,7 +159,7 @@ CHANGE MASTER TO MASTER_DELAY = 0; include/start_slave.inc ==== Clean up ==== [on master] -DROP TABLE t1; +DROP TABLE t1, t_check_dml_not_executed_prematurely; DROP FUNCTION delay_on_slave; [on slave] include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave.test b/mysql-test/suite/rpl/t/rpl_delayed_slave.test index 2fa5c81f5a5..3e6f5564bf2 100644 --- a/mysql-test/suite/rpl/t/rpl_delayed_slave.test +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.test @@ -6,7 +6,7 @@ # - Verify that slave has executed the events after but not before the # delay timeout. # -# - Verify that delay is correct works when slave is already lagging +# - 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 @@ -44,6 +44,7 @@ # 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 ==== # @@ -79,7 +80,8 @@ if (`SELECT '$max_query_execution_time' > 0`) { --echo [on master] -CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); +CREATE TABLE t1 (a VARCHAR(100), b INT); +INSERT INTO t1 VALUES ("zero", 0); --echo ==== Normal setup ==== @@ -94,23 +96,17 @@ CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); eval CHANGE MASTER TO MASTER_DELAY = $time2; --enable_query_log ---echo # Checking that delay is what we set it to ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) -if (`SELECT $delay != $time2`) { - --echo Delay is wrong! Expected $time2, got $delay - --source include/show_rpl_debug_info.inc - --die wrong delay -} - ---echo # Expect status to be '' -SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1; - --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(a) VALUES ('normal setup'); +INSERT INTO t1 VALUES ('normal setup', 1); +--let $query_number= 1 --source extra/rpl_tests/delayed_slave_wait_on_query.inc @@ -124,20 +120,24 @@ INSERT INTO t1(a) VALUES ('normal setup'); --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(a) SELECT delay_on_slave(3); +INSERT INTO t1 SELECT delay_on_slave(3), 2; --save_master_pos -INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately'); -INSERT INTO t1(a) SELECT delay_on_slave(2); +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 ---echo # Expect no query executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--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 @@ -145,27 +145,35 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1; --echo # sleep 1*T --sleep $time1 ---echo # Expect second query executed and status is executing third query (i.e., 'User sleep') -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Second query executed +--let $assert_cond= MAX(b) = 3 FROM t1 +--source include/rpl_assert.inc + +--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 ---echo # Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--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 -eval CHANGE MASTER TO MASTER_DELAY = 0; +CHANGE MASTER TO MASTER_DELAY = 0; --source include/start_slave.inc --connection master -INSERT INTO t1(a) VALUES ('Syncing slave'); +INSERT INTO t1 VALUES ('Syncing slave', 5); --sync_slave_with_master --source include/stop_slave.inc @@ -176,38 +184,28 @@ eval CHANGE MASTER TO MASTER_DELAY = $time2; --source include/start_slave.inc --connection master -INSERT INTO t1(a) VALUES (delay_on_slave(1)); +INSERT INTO t1 VALUES (delay_on_slave(1), 6); --save_master_pos --connection slave --echo # sleep 1*T --sleep $time1 -if ($bug_53167_is_fixed) { - ---let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1) -if (`SELECT $seconds_behind_master <= 0 OR $seconds_behind_master >= $time2`) { - --echo Seconds_Behind_Master was $seconds_behind_master. Expected that 0 < Seconds_Behind_Master < SQL_Delay = $time2 - --source include/show_rpl_debug_info.inc - --die Seconds_Behind_Master was wrong -} - -} +--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 $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1) -if (`SELECT $seconds_behind_master < $time2`) { - --echo Seconds_Behind_Master was $seconds_behind_master. Expected it to be >= SQL_Delay = $time2 - --source include/show_rpl_debug_info.inc - --die Seconds_Behind_Master was < SQL_Delay -} +--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 and START SLAVE ==== +--echo ==== STOP SLAVE / START SLAVE + DML ==== # Set up a longer delay. --source include/stop_slave.inc @@ -219,71 +217,141 @@ eval CHANGE MASTER TO MASTER_DELAY = $time3; --source include/start_slave.inc ---echo # Checking that delay is what we set it to ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) -if (`SELECT $delay != $time3`) { - --echo Delay is wrong! Expected $time2, got $delay - --source include/show_rpl_debug_info.inc - --die wrong delay -} - --echo [on master] --connection master -INSERT INTO t1(a) VALUES ('stop slave and start slave'); +INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7); --echo [on slave] --connection slave --echo # sleep 1*T --sleep $time1 -SET @before_stop_slave= UNIX_TIMESTAMP(); +--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 -if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`) -{ - --source include/show_rpl_debug_info.inc - --die STOP SLAVE did not finish in time -} ---echo # STOP SLAVE finished in time. ---echo # Expect query not executed and status is '' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.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 -if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`) -{ - --source include/show_rpl_debug_info.inc - --die START SLAVE did not finish in time -} ---echo # START SLAVE finished in time. +--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 extra/rpl_tests/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 -eval CHANGE MASTER TO MASTER_DELAY = 0; +CHANGE MASTER TO MASTER_DELAY = 0; ---echo # Expect delay is 0. ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) ---echo SQL_Delay='$delay' +--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(a) VALUES ('change back to no delay'); +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 ---echo # Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--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 ==== @@ -292,9 +360,9 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1; CHANGE MASTER TO MASTER_DELAY = 71; --source include/start_slave.inc ---echo # Expect delay is 71 ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) ---echo SQL_Delay='$delay' +--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 RESET SLAVE; @@ -305,12 +373,12 @@ RESET MASTER; --connection slave --source include/start_slave.inc ---echo # Expect delay is 0 ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) ---echo SQL_Delay='$delay' +--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 a bad value for the delay ==== +--echo ==== Set an invalid value for the delay ==== --source include/stop_slave.inc @@ -339,7 +407,7 @@ CHANGE MASTER TO MASTER_DELAY = 0; --echo [on master] --connection master -DROP TABLE t1; +DROP TABLE t1, t_check_dml_not_executed_prematurely; DROP FUNCTION delay_on_slave; --echo [on slave] diff --git a/sql/slave.cc b/sql/slave.cc index 813827e883f..a927b7598c6 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -3410,17 +3410,21 @@ has_temporary_error(THD *thd) /** If this is a lagging slave (specified with CHANGE MASTER TO MASTER_DELAY = X), delays accordingly. Also unlocks rli->data_lock. - Design note: this is the place to unlock rli->data_lock here since - it should be held when reading delay info from rli, but it should - not be held while sleeping. + Design note: this is the place to unlock rli->data_lock. The lock + must be held when reading delay info from rli, but it should not be + held while sleeping. @param ev Event that is about to be executed. @param thd The sql thread's THD object. @param rli The sql thread's Relay_log_info structure. + + @retval 0 If the delay timed out and the event shall be executed. + + @retval nonzero If the delay was interrupted and the event shall be skipped. */ -static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) +static int sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) { Relay_log_info* rli= rgi->rli; long sql_delay= rli->get_sql_delay(); @@ -3459,14 +3463,13 @@ static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) nap_time)); rli->start_sql_delay(sql_delay_end); mysql_mutex_unlock(&rli->data_lock); - slave_sleep(thd, nap_time, sql_slave_killed, rgi); - DBUG_VOID_RETURN; + DBUG_RETURN(slave_sleep(thd, nap_time, sql_slave_killed, rgi)); } } mysql_mutex_unlock(&rli->data_lock); - DBUG_VOID_RETURN; + DBUG_RETURN(0); } @@ -3696,7 +3699,8 @@ apply_event_and_update_pos(Log_event* ev, THD* thd, rpl_group_info *rgi) if (reason == Log_event::EVENT_SKIP_NOT) { // Sleeps if needed, and unlocks rli->data_lock. - sql_delay_event(ev, thd, rgi); + if (sql_delay_event(ev, thd, rgi)) + return 0; } else mysql_mutex_unlock(&rli->data_lock);