MySQL transactions deadlocking, but SHOW ENGINE INNODB STATUS does not show a true deadlock

Question

I am having some trouble with 2 processes modifying the same table in a MySQL database. Very occasionally it causes a deadlock and one or other of the processes gets a 'Deadlock found when trying to get lock; try restarting transaction' error.

I found a few answers to why this occurs on stackoverflow, and that has got me some of the way to solving the issue. (Just retry the transaction). I was hoping for a better solution than that so started investigating with SHOW ENGINE INNODB STATUS.

I have been confused by the output of the STATUS command. From what I can see it does not show a true deadlock. The first transaction is waiting for a row locked buy the second transaction, and the first transaction holds no other locks. The second transaction holds 4 locks, one being the lock required by the first transaction, and is waiting for a 5th lock. There is no mention of the 5th lock being held by any other transaction.

The output relating to the deadlock is:

------------------------
LATEST DETECTED DEADLOCK
------------------------
130514  8:54:12
*** (1) TRANSACTION:
TRANSACTION 0 487333931, ACTIVE 0 sec, process no 1007, OS thread id 2990889792 fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 320, 24 row lock(s), undo log entries 3
MySQL thread id 774102, query id 166772615 localhost 127.0.0.1 nesie updating
DELETE FROM DeviceStatus WHERE serialNo=1234567 AND subDevice=1 AND (parameter='band' OR parameter='arfcn' OR parameter='txPower' OR parameter='lac' OR parameter='cellId' OR parameter='channel' OR parameter='rxReversePower' OR parameter='reverseSnr' OR parameter='reverseGmp' OR parameter='reverseBepm' OR parameter='mobileHeldOn' OR parameter='mobileHeldBand' OR parameter='mobileTxPower' OR parameter='mobileCommandedPower' OR parameter='rxPathLoss' OR parameter='holdState' OR parameter='band' OR parameter='channel' OR parameter='arfcn' OR parameter='rxForwardPower' OR parameter='forwardSnr' OR parameter='forwardGmp' OR parameter='forwardBepm' OR parameter='lac' OR parameter='cellId')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1267 page no 3 n bits 96 index `PRIMARY` of table `nesie`.`DeviceStatus` trx id 0 487333931 lock_mode X waiting
Record lock, heap no 20 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80151487; asc     ;; 1: len 4; hex 80000001; asc     ;; 2: len 10; hex 6d6f6e69746f72696e67; asc monitoring;; 3: len 6; hex 00001d0c202a; asc      *;; 4: len 7; hex 00000000342dbd; asc     4- ;; 5: len 4; hex 80000000; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 0 487333930, ACTIVE 0 sec, process no 1007, OS thread id 3063302976 inserting, thread declared inside InnoDB 488
mysql tables in use 1, locked 1
5 lock struct(s), heap size 320, 6 row lock(s), undo log entries 4
MySQL thread id 774099, query id 166772616 localhost nesie update
REPLACE INTO DeviceStatus VALUES (1381511,1,'scanning',1),(1381511,1,'monitoring',0),(1381511,1,'transmitting',0),(1381511,1,'power',-84),(1381511,1,'band',1),(1381511,1,'uarfcn',10661),(1381511,1,'scramblingCode',377)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1267 page no 3 n bits 96 index `PRIMARY` of table `nesie`.`DeviceStatus` trx id 0 487333930 lock_mode X locks rec but not gap
Record lock, heap no 20 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80151487; asc     ;; 1: len 4; hex 80000001; asc     ;; 2: len 10; hex 6d6f6e69746f72696e67; asc monitoring;; 3: len 6; hex 00001d0c202a; asc      *;; 4: len 7; hex 00000000342dbd; asc     4- ;; 5: len 4; hex 80000000; asc     ;;

Record lock, heap no 21 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80151487; asc     ;; 1: len 4; hex 80000001; asc     ;; 2: len 5; hex 706f776572; asc power;; 3: len 6; hex 00001d0c202a; asc      *;; 4: len 7; hex 00000000342e11; asc     4. ;; 5: len 4; hex 7fffffac; asc     ;;

Record lock, heap no 22 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80151487; asc     ;; 1: len 4; hex 80000001; asc     ;; 2: len 8; hex 7363616e6e696e67; asc scanning;; 3: len 6; hex 00001d0c202a; asc      *;; 4: len 7; hex 00000000342d96; asc     4- ;; 5: len 4; hex 80000001; asc     ;;

Record lock, heap no 24 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80151487; asc     ;; 1: len 4; hex 80000001; asc     ;; 2: len 12; hex 7472616e736d697474696e67; asc transmitting;; 3: len 6; hex 00001d0c202a; asc      *;; 4: len 7; hex 00000000342de6; asc     4- ;; 5: len 4; hex 80000000; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1267 page no 3 n bits 96 index `PRIMARY` of table `nesie`.`DeviceStatus` trx id 0 487333930 lock_mode X locks rec but not gap waiting
Record lock, heap no 17 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80151487; asc     ;; 1: len 4; hex 80000001; asc     ;; 2: len 4; hex 62616e64; asc band;; 3: len 6; hex 00001d0c19ff; asc       ;; 4: len 7; hex 000000003428a7; asc     4( ;; 5: len 4; hex 80000001; asc     ;;

*** WE ROLL BACK TRANSACTION (1)

My questions are:

Why is this flagged as a deadlock, transaction 1 can be queued until transaction 2 completes as it holds no locks required by transaction 2?

Does any one know if this normal behaviour for MySQL or could it be a bug?

Thanks,

Simon.

Answer 1

You may use the new 5.6 variable: http://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_print_all_deadlocks

This way you'll be able to log all deadlocks, and maybe find which transaction is initiating your deadlock.