From a81e21f8a433cf4b4bd7ea5f9f9a6ec57ee388d4 Mon Sep 17 00:00:00 2001 From: Serge Kozlov Date: Sat, 4 Apr 2009 01:33:13 +0400 Subject: [PATCH] Bug#37716. 1. Test case was rewritten completely. 2. Test covers 3 cases: a) do deadlock on slave, wait retries of transaction, unlock slave before lock timeout; b) do deadlock on slave and wait error 'lock timeout exceed' on slave; c) same as b) but if of max relay log size = 0; 3. Added comments inline. 4. Updated result file. --- mysql-test/extra/rpl_tests/rpl_deadlock.test | 199 +++++++-------- mysql-test/include/wait_for_status_var.inc | 68 ++++++ .../suite/rpl/r/rpl_deadlock_innodb.result | 230 ++++++++++-------- 3 files changed, 290 insertions(+), 207 deletions(-) create mode 100644 mysql-test/include/wait_for_status_var.inc diff --git a/mysql-test/extra/rpl_tests/rpl_deadlock.test b/mysql-test/extra/rpl_tests/rpl_deadlock.test index 62fe9b2223a..1b331cc948b 100644 --- a/mysql-test/extra/rpl_tests/rpl_deadlock.test +++ b/mysql-test/extra/rpl_tests/rpl_deadlock.test @@ -7,125 +7,126 @@ # (Guilhem) have seen the test manage to provoke lock wait timeout # error but not deadlock error; that is ok as code deals with the two # errors in exactly the same way. -# We don't 'show status like 'slave_retried_transactions'' because this -# is not repeatable (depends on sleeps). --- source include/master-slave.inc +--source include/master-slave.inc + +# 0) Prepare tables and data +--echo *** Prepare tables and data *** connection master; eval CREATE TABLE t1 (a INT NOT NULL, KEY(a)) ENGINE=$engine_type; -eval CREATE TABLE t2 (a INT NOT NULL, KEY(a)) ENGINE=$engine_type; -# requiring 'unique' for the timeout part of the test -eval CREATE TABLE t3 (a INT UNIQUE) ENGINE=$engine_type; -eval CREATE TABLE t4 (a INT) ENGINE=$engine_type; -show variables like 'slave_transaction_retries'; +eval CREATE TABLE t2 (a INT) ENGINE=$engine_type; +eval CREATE TABLE t3 (a INT NOT NULL, KEY(a)) ENGINE=$engine_type; sync_slave_with_master; -show create table t1; -show create table t2; -show variables like 'slave_transaction_retries'; -stop slave; +SHOW CREATE TABLE t1; +SHOW CREATE TABLE t2; +SHOW CREATE TABLE t3; +SHOW VARIABLES LIKE 'slave_transaction_retries'; +--source include/stop_slave.inc + +connection master; +BEGIN; +INSERT INTO t1 VALUES (1); +# We make a long transaction here +INSERT INTO t2 VALUES (2), (2), (2), (2), (2), (2), (2), (2), (2), (2); +INSERT INTO t3 VALUES (3); +COMMIT; +save_master_pos; +# Save BEGIN event into variable +let $master_pos_begin= query_get_value(SHOW BINLOG EVENTS, Pos, 5); +--echo # 1) Test deadlock - -connection master; -begin; -# Let's keep BEGIN and the locked statement in two different relay logs. -insert into t2 values (0); # t2,t1 actors of deadlock in repl-ed ta -#insert into t3 select * from t2 for update; -let $1=10; -disable_query_log; -while ($1) -{ - eval insert into t3 values( $1 ); - dec $1; -} -enable_query_log; -insert into t1 values(1); -commit; -save_master_pos; +# Block slave SQL thread, wait retries of transaction, unlock slave before lock timeout +--echo *** Test deadlock *** connection slave; -begin; -# Let's make our transaction large so that it's repl-ed msta that's victim -let $1=100; -disable_query_log; -while ($1) -{ - eval insert into t4 values( $1 ); - dec $1; -} -enable_query_log; -select * from t1 for update; # t1,t2 on local slave's -start slave; - -# bad option, todo: replicate a non-transactional t_sync with the transaction -# and use wait_until_rows_count macro below ---real_sleep 3 # hope that slave is blocked now -#let $count=11; -#let $table=t_sync; -#--include wait_until_rows_count.inc - -select * from t2 for update /* dl */; # provoke deadlock, repl-ed should be victim -commit; +BEGIN; +SELECT * FROM t1 FOR UPDATE; +# Save variable 'Slave_retried_transactions' before deadlock +let $slave_retried_transactions= query_get_value(SHOW GLOBAL STATUS LIKE 'Slave_retried_transactions', Value, 1); +START SLAVE; +# Wait until SQL thread blocked: variable 'Slave_retried_transactions' will incremented +let $status_var= Slave_retried_transactions; +let $status_var_value= $slave_retried_transactions; +let $status_type= GLOBAL; +let $status_var_comparsion= >; +--source include/wait_for_status_var.inc +SELECT COUNT(*) FROM t2; +COMMIT; sync_with_master; -select * from t1; # check that repl-ed succeeded finally -select * from t2 /* must be 1 */; -# check that no error is reported ---replace_column 1 # 7 # 8 # 9 # 16 # 22 # 23 # 33 # 35 # 36 # ---replace_result $MASTER_MYPORT MASTER_MYPORT ---vertical_results -show slave status; ---horizontal_results + +# Check the data +SELECT * FROM t1; +SELECT * FROM t3; +# Check that no error is reported +--source include/show_slave_status2.inc +--echo # 2) Test lock wait timeout +# Block slave and wait lock timeout error +--echo *** Test lock wait timeout *** -stop slave; -delete from t3; -change master to master_log_pos=548; # the BEGIN log event -begin; -select * from t2 for update; # hold lock -start slave; ---real_sleep 10 # repl-ed should have blocked, and be retrying -select count(*) from t3 /* must be zero */; # replaying begins after rollback -commit; +connection slave; +--source include/stop_slave.inc +DELETE FROM t2; +# Set slave position to the BEGIN log event +--replace_result $master_pos_begin MASTER_POS_BEGIN +eval CHANGE MASTER TO MASTER_LOG_POS=$master_pos_begin; +BEGIN; +# Hold lock +SELECT * FROM t1 FOR UPDATE; +# Wait until slave stopped with error 'Lock wait timeout exceeded' +START SLAVE; +let $slave_sql_errno= 1205; +--source include/wait_for_slave_sql_error.inc +SELECT COUNT(*) FROM t2; +COMMIT; +--source include/start_slave.inc sync_with_master; -select * from t1; # check that repl-ed succeeded finally -select * from t2; -# check that no error is reported ---replace_column 1 # 7 # 8 # 9 # 11 # 16 # 22 # 23 # 33 # ---replace_result $MASTER_MYPORT MASTER_MYPORT ---vertical_results -show slave status; ---horizontal_results +# Check data from tables +SELECT * FROM t1; +SELECT * FROM t3; +# Check that no error is reported +--source include/show_slave_status2.inc +--echo -# Now we repeat 2), but with BEGIN in the same relay log as -# COMMIT (to see if seeking into hot log is ok). -set @my_max_relay_log_size= @@global.max_relay_log_size; -set global max_relay_log_size=0; +# 3) Test lock wait timeout and purged relay log +# Set max_relay_log_size=0, block slave and wait lock timeout error. +# Restart slave and check that no erros appear +--echo *** Test lock wait timeout and purged relay logs *** -# This is really copy-paste of 2) of above -stop slave; -delete from t3; -change master to master_log_pos=548; -begin; -select * from t2 for update; -start slave; ---real_sleep 10 -select count(*) from t3 /* must be zero */; # replaying begins after rollback -commit; +connection slave; +SET @my_max_relay_log_size= @@global.max_relay_log_size; +SET global max_relay_log_size=0; +--source include/stop_slave.inc +DELETE FROM t2; +# Set slave position to the BEGIN log event +eval CHANGE MASTER TO MASTER_LOG_POS=$master_pos_begin; +BEGIN; +# Hold lock +SELECT * FROM t1 FOR UPDATE; +# Wait until slave stopped with error 'Lock wait timeout exceeded' +START SLAVE; +let $slave_sql_errno= 1205; +--source include/wait_for_slave_sql_error.inc +SELECT COUNT(*) FROM t2; +COMMIT; +--source include/start_slave.inc sync_with_master; -select * from t1; -select * from t2; ---replace_column 1 # 7 # 8 # 9 # 11 # 16 # 22 # 23 # 33 # 35 # 36 # ---replace_result $MASTER_MYPORT MASTER_MYPORT ---vertical_results -show slave status; ---horizontal_results +# Check data from tables +SELECT * FROM t1; +SELECT * FROM t3; +# Check that no error is reported +--source include/show_slave_status2.inc +--echo +# Clean up +--echo *** Clean up *** connection master; -drop table t1,t2,t3,t4; +DROP TABLE t1,t2,t3; sync_slave_with_master; -set global max_relay_log_size= @my_max_relay_log_size; +SET global max_relay_log_size= @my_max_relay_log_size; --echo End of 5.1 tests diff --git a/mysql-test/include/wait_for_status_var.inc b/mysql-test/include/wait_for_status_var.inc new file mode 100644 index 00000000000..4c168da7f1a --- /dev/null +++ b/mysql-test/include/wait_for_status_var.inc @@ -0,0 +1,68 @@ +# ==== Purpose ==== +# +# Waits until a variable from SHOW STATUS has returned a specified +# value, or until a timeout is reached. +# +# ==== Usage ==== +# +# let $status_var= Threads_connected; +# let $status_var_value= 1; +# --source include/wait_for_status_var.inc +# +# Parameters: +# +# $status_var, $status_var_value +# This macro will wait until the variable of SHOW STATUS +# named $status_var gets the value $status_var_value. See +# the example above. +# +# $status_type= GLOBAL|SESSION +# To specify the type (attribute) of status variable and +# run either SHOW GLOBAL STATUS or SHOW SESSION STATUS. +# +# $status_var_comparsion +# By default, this file waits until $status_var becomes equal to +# $status_var_value. If you want to wait until $status_var +# becomes *unequal* to $status_var_value, set this parameter to the +# string '!=', like this: +# let $status_var_comparsion= !=; +# +# $status_timeout +# The default timeout is 1 minute. You can change the timeout by +# setting $status_timeout. The unit is tenths of seconds. +# + +if (`SELECT STRCMP('$status_type', '') * STRCMP(UPPER('$status_type'), 'SESSION') * STRCMP(UPPER('$status_type'), 'GLOBAL')`) +{ + --echo **** ERROR: Unknown type of variable status_type: allowed values are: SESSION or GLOBAL **** + exit; +} + +let $_status_timeout_counter= $status_timeout; +if (!$_status_timeout_counter) +{ + let $_status_timeout_counter= 600; +} + +let $_status_var_comparsion= $status_var_comparsion; +if (`SELECT '$_status_var_comparsion' = ''`) +{ + let $_status_var_comparsion= =; +} + +let $_show_status_value= query_get_value("SHOW $status_type STATUS LIKE '$status_var'", Value, 1); +while (`SELECT NOT('$_show_status_value' $_status_var_comparsion '$status_var_value')`) +{ + if (!$_status_timeout_counter) + { + --echo **** ERROR: failed while waiting for $status_type $status_var $_status_var_comparison $status_var_value **** + --echo Note: the following output may have changed since the failure was detected + --echo **** Showing STATUS, PROCESSLIST **** + eval SHOW $status_type STATUS LIKE '$status_var'; + SHOW PROCESSLIST; + exit; + } + dec $_status_timeout_counter; + sleep 0.1; + let $_show_status_value= query_get_value("SHOW $status_type STATUS LIKE '$status_var'", Value, 1); +} diff --git a/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result b/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result index 1753fc0cb2d..6c8d35619e5 100644 --- a/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result +++ b/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result @@ -4,51 +4,57 @@ reset master; reset slave; drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9; start slave; +*** Prepare tables and data *** CREATE TABLE t1 (a INT NOT NULL, KEY(a)) ENGINE=innodb; -CREATE TABLE t2 (a INT NOT NULL, KEY(a)) ENGINE=innodb; -CREATE TABLE t3 (a INT UNIQUE) ENGINE=innodb; -CREATE TABLE t4 (a INT) ENGINE=innodb; -show variables like 'slave_transaction_retries'; -Variable_name Value -slave_transaction_retries 10 -show create table t1; +CREATE TABLE t2 (a INT) ENGINE=innodb; +CREATE TABLE t3 (a INT NOT NULL, KEY(a)) ENGINE=innodb; +SHOW CREATE TABLE t1; Table Create Table t1 CREATE TABLE `t1` ( `a` int(11) NOT NULL, KEY `a` (`a`) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 -show create table t2; +SHOW CREATE TABLE t2; Table Create Table t2 CREATE TABLE `t2` ( + `a` int(11) DEFAULT NULL +) ENGINE=InnoDB DEFAULT CHARSET=latin1 +SHOW CREATE TABLE t3; +Table Create Table +t3 CREATE TABLE `t3` ( `a` int(11) NOT NULL, KEY `a` (`a`) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 -show variables like 'slave_transaction_retries'; +SHOW VARIABLES LIKE 'slave_transaction_retries'; Variable_name Value slave_transaction_retries 2 -stop slave; -begin; -insert into t2 values (0); -insert into t1 values(1); -commit; -begin; -select * from t1 for update; +include/stop_slave.inc +BEGIN; +INSERT INTO t1 VALUES (1); +INSERT INTO t2 VALUES (2), (2), (2), (2), (2), (2), (2), (2), (2), (2); +INSERT INTO t3 VALUES (3); +COMMIT; + +*** Test deadlock *** +BEGIN; +SELECT * FROM t1 FOR UPDATE; a -start slave; -select * from t2 for update /* dl */; -a -commit; -select * from t1; +START SLAVE; +SELECT COUNT(*) FROM t2; +COUNT(*) +0 +COMMIT; +SELECT * FROM t1; a 1 -select * from t2 /* must be 1 */; +SELECT * FROM t3; a -0 -show slave status; +3 +SHOW SLAVE STATUS; Slave_IO_State # Master_Host 127.0.0.1 Master_User root -Master_Port MASTER_MYPORT +Master_Port MASTER_PORT Connect_Retry 1 Master_Log_File master-bin.000001 Read_Master_Log_Pos # @@ -83,102 +89,41 @@ Last_IO_Errno # Last_IO_Error # Last_SQL_Errno 0 Last_SQL_Error -stop slave; -delete from t3; -change master to master_log_pos=548; -begin; -select * from t2 for update; + +*** Test lock wait timeout *** +include/stop_slave.inc +DELETE FROM t2; +CHANGE MASTER TO MASTER_LOG_POS=MASTER_POS_BEGIN; +BEGIN; +SELECT * FROM t1 FOR UPDATE; a +1 +START SLAVE; +SELECT COUNT(*) FROM t2; +COUNT(*) 0 -start slave; -select count(*) from t3 /* must be zero */; -count(*) -0 -commit; -select * from t1; +COMMIT; +include/start_slave.inc +SELECT * FROM t1; a 1 1 -select * from t2; +SELECT * FROM t3; a -0 -0 -show slave status; +3 +3 +SHOW SLAVE STATUS; Slave_IO_State # Master_Host 127.0.0.1 Master_User root -Master_Port MASTER_MYPORT +Master_Port MASTER_PORT Connect_Retry 1 Master_Log_File master-bin.000001 Read_Master_Log_Pos # Relay_Log_File # Relay_Log_Pos # Relay_Master_Log_File master-bin.000001 -Slave_IO_Running # -Slave_SQL_Running Yes -Replicate_Do_DB -Replicate_Ignore_DB -Replicate_Do_Table -Replicate_Ignore_Table # -Replicate_Wild_Do_Table -Replicate_Wild_Ignore_Table -Last_Errno 0 -Last_Error -Skip_Counter 0 -Exec_Master_Log_Pos # -Relay_Log_Space # -Until_Condition None -Until_Log_File -Until_Log_Pos 0 -Master_SSL_Allowed No -Master_SSL_CA_File -Master_SSL_CA_Path -Master_SSL_Cert -Master_SSL_Cipher -Master_SSL_Key -Seconds_Behind_Master # -Master_SSL_Verify_Server_Cert No -Last_IO_Errno 0 -Last_IO_Error -Last_SQL_Errno 0 -Last_SQL_Error -set @my_max_relay_log_size= @@global.max_relay_log_size; -set global max_relay_log_size=0; -stop slave; -delete from t3; -change master to master_log_pos=548; -begin; -select * from t2 for update; -a -0 -0 -start slave; -select count(*) from t3 /* must be zero */; -count(*) -0 -commit; -select * from t1; -a -1 -1 -1 -select * from t2; -a -0 -0 -0 -show slave status; -Slave_IO_State # -Master_Host 127.0.0.1 -Master_User root -Master_Port MASTER_MYPORT -Connect_Retry 1 -Master_Log_File master-bin.000001 -Read_Master_Log_Pos # -Relay_Log_File # -Relay_Log_Pos # -Relay_Master_Log_File master-bin.000001 -Slave_IO_Running # +Slave_IO_Running Yes Slave_SQL_Running Yes Replicate_Do_DB Replicate_Ignore_DB @@ -206,6 +151,75 @@ Last_IO_Errno # Last_IO_Error # Last_SQL_Errno 0 Last_SQL_Error -drop table t1,t2,t3,t4; -set global max_relay_log_size= @my_max_relay_log_size; + +*** Test lock wait timeout and purged relay logs *** +SET @my_max_relay_log_size= @@global.max_relay_log_size; +SET global max_relay_log_size=0; +include/stop_slave.inc +DELETE FROM t2; +CHANGE MASTER TO MASTER_LOG_POS=440; +BEGIN; +SELECT * FROM t1 FOR UPDATE; +a +1 +1 +START SLAVE; +SELECT COUNT(*) FROM t2; +COUNT(*) +0 +COMMIT; +include/start_slave.inc +SELECT * FROM t1; +a +1 +1 +1 +SELECT * FROM t3; +a +3 +3 +3 +SHOW SLAVE STATUS; +Slave_IO_State # +Master_Host 127.0.0.1 +Master_User root +Master_Port MASTER_PORT +Connect_Retry 1 +Master_Log_File master-bin.000001 +Read_Master_Log_Pos # +Relay_Log_File # +Relay_Log_Pos # +Relay_Master_Log_File master-bin.000001 +Slave_IO_Running Yes +Slave_SQL_Running Yes +Replicate_Do_DB +Replicate_Ignore_DB +Replicate_Do_Table +Replicate_Ignore_Table # +Replicate_Wild_Do_Table +Replicate_Wild_Ignore_Table +Last_Errno 0 +Last_Error +Skip_Counter 0 +Exec_Master_Log_Pos # +Relay_Log_Space # +Until_Condition None +Until_Log_File +Until_Log_Pos 0 +Master_SSL_Allowed No +Master_SSL_CA_File +Master_SSL_CA_Path +Master_SSL_Cert +Master_SSL_Cipher +Master_SSL_Key +Seconds_Behind_Master # +Master_SSL_Verify_Server_Cert No +Last_IO_Errno # +Last_IO_Error # +Last_SQL_Errno 0 +Last_SQL_Error + +*** Clean up *** +DROP TABLE t1,t2,t3; +SET global max_relay_log_size= @my_max_relay_log_size; End of 5.1 tests