MySQL Bugs: #41756: Strange error messages about locks from InnoDB

Bug #41756	Strange error messages about locks from InnoDB
Submitted:	26 Dec 2008 14:42	Modified:	18 Jun 2010 2:06
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S3 (Non-critical)
Version:	5.0.x, 5.0.79, 5.0.84, 5.1.37-bzr	OS:	Any (linux, windows ,solaris)
Assigned to:	Konstantin Osipov	CPU Architecture:	Any
Tags:	innodb_locks_unsafe_for_binlog

Description:
In some rare cases (on two sites so far) InnoDB outputs numerous error messages like these:

080912 7:43:14 InnoDB: Error: unlock row could not find a 4 mode lock on the record
080912 7:43:14 InnoDB: Error: unlock row could not find a 4 mode lock on the record

into the error log of a slave server where data are changed locally and NOT only through replication. This happens only if innodb_locks_unsafe_for_binlog=ON on slave.

These error messages lead to monitoring problems and increases the error log size, although they can be just ignored in some cases as no other harm is noted.

How to repeat:
Looks like these error messages are related to INSERT ... SELECT statements applied to local (InnoDB) temporary tables on slave, when the table being read is changed concurrently by replication thread.

There is no clear repeatable test case identified so far.

Suggested fix:
It is not always possible/desirable to set innodb_locks_unsafe_for_binlog=OFF on a slave that is NOT read-only (because of deadlocks) and has binlog enabled.

This error message appears because row_unlock_for_mysql() function assumes that we should have S lock on some record(s), while we don't have them. This function calls lock_rec_unlock() once for ordinary index and second time for
clustered index. It has the following comment in the source code:

/*
This can only be used when srv_locks_unsafe_for_binlog is TRUE. Before
calling this function we must use trx_reset_new_rec_lock_info() and
trx_register_new_rec_lock() to store the information which new record locks
really were set. This function removes a newly set lock under prebuilt->pcur,
and also under prebuilt->clust_pcur. Currently, this is only used and tested
in the case of an UPDATE or a DELETE statement, where the row lock is of the
LOCK_X or LOCK_S type.
*/

So, looks like we may deal with something unexpected and/or not tested in this case.

we are seeing this often on 5.1.33 (on Solaris), so the problem is not only 5.0.x.  this is on a replication slave, where many queries are run of the form "INSERT INTO local_table SELECT ... FROM replicated_table", with innodb_locks_unsafe_for_binlog=1.

I repeated this today for first time ever:

Version: '5.1.35'  socket: ''  port: 3306  Source distribution
17:28:16  InnoDB: Error: unlock row could not find a 4 mode lock on the record
17:28:16  InnoDB: Error: unlock row could not find a 4 mode lock on the record
17:28:16  InnoDB: Error: unlock row could not find a 4 mode lock on the record
17:28:16  InnoDB: Error: unlock row could not find a 4 mode lock on the record
17:28:16  InnoDB: Error: unlock row could not find a 4 mode lock on the record

testcase was not too complex. I'll enable logging and see if it's repeatable.

testcase 1:

drop table if exists tb1,tb2;
create table `tb2` (`a` int,`b` int) engine=innodb;
insert into `tb2` values (1,2),(1,2);
create table `tb1` (`a` int,`b` int primary key) engine=innodb;
insert into `tb1` values (1,1),(null,2),(1,3),(1,4);
select 1 from `tb1` natural join (select * from `tb2`) as `d` for update;
 
produces this error message:

InnoDB: Error: unlock row could not find a 5 mode lock on the record

please run server with --transaction-isolation=read-committed for the above testcase, and the next testcase.

testcase 2 is same as first, except 'lock in share mode':
run with read committed transaction level:

drop table if exists tb1,tb2;
create table `tb2` (`a` int,`b` int) engine=innodb;
insert into `tb2` values (1,2),(1,2);
create table `tb1` (`a` int,`b` int primary key) engine=innodb;
insert into `tb1` values (1,1),(null,2),(1,3),(1,4);
select 1 from `tb1` natural join (select * from `tb2`) as `d` lock in share mode;

to repeat the errors in 5.0.79 i had to run server like this:

--transaction-isolation=read-committed --log-bin --innodb_locks_unsafe_for_binlog=1

Version: '5.0.79-enterprise-gpl-debug-log'  socket: ''  port: 3307  MySQL Enterprise Server - Pro Edition Debug (GPL)
090616 21:19:48  InnoDB: Error: unlock row could not find a 4 mode lock on the record
090616 21:19:59  InnoDB: Error: unlock row could not find a 5 mode lock on the record

Verified just as described in recent comments from Shane with latest 5.1.36 from bzr (both test cases).

Verified with latest 5.0.84 from bzr also:

valeriy-kravchuks-macbook-pro:5.0 openxs$ bin/mysqld_safe --transaction-isolation=read-committed --log-bin --innodb_locks_unsafe_for_binlog=1 &
[1] 12288
valeriy-kravchuks-macbook-pro:5.0 openxs$ chown: /Users/openxs/dbs/5.0/var/valeriy-kravchuks-macbook-pro.local.err: Operation not permitted
Starting mysqld daemon with databases from /Users/openxs/dbs/5.0/var

valeriy-kravchuks-macbook-pro:5.0 openxs$ bin/mysql -uroot testReading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.84-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> drop table if exists tb1,tb2;
Query OK, 0 rows affected, 2 warnings (0.00 sec)

mysql> create table `tb2` (`a` int,`b` int) engine=innodb;
Query OK, 0 rows affected (0.37 sec)

mysql> insert into `tb2` values (1,2),(1,2);
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> create table `tb1` (`a` int,`b` int primary key) engine=innodb;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into `tb1` values (1,1),(null,2),(1,3),(1,4);
Query OK, 4 rows affected (0.01 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> select 1 from `tb1` natural join (select * from `tb2`) as `d` for update;Empty set (0.00 sec)

mysql>  
mysql> drop table if exists tb1,tb2;
Query OK, 0 rows affected (0.00 sec)

mysql> create table `tb2` (`a` int,`b` int) engine=innodb;
Query OK, 0 rows affected (0.01 sec)

mysql> insert into `tb2` values (1,2),(1,2);
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> create table `tb1` (`a` int,`b` int primary key) engine=innodb;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into `tb1` values (1,1),(null,2),(1,3),(1,4);
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> select 1 from `tb1` natural join (select * from `tb2`) as `d` lock in share mode;
Empty set (0.00 sec)

mysql> exit
Bye
valeriy-kravchuks-macbook-pro:5.0 openxs$ tail var/valeriy-kravchuks-macbook-pro.local.err 
090617  6:59:08 [Warning] Setting lower_case_table_names=2 because file system for /Users/openxs/dbs/5.0/var/ is case insensitive
090617  6:59:08 [Warning] One can only use the --user switch if running as root

090617  6:59:08 [Warning] You have enabled the binary log, but you haven't set server-id to a non-zero value: we force server id to 1; updates will be logged to the binary log, but connections from slaves will not be accepted.
090617  6:59:08 [Warning] No argument was provided to --log-bin, and --log-bin-index was not used; so replication may break when this MySQL server acts as a master and has his hostname changed!! Please use '--log-bin=valeriy-kravchuks-macbook-pro-bin' to avoid this problem.
090617  6:59:08  InnoDB: Started; log sequence number 0 31378397
090617  6:59:08 [Note] /Users/openxs/dbs/5.0/libexec/mysqld: ready for connections.
Version: '5.0.84-debug-log'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
090617  6:59:21  InnoDB: Error: unlock row could not find a 5 mode lock on the record
090617  6:59:33  InnoDB: Error: unlock row could not find a 4 mode lock on the record

Sorry, I cannot repeat this in the latest InnoDB development versions of 5.0, 5.1 or InnoDB Plugin. I was thinking that this could be related to Bug #39320, but it looks like only 5.1 was affected by that bug. I will try once more to reproduce this in the MySQL 5.0 tree.

I cannot repeat this bug with http://bazaar.launchpad.net/%7Emysql/mysql-server/mysql-5.0/ either, as of the following version:

bzr version-info
revision-id: gkodinov@mysql.com-20090616082753-kwe0l8uoictxhojf                
date: 2009-06-16 10:27:53 +0200
build-date: 2009-06-24 14:12:53 +0300
revno: 2775
branch-nick: mysql-5.0

Built with BUILD/compile-pentium-debug, defined UNIV_DEBUG in univ.i, mysqld started as
--gdb --transaction-isolation=read-committed --log-bin --innodb_locks_unsafe_for_binlog=1
I see no output from mysqld in the error log when I feed the following commands to the mysql client:

set session transaction isolation level read committed;
create table bug41756_1 (a int, b int primary key) engine=innodb;
create table bug41756_2 (a int, b int) engine=innodb;
insert into bug41756_1 values (1,1),(null,2),(1,3),(1,4);
select 1 from bug41756_1 natural join (select * from bug41756_2) d
for update;
select 1 from bug41756_1 natural join (select * from bug41756_2) d
lock in share mode;

drop table bug41756_1,bug41756_2;

The only printout I see is the thread start/exit printed by gdb.

This is still easily repeatable, but you need to start server with innodb_locks_unsafe_for_binlog set or with --transaction-isolation=read-committed, as Shane explicitely mentioned. Look:

openxs@suse:/home2/openxs/bzr/mysql-5.1> bzr version-info
revision-id: jperkin@sun.com-20090616120004-t5h478l7w5j4pwsz
date: 2009-06-16 14:00:04 +0200
build-date: 2009-09-29 23:49:47 +0300
revno: 2951
branch-nick: mysql-5.1

So, my version ofd 5.1 is newer, and:

openxs@suse:/home2/openxs/bzr/mysql-5.1> cd ../../dbs/5.1
openxs@suse:/home2/openxs/dbs/5.1> bin/mysqld_safe --transaction-isolation=read-committed &
[1] 15321
openxs@suse:/home2/openxs/dbs/5.1> 090929 23:54:39 mysqld_safe Logging to '/home2/openxs/dbs/5.1/var/suse.err'.
090929 23:54:40 mysqld_safe Starting mysqld daemon with databases from /home2/openxs/dbs/5.1/var

openxs@suse:/home2/openxs/dbs/5.1> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.37-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> drop table if exists tb1,tb2;
Query OK, 0 rows affected (0.07 sec)

mysql> create table `tb2` (`a` int,`b` int) engine=innodb;
Query OK, 0 rows affected (0.05 sec)

mysql> insert into `tb2` values (1,2),(1,2);
Query OK, 2 rows affected (0.01 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> create table `tb1` (`a` int,`b` int primary key) engine=innodb;
Query OK, 0 rows affected (0.05 sec)

mysql> insert into `tb1` values (1,1),(null,2),(1,3),(1,4);
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> select 1 from `tb1` natural join (select * from `tb2`) as `d` lock in share mode;
Empty set (0.01 sec)

mysql> exit
Bye
openxs@suse:/home2/openxs/dbs/5.1> tail var/suse.err
090929 23:54:00 mysqld_safe mysqld from pid file /home2/openxs/dbs/5.1/var/suse.pid ended
090929 23:54:40 mysqld_safe Starting mysqld daemon with databases from /home2/openxs/dbs/5.1/var
090929 23:54:40 [Note] Plugin 'FEDERATED' is disabled.
090929 23:54:40 [Note] Plugin 'ndbcluster' is disabled.
090929 23:54:40  InnoDB: Started; log sequence number 0 165782891
090929 23:54:40 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=suse-relay-bin' to avoid this problem.
090929 23:54:40 [Note] Event Scheduler: Loaded 0 events
090929 23:54:40 [Note] /home2/openxs/dbs/5.1/libexec/mysqld: ready for connections.
Version: '5.1.37-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
090929 23:55:05  InnoDB: Error: unlock row could not find a 4 mode lock on the record

There are error messages!

Marko, you've used a wrong testcase.

You didn't populate the bug41756_2 table!!!

Thanks Shane, I can reproduce it now. I wanted to rename the tables in the test case, so that we can better reuse the test cases in a stress test by executing multiple tests in parallel.

MySQL is calling unlock_row twice for the first table (tb1) for each SELECT. The error message is displayed on the second call. The MySQL layer is breaking the protocol by invoking unlock_row twice for the same row. You can verify this by setting breakpoints on row_search_for_mysql() and ha_innobase::unlock_row():

Version: '5.1.37-debug-log'  socket: '.../mysql-5.1/mysql-test/var/tmp/mysqld.1.sock'  port: 13000  Source distribution
[New Thread 0xb36a9b90 (LWP 10622)]
[Switching to Thread 0xb36a9b90 (LWP 10622)]
Breakpoint 4, row_search_for_mysql (buf=0xabb4760 "\377", mode=1, prebuilt=0xb72ae868, match_mode=0, direction=0) at row/row0sel.c:3188
Current language:  auto; currently c
(gdb) display prebuilt->table->name
3: prebuilt->table->name = 0xb72a7168 "test/bug41756_2"
(gdb) c
Continuing.

Breakpoint 4, row_search_for_mysql (buf=0xabb4760 "\371\001", mode=0, prebuilt=0xb72ae868, match_mode=0, direction=1) at row/row0sel.c:3188
3: prebuilt->table->name = 0xb72a7168 "test/bug41756_2"
(gdb) 
Continuing.

Breakpoint 4, row_search_for_mysql (buf=0xabb4760 "\371\001", mode=0, prebuilt=0xb72ae868, match_mode=0, direction=1) at row/row0sel.c:3188
3: prebuilt->table->name = 0xb72a7168 "test/bug41756_2"
(gdb) 
Continuing.

Breakpoint 4, row_search_for_mysql (buf=0xaba5478 "\375\001", mode=2, prebuilt=0xb72b0868, match_mode=1, direction=0) at row/row0sel.c:3188
3: prebuilt->table->name = 0xb72a7968 "test/bug41756_1"
(gdb) 
Continuing.

Breakpoint 3, ha_innobase::unlock_row (this=0xaba5328) at handler/ha_innodb.cc:4184
2: this->prebuilt->table->name = 0xb72a7968 "test/bug41756_1"
Current language:  auto; currently c++
(gdb) 
Continuing.

Breakpoint 3, ha_innobase::unlock_row (this=0xaba5328) at handler/ha_innodb.cc:4184
2: this->prebuilt->table->name = 0xb72a7968 "test/bug41756_1"
(gdb) finish
Run till exit from #0  ha_innobase::unlock_row (this=0xaba5328) at handler/ha_innodb.cc:4184
090624 22:47:48  InnoDB: Error: unlock row could not find a 5 mode lock on the record

The convention, documented in innobase/include/row0mysql.h (search for "row_read_type"), is that unlock_row should be called at most once per non-matching row. This bug would have to be fixed within the MySQL query evaluator. When I implemented semi-consistent read (Bug #3300), I did not entirely understand the join execution logic. It is also possible that the protocol was broken by some later change. Either way, this bug has to be fixed within the MySQL proper. I'm thus assigning it away from InnoDB and me. (InnoDB just happens to expose the bug by implementing handler::unlock_row.)

This is becoming a critical bug for us on 5.1.38 (enterprise).  Logging of errors is now taking up approximately as much space as the binlogs themselves.  We can reproduce this behavior with or without slaves when binlogs are turned on.

Bug: http://bugs.mysql.com/bug.php?id=48306 marked as duplicate of this one.

These error messages are not harmless.

For example, take Shane's test. 'FOR UPDATE' clause is effectively ignored
for t1 rows:

--echo #
--echo # Bug#41756 Strange error messages about locks from InnoDB
--echo #
--disable_warnings
drop table if exists t1, t2;
--enable_warnings

create table t1 (a int, b int primary key) engine=innodb;
insert into t1 values (1,1), (null,2), (1,3), (1,4);
create table t2 (a int, b int) engine=innodb;
insert into t2 values (1,2), (1,2);
begin;
select 1 from t1 natural join (select * from t2) as d for update;
connect (con1,localhost,root,,);
--echo #
--echo # Switching to connection con1
connection con1;
--error ER_LOCK_WAIT_TIMEOUT
delete from t1;
disconnect con1;
connection default;
commit;

drop table t1, t2;

In the above test case one can delete records from t1, even though they were supposed to be locked for update.

Result of the above test is:
TEST                           RESULT         TIME (ms)
-------------------------------------------------------

41756                          [ fail ]

mysqltest: At line 23: query 'delete from t1' succeeded - should have failed with errno 1205...

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/88518

2829 Konstantin Osipov	2009-10-28
      A preview of the fix for 
      Bug#41756 "Strange error messages about locks from InnoDB".
      
      Don't try to unlock rows unless certain that a) they were locked
      b) they are not used.

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/88744

2829 Konstantin Osipov	2009-10-30
      A preview of the fix for 
      Bug#41756 "Strange error messages about locks from InnoDB".
      
      Don't try to unlock rows unless certain that a) they were locked
      b) they are not used.
      An extended fix that counts locks.

Can we convert all Innodb errors into assertions? This will make it much easier to detect them without processing the server error log.

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/88864

3171 Konstantin Osipov	2009-10-31
      A fix and a test case for 
      Bug#41756 "Strange error messages about locks from InnoDB".
            
      In JT_EQ_REF (join_read_key()) access method, 
      don't try to unlock rows in the handler, unless certain that 
      a) they were locked
      b) they are not used.
      
      Unlocking of rows is done by the logic of the nested join loop,
      and is unaware of the possible caching that the access method may
      have. This could lead to double unlocking, when a row
      was unlocked first after reading into the cache, and then 
      when taken from cache, as well as to unlocking of rows which
      were actually used (but taken from cache).
            
      Delegate part of the unlocking logic to the access method,
      and in JT_EQ_REF count how many times a record was actually 
      used in the join. Unlock it only if it's usage count is 0.
     @ mysql-test/r/innodb_lock_wait_timeout_1.result
        Update results (Bug41756).
     @ mysql-test/t/innodb_lock_wait_timeout_1.test
        Add a test case (Bug#41756).
     @ sql/item_subselect.cc
        Complete struct READ_RECORD initialization with a new
        member to unlock records.
     @ sql/records.cc
        Extend READ_RECORD API with a method to unlock read records.
     @ sql/sql_select.cc
        In JT_EQ_REF (join_read_key()) access method, 
        don't try to unlock rows in the handler, unless certain that 
        a) they were locked
        b) they are not used.
     @ sql/sql_select.h
        Add members to TABLE_REF to count TABLE_REF buffer usage count.
     @ sql/structs.h
        Update declarations.

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/89115

3171 Konstantin Osipov	2009-11-03
      A fix and a test case for 
      Bug#41756 "Strange error messages about locks from InnoDB".
            
      In JT_EQ_REF (join_read_key()) access method, 
      don't try to unlock rows in the handler, unless certain that 
      a) they were locked
      b) they are not used.
      
      Unlocking of rows is done by the logic of the nested join loop,
      and is unaware of the possible caching that the access method may
      have. This could lead to double unlocking, when a row
      was unlocked first after reading into the cache, and then 
      when taken from cache, as well as to unlocking of rows which
      were actually used (but taken from cache).
            
      Delegate part of the unlocking logic to the access method,
      and in JT_EQ_REF count how many times a record was actually 
      used in the join. Unlock it only if it's usage count is 0.
      
      Implemented review comments.
     @ mysql-test/r/innodb_lock_wait_timeout_1.result
        Update results (Bug41756).
     @ mysql-test/t/innodb_lock_wait_timeout_1.test
        Add a test case (Bug#41756).
     @ sql/item_subselect.cc
        Complete struct READ_RECORD initialization with a new
        member to unlock records.
     @ sql/records.cc
        Extend READ_RECORD API with a method to unlock read records.
     @ sql/sql_select.cc
        In JT_EQ_REF (join_read_key()) access method, 
        don't try to unlock rows in the handler, unless certain that 
        a) they were locked
        b) they are not used.
     @ sql/sql_select.h
        Add members to TABLE_REF to count TABLE_REF buffer usage count.
     @ sql/structs.h
        Update declarations.

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/89119

3171 Konstantin Osipov	2009-11-03
      A fix and a test case for 
      Bug#41756 "Strange error messages about locks from InnoDB".
            
      In JT_EQ_REF (join_read_key()) access method, 
      don't try to unlock rows in the handler, unless certain that 
      a) they were locked
      b) they are not used.
      
      Unlocking of rows is done by the logic of the nested join loop,
      and is unaware of the possible caching that the access method may
      have. This could lead to double unlocking, when a row
      was unlocked first after reading into the cache, and then 
      when taken from cache, as well as to unlocking of rows which
      were actually used (but taken from cache).
            
      Delegate part of the unlocking logic to the access method,
      and in JT_EQ_REF count how many times a record was actually 
      used in the join. Unlock it only if it's usage count is 0.
      
      Implemented review comments.
     @ mysql-test/r/innodb_lock_wait_timeout_1.result
        Update results (Bug41756).
     @ mysql-test/t/innodb_lock_wait_timeout_1.test
        Add a test case (Bug#41756).
     @ sql/item_subselect.cc
        Complete struct READ_RECORD initialization with a new
        member to unlock records.
     @ sql/records.cc
        Extend READ_RECORD API with a method to unlock read records.
     @ sql/sql_select.cc
        In JT_EQ_REF (join_read_key()) access method, 
        don't try to unlock rows in the handler, unless certain that 
        a) they were locked
        b) they are not used.
     @ sql/sql_select.h
        Add members to TABLE_REF to count TABLE_REF buffer usage count.
     @ sql/structs.h
        Update declarations.

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/89174

2837 Konstantin Osipov	2009-11-03
      A fix and a test case for
      Bug#41756 "Strange error messages about locks from InnoDB".
      
      In JT_EQ_REF (join_read_key()) access method,
      don't try to unlock rows in the handler, unless certain that
      a) they were locked
      b) they are not used.
      
      Unlocking of rows is done by the logic of the nested join loop,
      and is unaware of the possible caching that the access method may
      have. This could lead to double unlocking, when a row
      was unlocked first after reading into the cache, and then
      when taken from cache, as well as to unlocking of rows which
      were actually used (but taken from cache).
      
      Delegate part of the unlocking logic to the access method,
      and in JT_EQ_REF count how many times a record was actually
      used in the join. Unlock it only if it's usage count is 0.
      
      Implemented review comments.
     @ mysql-test/r/bug41756.result
        Add result file (Bug#41756)
     @ mysql-test/t/bug41756-master.opt
        Use --innodb-locks-unsafe-for-binlog, as in 5.0 just
        using read_committed isolation is not sufficient to 
        reproduce the bug.
     @ mysql-test/t/bug41756.test
        Add a test file (Bug#41756)
     @ sql/item_subselect.cc
        Complete struct READ_RECORD initialization with a new
        member to unlock records.
     @ sql/records.cc
        Extend READ_RECORD API with a method to unlock read records.
     @ sql/sql_select.cc
        In JT_EQ_REF (join_read_key()) access method,
        don't try to unlock rows in the handler, unless certain that
        a) they were locked
        b) they are not used.
     @ sql/sql_select.h
        Add members to TABLE_REF to count TABLE_REF buffer usage count.
     @ sql/structs.h
        Update declarations.

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/89181

3189 Konstantin Osipov	2009-11-03 [merge]
      A fix and a test case for 
      Bug#41756 "Strange error messages about locks from InnoDB".
            
      In JT_EQ_REF (join_read_key()) access method, 
      don't try to unlock rows in the handler, unless certain that 
      a) they were locked
      b) they are not used.
      
      Unlocking of rows is done by the logic of the nested join loop,
      and is unaware of the possible caching that the access method may
      have. This could lead to double unlocking, when a row
      was unlocked first after reading into the cache, and then 
      when taken from cache, as well as to unlocking of rows which
      were actually used (but taken from cache).
            
      Delegate part of the unlocking logic to the access method,
      and in JT_EQ_REF count how many times a record was actually 
      used in the join. Unlock it only if it's usage count is 0.
      
      Implemented review comments.
     @ mysql-test/r/innodb_lock_wait_timeout_1.result
        Update results (Bug41756).
     @ mysql-test/t/innodb_lock_wait_timeout_1.test
        Add a test case (Bug#41756).
     @ sql/item_subselect.cc
        Complete struct READ_RECORD initialization with a new
        member to unlock records.
     @ sql/records.cc
        Extend READ_RECORD API with a method to unlock read records.
     @ sql/sql_select.cc
        In JT_EQ_REF (join_read_key()) access method, 
        don't try to unlock rows in the handler, unless certain that 
        a) they were locked
        b) they are not used.
     @ sql/sql_select.h
        Add members to TABLE_REF to count TABLE_REF buffer usage count.
     @ sql/structs.h
        Update declarations.

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/89183

3190 Konstantin Osipov	2009-11-03 [merge]
      A fix and a test case for 
      Bug#41756 "Strange error messages about locks from InnoDB".
            
      In JT_EQ_REF (join_read_key()) access method, 
      don't try to unlock rows in the handler, unless certain that 
      a) they were locked
      b) they are not used.
      
      Unlocking of rows is done by the logic of the nested join loop,
      and is unaware of the possible caching that the access method may
      have. This could lead to double unlocking, when a row
      was unlocked first after reading into the cache, and then 
      when taken from cache, as well as to unlocking of rows which
      were actually used (but taken from cache).
            
      Delegate part of the unlocking logic to the access method,
      and in JT_EQ_REF count how many times a record was actually 
      used in the join. Unlock it only if it's usage count is 0.
      
      Implemented review comments.
     @ mysql-test/r/innodb_lock_wait_timeout_1.result
        Update results (Bug41756).
     @ mysql-test/t/innodb_lock_wait_timeout_1.test
        Add a test case (Bug#41756).
     @ sql/item_subselect.cc
        Complete struct READ_RECORD initialization with a new
        member to unlock records.
     @ sql/records.cc
        Extend READ_RECORD API with a method to unlock read records.
     @ sql/sql_select.cc
        In JT_EQ_REF (join_read_key()) access method, 
        don't try to unlock rows in the handler, unless certain that 
        a) they were locked
        b) they are not used.
     @ sql/sql_select.h
        Add members to TABLE_REF to count TABLE_REF buffer usage count.
     @ sql/structs.h
        Update declarations.

Pushed into 5.1-bugteam, 5.0-bugteam, mysql-pe.

Pushed into 5.0.88 (revid:joro@sun.com-20091104091355-hpz6dwgkrfmokj3k) (version source revid:kostja@sun.com-20091103165854-7di545xruez8w207) (merge vers: 5.0.88) (pib:13)

Pushed into 5.1.41 (revid:joro@sun.com-20091104092152-qz96bzlf2o1japwc) (version source revid:kostja@sun.com-20091103174552-bfpak6r7ngf5cbjb) (merge vers: 5.1.41) (pib:13)

Please, don't forget to push this to 5.4.x (if any new releases will happen) and 5.5.x.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091110093407-rw5g8dys2baqkt67) (version source revid:alik@sun.com-20091109080109-7dxapd5y5pxlu08w) (merge vers: 6.0.14-alpha) (pib:13)

Pushed into 5.5.0-beta (revid:alik@sun.com-20091109115615-nuohp02h8mdrz8m2) (version source revid:alik@sun.com-20091105145905-qen477qntdv20g5o) (merge vers: 5.5.0-beta) (pib:13)

Noted in 5.0.88, 5.1.41, 5.5.0, 6.0.14 changelogs.

In a replication scenario with innodb_locks_unsafe_for_binlog enabled
on the slave, where rows were changed only on the slave (not through 
replication), in some rare cases, many messages of the following form
were written to the slave error log: InnoDB: Error: unlock row could
not find a 4 mode lock on the record.

Noted in 5.1.40sp1 changelog.

Pushed into 5.1.43 (revid:build@mysql.com-20091208092611-pbno5awyb0v38hs7) (version source revid:build@mysql.com-20091208092611-pbno5awyb0v38hs7) (merge vers: 5.1.43) (pib:13)

Already fixed in 5.1.x.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091216083311-xorsasf5kopjxshf) (version source revid:alik@sun.com-20091215065750-5m04ogppd5l0pol5) (merge vers: 6.0.14-alpha) (pib:14)

Pushed into 5.5.0-beta (revid:alik@sun.com-20091216082430-s0gtzibcgkv4pqul) (version source revid:alik@sun.com-20091211070127-kl8uvlrv9cr11kva) (merge vers: 5.5.0-beta) (pib:14)

Pushed into mysql-next-mr (revid:alik@sun.com-20091216083231-rp8ecpnvkkbhtb27) (version source revid:alik@sun.com-20091212203859-fx4rx5uab47wwuzd) (merge vers: 5.6.0-beta) (pib:14)

Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)

Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)

Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)

Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)

Noted in 5.0.87sp1 changelog.

Pushed into 5.0.91 (revid:build@mysql.com-20100220170835-5kr6ztsg25va7qzz) (version source revid:build@mysql.com-20100220170835-5kr6ztsg25va7qzz) (merge vers: 5.0.91) (pib:16)

Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:joro@sun.com-20100226131646-kpvzk740hxbtaexn) (merge vers: 5.1.45) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100302142746-u1gxdf5yk2bjrq3e) (version source revid:alik@sun.com-20100301095421-4cz64ibem1h2quve) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.3-m2 (revid:alik@sun.com-20100302072233-t3uqgjzdukt1pyhe) (version source revid:alik@sun.com-20100301090215-63o2w2y16go8n53p) (merge vers: 5.5.3-m2) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100301094536-2zc4uqyy3os8san7) (pib:16)

Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)

Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)

Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)

in case you're still seeing this error message, please refer to bug #53674

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)