List:Commits« Previous MessageNext Message »
From:Sven Sandberg Date:September 13 2010 1:21pm
Subject:bzr commit into mysql-next-mr-bugfixing branch (sven.sandberg:3285) Bug#56442
View as plain text  
#At file:///home/sven/bzr/b56442-delayed_slave_stop/next-mr-bugfixing/ based on revid:tor.didriksen@stripped

 3285 Sven Sandberg	2010-09-13
      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-13 13:21:48 +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-13 13:21:48 +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-13 13:21:48 +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-13 13:21:48 +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 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]
 # 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 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)
+# 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-13 13:21:48 +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 $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 ====
@@ -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-13 13:21:48 +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


Attachment: [text/bzr-bundle] bzr/sven.sandberg@oracle.com-20100913132148-c30z2buhbkt6chx5.bundle
Thread
bzr commit into mysql-next-mr-bugfixing branch (sven.sandberg:3285) Bug#56442Sven Sandberg13 Sep