Hi Sven,
Nice Work. But before approving, I need you to check a few
issues.
Cheers,
Luís Soares
STATUS
------
Not approved.
REQUIRED CHANGES
----------------
RC1. Please, check
http://fimafeng11.norway.sun.com:8080/job/mysql-next-mr-bugfixing/31/console
That's the output of mtr running in parallel=4. There are
some failures in rpl tests. I assume that they are caused
by your patch (PB2 shows no failures for
mysql-next-mr-bugfixing, but then it does not run mtr in
parallel). Double check that your patch is not causing
this.
Failing tests:
rpl.rpl_row_event_max_size
rpl.rpl_log_pos
rpl.rpl_get_master_version_and_clock
rpl.rpl_row_reset_slave
rpl.rpl_stm_reset_slave
rpl.rpl_server_uuid
RC2. The test case needs some more comments. Eg,
+--echo # sleep 1*T
+--sleep $time1
+
+--let $before_stop_slave= `SELECT UNIX_TIMESTAMP()`
+--let $relay_log_pos_before= 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 delay
+--let $assert_cond= CURRENT_TIMESTAMP() - $before_stop_slave >= $time1
+--source include/rpl_assert.inc
1. not wait for the delay? What delay exactly?
2. "STOP SLAVE should finish quickly" and then:
CURRENT_TIMESTAMP() - $before_stop_slave >= $time1
I think at least this one deserves some comments... ;)
REQUESTS
--------
n/a
SUGGESTIONS
-----------
n/a
DETAILS
-------
n/a
On 09/10/2010 05:46 PM, Sven Sandberg wrote:
> #At file:///home/sven/bzr/b56442-delayed_slave_stop/next-mr-bugfixing/ based on
> revid:tor.didriksen@stripped
>
> 3285 Sven Sandberg 2010-09-10
> BUG#56442: Slave executes delayed statements when STOP SLAVE is issued
> Problem:
> When using the delayed slave feature, and the SQL thread is delaying,
> and the user issues STOP SLAVE, the event we wait for was executed.
> It should not be executed.
> Fix:
> Check the return value from the delay function,
> rpl_slave.cc:safe_sleep(). If the return value is 1, it means the thread
> has been stopped, in this case we don't execute the statement.
>
> Also, refactored the test case for delayed slave a little: added the
> test script include/rpl_assert.inc, which asserts that a condition holds
> and prints a message if not. Made rpl_delayed_slave.test use this. The
> advantage is that the test file is much easier to read and maintain,
> because it is clear what is an assertion and what is not, and also the
> expected result can be found in the test file, you don't have to compare
> it to the result file.
> @ mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc
> Made test use assertions instead of print to the result file.
> @ mysql-test/include/rpl_assert.inc
> Added file to check test assertions.
> @ mysql-test/include/wait_for_slave_param.inc
> Made the parameter $slave_timeout be seconds, not tenths of seconds,
> because nobody uses tenths of seconds.
> @ mysql-test/suite/rpl/r/rpl_delayed_slave.result
> updated result file
> @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
> - Added test for BUG#56442
> - Made test use assertions instead of print to result file
> - Removed the line SELECT STATE FROM I_S.PROCESSLIST... because it
> did not seem to test anything useful.
> @ sql/rpl_slave.cc
> - Avoid executing the waited-for event when user does STOP SLAVE,
> by checking the return value from safe_sleep.
> - Documented safe_sleep.
>
> added:
> mysql-test/include/rpl_assert.inc
> modified:
> mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc
> mysql-test/include/wait_for_slave_param.inc
> mysql-test/suite/rpl/r/rpl_delayed_slave.result
> mysql-test/suite/rpl/t/rpl_delayed_slave.test
> sql/rpl_slave.cc
> === modified file 'mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc'
> --- a/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc 2010-06-21 10:44:26
> +0000
> +++ b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc 2010-09-10 16:45:54
> +0000
> @@ -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
>
> === added file 'mysql-test/include/rpl_assert.inc'
> --- a/mysql-test/include/rpl_assert.inc 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/include/rpl_assert.inc 2010-09-10 16:45:54 +0000
> @@ -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=
>
> === modified file 'mysql-test/include/wait_for_slave_param.inc'
> --- a/mysql-test/include/wait_for_slave_param.inc 2010-05-26 14:34:25 +0000
> +++ b/mysql-test/include/wait_for_slave_param.inc 2010-09-10 16:45:54 +0000
> @@ -25,7 +25,7 @@
> #
> # $slave_timeout
> # The default timeout is 5 minutes. You can change the timeout by
> -# setting $slave_timeout. The unit is tenths of seconds.
> +# setting $slave_timeout. The unit is seconds.
> #
> # $master_connection
> # If the timeout is reached, debug info is given by calling SHOW
> @@ -47,10 +47,12 @@
> let $_slave_timeout_counter= $slave_timeout;
> if (!$_slave_timeout_counter)
> {
> - let $_slave_timeout_counter= 3000;
> + let $_slave_timeout_counter= 300;
> }
> # Save resulting counter for later use.
> let $slave_tcnt= $_slave_timeout_counter;
> +# Convert to deci-seconds
> +let $_slave_timeout_counter= `SELECT 10 * $_slave_timeout_counter`
>
> let $_slave_param_comparison= $slave_param_comparison;
> if (`SELECT '$_slave_param_comparison' = ''`)
> @@ -72,7 +74,7 @@ while (`SELECT NOT('$_show_slave_status_
> # This has to be outside the loop until BUG#41913 has been fixed
> if (!$_slave_timeout_counter)
> {
> - --echo **** ERROR: timeout after $slave_tcnt deci-seconds while waiting for slave
> parameter $slave_param $_slave_param_comparison $slave_param_value ****
> + --echo **** ERROR: timeout after $slave_tcnt seconds while waiting for slave
> parameter $slave_param $_slave_param_comparison $slave_param_value ****
> if (`SELECT '$slave_error_message' != ''`)
> {
> --echo Message: $slave_error_message
> @@ -80,5 +82,5 @@ if (!$_slave_timeout_counter)
> --echo Current connection is '$CURRENT_CONNECTION'
> echo Note: the following output may have changed since the failure was detected;
> source include/show_rpl_debug_info.inc;
> - die;
> + die timeout in wait_for_slave_param.inc;
> }
>
> === modified file 'mysql-test/suite/rpl/r/rpl_delayed_slave.result'
> --- a/mysql-test/suite/rpl/r/rpl_delayed_slave.result 2010-06-21 12:32:29 +0000
> +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave.result 2010-09-10 16:45:54 +0000
> @@ -7,145 +7,135 @@ start slave;
> 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]
> # 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)
> -# 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...'
> Checking that both slave threads are running.
> ==== Slave lags "naturally" after master ====
> [on master]
> # CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@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]
> # 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 delay
> +# 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]
> # 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)
> -# 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...'
> +Checking that both slave threads are running.
> +==== STOP SLAVE / START SLAVE + DDL ====
> +This verifies BUG#56442
> +[on master]
> +CREATE TABLE t_check_dml_not_executed_prematurely (a INT);
> +[on slave]
> +# sleep 1*T
> +include/stop_slave.inc
> +# Asserted this: STOP SLAVE should finish quickly, not wait for the delay
> +# 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)
> +# Asserted this: DDL Query should be executed
> +# Asserted this: Status should be 'Has read all relay log...'
> Checking that both slave threads are running.
> ==== 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]
> # 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;
> @@ -162,6 +152,6 @@ 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]
>
> === modified file 'mysql-test/suite/rpl/t/rpl_delayed_slave.test'
> --- a/mysql-test/suite/rpl/t/rpl_delayed_slave.test 2010-09-04 00:24:29 +0000
> +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.test 2010-09-10 16:45:54 +0000
> @@ -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'
>
>
> --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 A
> 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
> @@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,39 +184,28 @@ eval CHANGE MASTER TO MASTER_DELAY = $ti
> --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
>
> -let $bug_53167_is_fixed= 1;
> -if ($bug_53167_is_fixed) {
> - --let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS,
> Seconds_Behind_Master, 1)
> - # The value of Seconds_Behind_Master will be zero
> - # before the first non-FD event is executed.
> - 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
> @@ -220,71 +217,141 @@ eval CHANGE MASTER TO MASTER_DELAY = $ti
>
> --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 $before_stop_slave= `SELECT UNIX_TIMESTAMP()`
> +--let $before_relay_log_pos= 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 delay
> +--let $assert_cond= UNIX_TIMESTAMP() - $before_stop_slave < $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] = $before_relay_log_pos
> +--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() - $before_stop_slave < $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 $before_stop_slave= `SELECT UNIX_TIMESTAMP()`
> +--let $relay_log_pos_before= 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 delay
> +--let $assert_cond= CURRENT_TIMESTAMP() - $before_stop_slave >= $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] = $before_relay_log_pos
> +--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() - $before_stop_slave < $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 ====
> @@ -293,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;
> @@ -306,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
>
> @@ -340,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]
>
> === modified file 'sql/rpl_slave.cc'
> --- a/sql/rpl_slave.cc 2010-09-04 00:24:29 +0000
> +++ b/sql/rpl_slave.cc 2010-09-10 16:45:54 +0000
> @@ -2244,6 +2244,26 @@ static int init_slave_thread(THD* thd, S
> }
>
>
> +/**
> + Sleep for the given amount of time. If the sleep is interrupted,
> + continue sleeping unless the THD has been killed.
> +
> + @param thd The THD object passed as first parameter to
> + (*thread_killed).
> +
> + @param sec The number of seconds to sleep.
> +
> + @param thread_killed Pointer to function that checks if the thread
> + has been killed or not.
> +
> + @param thread_killed_arg Pointer passed as second parameter to
> + (*thread_killed).
> +
> + @retval 0 If we slept the given number of seconds and THD was not
> + killed.
> +
> + @retval 1 If sleep was interrupted and THD killed.
> +*/
> static int safe_sleep(THD* thd, int sec, CHECK_KILLED_FUNC thread_killed,
> void* thread_killed_arg)
> {
> @@ -2442,17 +2462,21 @@ static int 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, Relay_log_info *rli)
> +static int sql_delay_event(Log_event *ev, THD *thd, Relay_log_info *rli)
> {
> long sql_delay= rli->get_sql_delay();
>
> @@ -2490,15 +2514,14 @@ static void sql_delay_event(Log_event *e
> nap_time));
> rli->start_sql_delay(sql_delay_end);
> mysql_mutex_unlock(&rli->data_lock);
> - safe_sleep(thd, nap_time, (CHECK_KILLED_FUNC)sql_slave_killed,
> - (void*)rli);
> - DBUG_VOID_RETURN;
> + DBUG_RETURN(safe_sleep(thd, nap_time,
> + (CHECK_KILLED_FUNC)sql_slave_killed, (void*)rli));
> }
> }
>
> mysql_mutex_unlock(&rli->data_lock);
>
> - DBUG_VOID_RETURN;
> + DBUG_RETURN(0);
> }
>
>
> @@ -2598,7 +2621,8 @@ int apply_event_and_update_pos(Log_event
> if (reason == Log_event::EVENT_SKIP_NOT)
> {
> // Sleeps if needed, and unlocks rli->data_lock.
> - sql_delay_event(ev, thd, rli);
> + if (sql_delay_event(ev, thd, rli))
> + DBUG_RETURN(0);
> exec_res= ev->apply_event(rli);
> }
> else
>
>
>
>
>
