MySQL Bugs: #61502: deadlock on insertion - insert holds and waits on same lock

Bug #61502	deadlock on insertion - insert holds and waits on same lock
Submitted:	13 Jun 2011 14:02	Modified:	4 Aug 2011 21:32
Reporter:	Greg Hazel	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.5.10	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
I got a deadlock which seems to be caused by one transaction both holding and waiting on the same lock...

------------------------
LATEST DETECTED DEADLOCK
------------------------
110613 12:07:42
*** (1) TRANSACTION:
TRANSACTION BAFE9EEA, ACTIVE 3 sec, process no 23086, OS thread id 1514367296 inserting
mysql tables in use 1, locked 1
LOCK WAIT 6 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 5
MySQL thread id 1039112, query id 693500378 10.10.10.10 user update
INSERT INTO `entries` (`created_at`, `nuid`, `updated_at`, `hidden`, `item_type`, `hidable`, `action_id`, `item_id`) VALUES('2011-06-  13 12:07:40', 3037690260, '2011-06-13 12:07:40', 0, 'User', 1, 11294338, 1408934)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 441 page no 158057 n bits 640 index `index_entries_on_item_id` of table `user_db`.`entries` trx id BAFE9E  EA lock_mode X locks gap before rec insert intention waiting
*** (2) TRANSACTION:
TRANSACTION BAFE8D51, ACTIVE 45 sec, process no 23086, OS thread id 1507977536 inserting
mysql tables in use 1, locked 1
7 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 5
MySQL thread id 1039716, query id 693488863 10.10.10.10 user update
INSERT INTO `entries` (`created_at`, `nuid`, `updated_at`, `hidden`, `item_type`, `hidable`, `action_id`, `item_id`) VALUES('2011-06-  13 12:06:58', 3029124520, '2011-06-13 12:06:58', 0, 'User', 1, 11294337, 1408933)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 441 page no 158057 n bits 640 index `index_entries_on_item_id` of table `user_db`.`entries` trx id BAFE8D  51 lock_mode X locks gap before rec
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 441 page no 158057 n bits 640 index `index_entries_on_item_id` of table `user_db`.`entries` trx id BAFE8D  51 lock_mode X locks gap before rec insert intention waiting
*** WE ROLL BACK TRANSACTION (1)

Am I misreading it? Transaction 2 appears to be waiting on the lock it already holds.

In case it matters:

mysql> SELECT @@GLOBAL.tx_isolation, @@tx_isolation;
+-----------------------+-----------------+
| @@GLOBAL.tx_isolation | @@tx_isolation  |
+-----------------------+-----------------+
| REPEATABLE-READ       | REPEATABLE-READ |
+-----------------------+-----------------+
1 row in set (0.00 sec)

How to repeat:
Uncertain. Presumably, run concurrent inserts until the bug occurs.

Please, check if http://dev.mysql.com/doc/refman/5.5/en/innodb-locks-set.html explains the problem (see parts related to insert intention locks). 

Looks like your transactions try to insert into the same gap (values 1408933 and 1408934 of item_id are inserted) between existing values. One of them already locked the gap (see http://dev.mysql.com/doc/refman/5.5/en/innodb-record-level-locks.html), but this is a gap lock, not insert intention gap lock.

Please, send CREATE TABLE for the table in question.

It's not clear if these two transactions are "inserting at the same position within the gap". I suppose they must be for this deadlock to occur, but it's not obvious.

How is it that the insert could have locked the gap lock without grabbing the "insert intention" lock? More importantly, why can't it upgrade the lock type from a gap lock to "insert intention" so that it can complete?

mysql> show create table entries\G
*************************** 1. row ***************************
       Table: entries
Create Table: CREATE TABLE `entries` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `item_id` int(11) DEFAULT NULL,
  `item_type` varchar(255) DEFAULT NULL,
  `action_id` int(11) DEFAULT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  `nuid` int(11) unsigned NOT NULL DEFAULT '0',
  `hidden` tinyint(1) DEFAULT '0',
  `hidable` tinyint(1) NOT NULL DEFAULT '0',
  PRIMARY KEY (`id`),
  KEY `index_entries_on_item_id` (`item_id`),
  KEY `index_entries_on_item_type` (`item_type`),
  KEY `index_entries_on_action_id` (`action_id`),
  KEY `index_entries_on_created_at` (`created_at`),
  KEY `index_entries_on_updated_at` (`updated_at`),
  KEY `index_entries_on_nuid` (`nuid`),
  KEY `index_entries_on_hidden` (`hidden`),
  KEY `index_entries_on_hidable` (`hidable`)
) ENGINE=InnoDB AUTO_INCREMENT=15103328 DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

Thank you for the feedback.

It does not wait a lock for same row, it waits lock which hold by another transaction:

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 441 page no 158057 n bits 640 index `index_entries_on_item_id` of
table `user_db`.`entries` trx id BAFE9E  EA lock_mode X locks gap before rec insert
intention waiting

...

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 441 page no 158057 n bits 640 index `index_entries_on_item_id` of
table `user_db`.`entries` trx id BAFE8D  51 lock_mode X locks gap before rec

I have debugging information in DEADLOCK output. You can see it:

------------------------
LATEST DETECTED DEADLOCK
------------------------
110804 22:43:33
*** (1) TRANSACTION:
TRANSACTION 3BEC, ACTIVE 6 sec, OS thread id 35261952 inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 320, 4 row lock(s), undo log entries 2
MySQL thread id 33696, query id 1390 localhost root update
INSERT INTO `entries` (`created_at`, `nuid`, `updated_at`, `hidden`, `item_type`, `hidable`, `action_id`, `item_id`) VALUES('2011-06-13 12:06:58', 3029124520, '2011-06-13 12:06:58', 0, 'User', 1, 11294337, 1408933)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1130 page no 9 n bits 80 index `index_entries_on_nuid` of table `test`.`entries` trx id 3BEC lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex b50f7994; asc   y ;;
 1: len 4; hex 80e6756a; asc   uj;;

*** (2) TRANSACTION:
TRANSACTION 3BEB, ACTIVE 16 sec, OS thread id 35238912 inserting
mysql tables in use 1, locked 1
5 lock struct(s), heap size 320, 4 row lock(s), undo log entries 2
MySQL thread id 33697, query id 1391 localhost root update
INSERT INTO `entries` (`created_at`, `nuid`, `updated_at`, `hidden`, `item_type`, `hidable`, `action_id`, `item_id`) VALUES('2011-06-13 12:07:40', 3037690260, '2011-06-13 12:07:40', 0, 'User', 1, 11294338, 1408934)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1130 page no 9 n bits 80 index `index_entries_on_nuid` of table `test`.`entries` trx id 3BEB lock_mode X locks gap before rec
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex b50f7994; asc   y ;;
 1: len 4; hex 80e6756a; asc   uj;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1130 page no 9 n bits 80 index `index_entries_on_nuid` of table `test`.`entries` trx id 3BEB lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** WE ROLL BACK TRANSACTION (1)

Pay attention not to "RECORD LOCKS space id 1130 page no 9 n bits 80 index `index_entries_on_nuid` of table `test`.`entries`", but for record content.

I see, in your debugging output, that transaction 2 is waiting for a different record than it holds, but why can't it get that lock? Who holds it?