MySQL Bugs: #49620: Repl diff with concurrent transactions with trigger+savepoint+lock wait timeout

Bug #49620	Repl diff with concurrent transactions with trigger+savepoint+lock wait timeout
Submitted:	11 Dec 2009 12:21	Modified:	21 Dec 2009 7:45
Reporter:	Victor Kirkebo	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.1.43, 5.1, next-mr bzr	OS:	Any
Assigned to:	Alfranio Tavares Correia Junior	CPU Architecture:	Any
Tags:	ERROR 1205, lock wait timeout, replication, savepoint, trigger

Description:
I checked this on a pre-release 5.1.43 version.
When I run two concurrent transactions on an innodb table I get a replication diff between master and slave. One transaction sets a table lock. The other transaction tries to update a row in the table but gets lock wait timeout error, then sets a savepoint and tries to update the row again only to get lock wait timeout error one more time. Finally it tries to commit the transaction.
On master the innodb table has not been updated but on slave it has been.

This seems only to happen when there is an update trigger present that updates a myisam table when updates are being done to the innodb table. Also I didn't see this error when not using the savepoint inside the transaction.

I haven't had time to check other transactions doing insert/delete with insert/delete triggers. I suspect there might be a similar behavior for these.

How to repeat:
mysql> show variables like '%lock%';
+--------------------------------+----------------------+
| Variable_name                  | Value                |
+--------------------------------+----------------------+
| innodb_autoinc_lock_mode       | 1                    |
| innodb_lock_wait_timeout       | 10                   |
| innodb_locks_unsafe_for_binlog | OFF                  |
| innodb_table_locks             | ON                   |
| key_cache_block_size           | 1024                 |
| locked_in_memory               | OFF                  |
| max_write_lock_count           | 18446744073709551615 |
| query_alloc_block_size         | 8192                 |
| query_cache_wlock_invalidate   | OFF                  |
| range_alloc_block_size         | 4096                 |
| skip_external_locking          | ON                   |
| table_lock_wait_timeout        | 50                   |
| transaction_alloc_block_size   | 8192                 |
+--------------------------------+----------------------+

On master connection #1:
-------------------------
mysql> create database mydb;
Query OK, 1 row affected (0.00 sec)

mysql> use mydb;
Database changed

mysql> create table mytbl(i int) engine=innodb;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into mytbl values(10);
Query OK, 1 row affected (0.00 sec)

mysql> create table log (entry_dsc char(100)) engine=myisam;
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter //

mysql> create trigger tr_upd after update on mytbl for each row begin insert into log (entry_dsc) values (concat('Update row ', old.i,'->', new.i)); end//
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter ;

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into mytbl values(100);
Query OK, 1 row affected (0.00 sec)

On master connection #2:
-------------------------
mysql> use mydb;
Database changed

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> update mytbl set i=i-5 where i=10;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

mysql> savepoint svpt1;
Query OK, 0 rows affected (0.00 sec)

mysql> update mytbl set i=i+5 where i=10;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

mysql> commit;
Query OK, 0 rows affected (0.00 sec)

On master connection #1:
-------------------------
mysql> rollback;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from mytbl;
+------+
| i    |
+------+
|   10 |
+------+
1 row in set (0.00 sec)

mysql> select * from log;
+-------------------+
| entry_dsc         |
+-------------------+
| Update row 10->5  |
| Update row 10->15 |
+-------------------+
2 rows in set (0.00 sec)

On slave connection:
--------------------
mysql> use mydb;
Database changed

mysql> select * from mytbl;
+------+
| i    |
+------+
|    5 |
+------+
1 row in set (0.00 sec)

mysql> select * from log;
+------------------+
| entry_dsc        |
+------------------+
| Update row 10->5 |
+------------------+
1 row in set (0.00 sec)

Thank you for the report.

Verified almost as described:

master:
select * from mytbl;
i
10
select * from log;
entry_dsc
Update row 10->5
Update row 10->15

slave:
select * from mytbl;
i
15
select * from log;
entry_dsc
Update row 10->5
Update row 10->15

To repeat binlog-format=row needed.

This bug needs binlog-format=row while bug #47327 needs binlog-format=statement. They are probably duplicates anyway, but I think would be better if Replication Team decides this.

In mysql-5.1-rep+3 I have:

no rows in table mytbl on slave and error "select * from log' failed: 1146: Table 'test.log' doesn't exist"

Hi Sveta,

The error reported above is quite strange.
Have you synced the slave with the master?

I've created a test case and got the following results:

--- master ---
select * from mytbl;                                                          
i                                                                             
10                                                                            
select * from log;                                                            
entry_dsc                                                                     
Update row 10->5                                                              
Update row 10->15          

--- slave ---                                                   
use mydb;                                                                     
select * from mytbl;                                                          
i                                                                             
10                                                                            
select * from log;

--- test case ---
--source include/master-slave.inc
--source include/have_innodb.inc
--source include/have_binlog_format_row.inc

connect (a,localhost,root,,);
connect (b,localhost,root,,);

connection master;

create database mydb;
use mydb;

create table mytbl(i int) engine=innodb;
insert into mytbl values(10);
create table log (entry_dsc char(100)) engine=myisam;

DELIMITER |;
CREATE TRIGGER tr_upd AFTER UPDATE ON mytbl FOR EACH ROW
begin
insert into log (entry_dsc) values (concat('Update row ', old.i,'->', new.i));
end|
delimiter ;|

connection a;
use mydb;

start transaction;

insert into mytbl values(100);

connection b;

use mydb;

start transaction;

--error 1205
update mytbl set i=i-5 where i=10;

savepoint svpt1;

--error 1205
update mytbl set i=i+5 where i=10;

commit;

connection a;

rollback;

connection master;

select * from mytbl;
select * from log;

--sync_slave_with_master

use mydb;

select * from mytbl;
select * from log;

exit;

Alfranio,

yes, this can be closed as "Can't repeat": I retested with correct settings and bug is not repeatable in mysql-5.1-rep+3

Victor,

bug fixed in development tree mysql-5.1-rep+3 and is not in main tree yet. Please wait when changes will be merged to main.