List:Commits« Previous MessageNext Message »
From:Luís Soares Date:September 13 2010 11:19am
Subject:Re: bzr commit into mysql-next-mr-bugfixing branch (sven.sandberg:3285)
Bug#56442
View as plain text  
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
> 
> 
> 
> 
> 

Thread
bzr commit into mysql-next-mr-bugfixing branch (sven.sandberg:3285) Bug#56442Sven Sandberg10 Sep
  • Re: bzr commit into mysql-next-mr-bugfixing branch (sven.sandberg:3285)Bug#56442Luís Soares13 Sep
    • Re: bzr commit into mysql-next-mr-bugfixing branch (sven.sandberg:3285)Bug#56442Sven Sandberg13 Sep