Bug #37716 rpl.rpl_deadlock_innodb 'row' failed on pushbuild
Submitted: 28 Jun 2008 11:20 Modified: 7 May 2009 12:40
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S7 (Test Cases)
Version:6.0, 5.1 OS:Any
Assigned to: Serge Kozlov CPU Architecture:Any
Tags: Lock wait timeout exceeded; try restarting transaction, pushbuild, rpl.rpl_deadlock_innodb 'row', sporadic, test failure

[28 Jun 2008 11:20] Sven Sandberg
Description:
Seen on pushbuild:

rpl.rpl_deadlock_innodb 'row'  [ fail ]

mysqltest: In included file ".\extra\rpl_tests\rpl_deadlock.test": At line 69: query 'select * from t2 for update /* dl */' failed: 1205: Lock wait timeout exceeded; try restarting transaction

The result from queries just before the failure was:
< snip >
) ENGINE=InnoDB DEFAULT CHARSET=latin1
show create table t2;
Table	Create Table
t2	CREATE TABLE `t2` (
  `a` int(11) NOT NULL,
  KEY `a` (`a`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
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;
a
start slave;
select * from t2 for update /* dl */;

More results from queries before failure can be found in e:\var-rpl_binlog_row-100\log\rpl_deadlock_innodb.log

Stopping All Servers

How to repeat:
 WHERE: 6.0/timothy_smith on Wed Jun 18 23:30:24 2008/'vm-win2003-32-a' Win32 VS2003 -max-nt/rpl_binlog_row
 URL: https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0&order=10
[15 Sep 2008 7:47] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/54056

2697 Serge Kozlov	2008-09-15
      Bug#37716. Remove real_sleep and and waiting proper values of Read_Master_Log_Pos and 
      Exec_Master_Log_Pos on slave.
[22 Oct 2008 10:35] Sven Sandberg
xref links:
rpl.rpl_deadlock_innodb: http://tinyurl.com/59m4ra
rpl.rpl_deadlock_innodb 'stmt': http://tinyurl.com/6mqt3n
rpl.rpl_deadlock_innodb 'row': http://tinyurl.com/63dzdo
[22 Oct 2008 10:55] Sven Sandberg
The test fails in one more way, related to the above:

==== BEGIN FAILURE 2 ====
rpl.rpl_deadlock_innodb 'row'  [ fail ]

=== SHOW MASTER STATUS ===
---- 1. ----
File	slave-bin.000001
Position	10401
Binlog_Do_DB	
Binlog_Ignore_DB	
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State	Waiting for master to send event
Master_Host	127.0.0.1
Master_User	root
Master_Port	10070
Connect_Retry	1
Master_Log_File	master-bin.000001
Read_Master_Log_Pos	1544
Relay_Log_File	slave-relay-bin.000002
Relay_Log_Pos	254
Relay_Master_Log_File	master-bin.000001
Slave_IO_Running	Yes
Slave_SQL_Running	No
Replicate_Do_DB	
Replicate_Ignore_DB	
Replicate_Do_Table	
Replicate_Ignore_Table	
Replicate_Wild_Do_Table	
Replicate_Wild_Ignore_Table	
Last_Errno	1205
Last_Error	Could not execute Write_rows event on table test.t2; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log master-bin.000001, end_log_pos 692
Skip_Counter	0
Exec_Master_Log_Pos	549
Relay_Log_Space	1405
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	1205
Last_SQL_Error	Could not execute Write_rows event on table test.t2; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log master-bin.000001, end_log_pos 692
=========================

mysqltest: In included file "./extra/rpl_tests/rpl_deadlock.test": At line 92: could not sync with master ('select master_pos_wait('master-bin.000001', 1544)' returned NULL)

The result from queries just before the failure was:
< snip >
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	
stop slave;
delete from t3;
change master to master_log_pos=549;
begin;
select * from t2 for update;
a
0
start slave;
select count(*) from t3  /* must be zero */;
count(*)
0
commit;

More results from queries before failure can be found in /tmp/var-rpl_binlog_row-7/log/rpl_deadlock_innodb.log

Stopping All Servers
==== END FAILURE 2 ====

It happened both in statement mode:

https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=77 sol10-amd64-a/n_mix

and in row mode:
https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-bugteam&order=17... sol10-amd64-a/rpl_binlog_row
[22 Oct 2008 13:22] Sven Sandberg
==== PURPOSE OF THE TEST ====

The purpose of the test is to check the behavior of a deadlock with innodb locks, between the slave's SQL thread and the client connection. Moreover, it wants to test this when the transaction spans several binlogs. The test ensures that innodb will choose to rollback the SQL thread.

To create a deadlock, it creates a transaction on master that does:

  BEGIN
    update t2
    update t1
  COMMIT

and on slave it does:

  BEGIN
    lock all rows of t1
    START SLAVE
    lock all rows of t2
  COMMIT

To ensure that the transaction spans several binlogs, it sets a low value for --max-relay-log-size and makes the master's transaction big.

To ensure that the slave SQL thread and not the client thread is rolled back, it makes the slave client transaction bigger than the master's transaction. (That utilizes a heuristic in innodb that works as follows. Each transaction is given a "weight", which is the number of modified rows plus the number of locked rows. The transaction of smallest weight will be rolled back.)

So a simplified version of the test case looks like this:

 1   master: BEGIN
 2             insert 10 rows into t3
 3             INSERT INTO t2
 4             INSERT INTO t1
 5           COMMIT
 6   slave:  BEGIN
 7             insert 100 rows into t4
 8             SELECT * FROM t1 FOR UPDATE
 9             START SLAVE
 10            sleep 2
 11            SELECT * FROM t2 FOR UPDATE
 12          COMMIT

==== THE FAILURE ====

There are two types of failures above:

 (1) "lock wait timeout exceeded" on line 11 in the simplified version.
     This means that line 11 did not cause deadlock, which means that 2
     seconds was not enough for the slave to replicate everything. Moreover,
     the slave server was so overloaded that the lock could not be acquired
     for the 4 seconds specified by innodb_lock_wait_timeout (in the
     -slave.opt file).

 (2) "lock wait timeout exceeded" in the slave sql thread after the second
     transaction has committed. There are two ways this could have happened:
   (2a) There was no deadlock on line 11 because 2 seconds was not enough
        for the slave to replicate everything. After that, the transaction
        in the slave client successfully committed. Then, the slave sql
        thread had time to replicate again, but the 4 seconds specified by
        innodb_lock_wait_timeout was not enough.
   (2b) There was a deadlock as expected, and the transaction in the slave
        sql thread was rolled back. The slave client transaction got the
        lock and committed. Then the slave sql thread restarted (because
        of slave_transaction_retries=2). When the slave sql thread tried to
        get the lock on t2, it timed out.

==== PROBLEMS WITH THE TEST CASE ====

 (1) The test case does not state the purpose of the test, and it does not
     explain why it needs to update t3 and t4. That made it very difficult
     to debug and review. The few comments that exist are cryptic. We
     should write proper comments.

 (2) It uses a -slave.opt file to set server variables that can be
     modified dynamically. That causes server restarts and makes the test
     difficult to debug. We should get rid of the -slave.opt file and use
     dynamic server variables instead.

 (3) The innodb_lock_wait_timeout is too low. This is what caused the
     failures in each case above (both (1), (2a), and (2b)). The timeout
     shouldn't be smaller than the default of 50 seconds.

 (4) The slave should synchronize better. That didn't cause the
     failures. If the slave does not synchronize, the test will just pass.
     However, we want the slave to synchronize as good as possible,
     because there won't be any deadlock otherwise.
[22 Oct 2008 14:14] Sven Sandberg
(5) The test uses explicit binlog positions. Please remove that, and read the binlog position on master instead.
[22 Oct 2008 14:57] Sven Sandberg
Actually, my analysis of failure (2) above (under THE FAILURE) is incorrect. The slave SQL thread got the "lock wait timeout" later, unrelated to the first case.

Here is what the test case tried to do when failure (2) occurred:

master:   BEGIN
            INSERT INTO t2
          COMMIT
slave:    BEGIN
            SELECT * FROM t2 FOR UPDATE
            start slave;
            sleep 10
          COMMIT

The test uses lock_wait_timeout=4 and slave_transaction_retries=2. Hence, the purpose of the test is that:

 1 The sql thread waits for the lock 4 seconds.
 2 The sql thread times out and restarts the transaction.
 3 The sql thread waits for the lock 4 seconds more.
 4 The sql thread times out and restarts the transaction.
 5 The sql thread waits for the lock for 2 seconds more.
 6 The client thread stops sleeping (10 seconds have passed), commits, and gives up the lock
 7 The sql thread finally gets the lock and can proceed.
  
When the test failed, the sql thread timed out a third time. That means the client thread was too slow in giving up the lock, so the sql thread timed out a third time. Since slave_transaction_retries=2, the sql thread will not restart again, and instead give an error and stop.

We should still implement (1)-(5) above. The second part of the test should also be rewritten so that it syncs as good as possible, and so that it uses longer lock_wait_timeouts.
[15 Feb 2009 22:34] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/66404

2801 Serge Kozlov	2009-02-16
      Bug#37716: The test case completely rewritten. Main items are:
      1. Removed all sleeps.
      2. Logic of test is optimized.
      3. Added comments.
      4. Updated result file.
      added:
        mysql-test/include/wait_for_status_var.inc
      modified:
        mysql-test/extra/rpl_tests/rpl_deadlock.test
        mysql-test/suite/rpl/r/rpl_deadlock_innodb.result

=== modified file 'mysql-test/extra/rpl_tests/rpl_deadlock.test'
--- a/mysql-test/extra/rpl_tests/rpl_deadlock.test	2007-06-21 12:39:40 +0000
+++ b/mysql-test/extra/rpl_tests/rpl_deadlock.test	2009-02-15 22:33:20 +0000
@@ -7,125 +7,121 @@
 # (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;
-
-# 1) Test deadlock
+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;
-# 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;
+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
 
-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
+# 1) Test deadlock
+--echo *** Test deadlock ***
 
-select * from t2 for update /* dl */; # provoke deadlock, repl-ed should be victim
-commit;
+connection slave;
+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
+--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
+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
-
-# 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;
-
-# 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;
+# Check data from tables
+SELECT * FROM t1;
+SELECT * FROM t3;
+# Check that no error is reported
+--source include/show_slave_status2.inc
+--echo
+
+# 3) Test lock wait timeout and purged relay log
+--echo *** Test lock wait timeout and purged relay logs ***
+
+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

=== added file 'mysql-test/include/wait_for_status_var.inc'
--- a/mysql-test/include/wait_for_status_var.inc	1970-01-01 00:00:00 +0000
+++ b/mysql-test/include/wait_for_status_var.inc	2009-02-15 22:33:20 +0000
@@ -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);
+}

=== modified file 'mysql-test/suite/rpl/r/rpl_deadlock_innodb.result'
--- a/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result	2007-06-27 12:29:10 +0000
+++ b/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result	2009-02-15 22:33:20 +0000
@@ -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;
-a
-start slave;
-select * from t2 for update /* dl */;
-a
-commit;
-select * from t1;
+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 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,38 +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=440;
+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_IO_Running	Yes
 Slave_SQL_Running	Yes
 Replicate_Do_DB	
 Replicate_Ignore_DB	
@@ -138,47 +147,50 @@ Master_SSL_Cipher	
 Master_SSL_Key	
 Seconds_Behind_Master	#
 Master_SSL_Verify_Server_Cert	No
-Last_IO_Errno	0
-Last_IO_Error	
+Last_IO_Errno	#
+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;
+
+*** 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
-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
 1
-select * from t2;
+SELECT * FROM t3;
 a
-0
-0
-0
-show slave status;
+3
+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_IO_Running	Yes
 Slave_SQL_Running	Yes
 Replicate_Do_DB	
 Replicate_Ignore_DB	
@@ -206,6 +218,8 @@ 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;
+
+*** Clean up ***
+DROP TABLE t1,t2,t3;
+SET global max_relay_log_size= @my_max_relay_log_size;
 End of 5.1 tests

-- 
MySQL Code Commits Mailing List
For list archives: http://lists.mysql.com/commits
To unsubscribe:    http://lists.mysql.com/commits?unsub=commits@bugs.mysql.com
[23 Mar 2009 10:24] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/70031

2828 Serge Kozlov	2009-03-23
      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.
      added:
        mysql-test/include/wait_for_status_var.inc
      modified:
        mysql-test/extra/rpl_tests/rpl_deadlock.test
        mysql-test/suite/rpl/r/rpl_deadlock_innodb.result
[3 Apr 2009 21:02] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/71360

2856 Serge Kozlov	2009-04-04
      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.
      added:
        mysql-test/include/wait_for_status_var.inc
      modified:
        mysql-test/extra/rpl_tests/rpl_deadlock.test
        mysql-test/suite/rpl/r/rpl_deadlock_innodb.result
[3 Apr 2009 21:34] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/71368

2856 Serge Kozlov	2009-04-04
       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.
      added:
        mysql-test/include/wait_for_status_var.inc
      modified:
        mysql-test/extra/rpl_tests/rpl_deadlock.test
        mysql-test/suite/rpl/r/rpl_deadlock_innodb.result
[3 Apr 2009 21:41] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/71371

3180 Serge Kozlov	2009-04-04 [merge]
      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.
      removed:
        mysql-test/include/wait_for_status_var.inc
      added:
        mysql-test/include/wait_for_status_var.inc
      modified:
        mysql-test/extra/rpl_tests/rpl_deadlock.test
        mysql-test/suite/rpl/r/rpl_deadlock_innodb.result
[5 May 2009 19:42] Bugs System
Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)
[6 May 2009 14:09] Bugs System
Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:serge.kozlov@sun.com-20090403214017-xo48zof7jrh3upep) (merge vers: 6.0.11-alpha) (pib:6)
[7 May 2009 12:41] Jon Stephens
Test case only; no user-facing changes to document. Closed.
[15 Jun 2009 8:28] Bugs System
Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)
[15 Jun 2009 9:08] Bugs System
Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)
[15 Jun 2009 9:49] Bugs System
Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)