Deadlock apparently on a single resource: How to avoid?

[Ali Rizvi]

A deadlock issue is being experienced in a system that is using InnoDB tables with transactions and locking and has high concurrency between processes.
The two processes that are involved in this deadlock both are supposed to first lock the row (in a transaction) and then each has to do a separate task of updating the row. No delete or insert statements are involved.

My investigation shows me that the following happens, but I am at a loss that why does the deadlock occur? A single row is involved and only three types of queries are involved:
1 - SELECT for UPDATE
2 - SELECT
3 - UPDATE

Process A already holds an exclusive lock an a row (by doing SELECT for UPDATE on that row)

At the same 'time' the following happens:
- Process B tries to get exclusive lock (by doing SELECT for UPDATE) of the same row and waits for the lock
- Process A runs an UPDATE query on its locked resource

Deadlock occurs!

Why does this happen and how can it be avoided?

Thanks,
Ali Rizvi
Kolachi Advanced Technologies

Following is the complete InnoDB status log for the deadlock:
[The table is named TICKET and has Primary Key TIKNUM on which locking is done.]

=====================================
060110 18:57:48 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 15 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 42090483, signal count 41499350
Mutex spin waits 785322774, rounds 869822180, OS waits 1073849
RW-shared spins 84580411, OS waits 35657872; RW-excl spins 22725059, OS waits 3017487
------------------------
LATEST DETECTED DEADLOCK
------------------------
060110 12:36:29
*** (1) TRANSACTION:
TRANSACTION 0 248835206, ACTIVE 0 sec, process no 28858, OS thread id 2912996272 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 320
MySQL thread id 5151, query id 8925498 trdelegate 202.82.29.214 tsdbuser statistics
SELECT * FROM TICKET WHERE TICKET.TIKNUM = '100000EF8V' FOR UPDATE
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 14341 n bits 112 index `PRIMARY` of table `TS/TICKET` trx id 0 248835206 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 43; 1-byte offs FALSE; info bits 0
0: len 10; hex 31303030303045463856; asc 100000EF8V;; 1: len 6; hex 00000ed4e0cb; asc ;; 2: len 7; hex 00000000c20e1c; asc ;; 3: len 4; hex 80000178; asc x;; 4: len 6; hex 455155495459; asc EQUITY;; 5: len 8; hex 8000123e9bbb45a0; asc > E ;; 6: len 4; hex 53454c4c; asc SELL;; 7: len 6; hex 303030373030; asc 000700;; 8: len 8; hex 80000000000023f0; asc # ;; 9: len 8; hex 8000000000001068; asc h;; 10: len 1; hex 53 ; asc S;; 11: len 3; hex 4b5220; asc KR ;; 12: len 2; hex 4344; asc CD;; 13: SQL NULL, size 0 ; 14: SQL NULL, size 0 ; 15: len 10; hex 4f5645525448454 44159; asc OVERTHEDAY;; 16: len 3; hex 444159; asc DAY;; 17: len 7; hex 574f524b494e47; asc WORKING;; 18: len 4; hex 52435644; asc RCVD;; 19: len 8; h ex 8000000000001388; asc ;; 20: len 16; hex 2020202032333736302e303030303030; asc 23760.000000;; 21: SQL NULL, size 0 ; 22: SQL NULL, size 0 ; 23: len 22; hex 48616e6a696e205368697070696e6720436f204c7464; asc Hanjin Shipping Co Ltd;; 24: len 3; hex 4b5343; asc KSC;; 25: len 3; hex 8fac2a ; asc *;; 26: len 1; hex 30; asc 0;; 27: len 12; hex 4b5237303030373030303035; asc KR7000700005;; 28: len 3; hex 4b5257; asc KRW;; 29: len 8; hex 80 00000000001068; asc h;; 30: len 4; hex 80000128; asc (;; 31: len 1; hex 00; asc ;; 32: len 4; hex 80000128; asc (;; 33: SQL NULL, size 0 ; 34: len 6; hex 4b522d4b5343; asc KR-KSC;; 35: len 9; hex 3030303730302e4b53; asc 000700.KS;; 36: len 4; hex 00000128; asc (;; 37: len 10; hex 31 3030303030314e3959; asc 1000001N9Y;; 38: len 4; hex 8000000b; asc ;; 39: SQL NULL, size 3 ; 40: SQL NULL, size 0 ; 41: len 6; hex 313130323334; as c 110234;; 42: len 1; hex 80; asc ;;

*** (2) TRANSACTION:
TRANSACTION 0 248835204, ACTIVE 1 sec, process no 28858, OS thread id 2913799088 starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
9 lock struct(s), heap size 1024, undo log entries 3
MySQL thread id 5127, query id 8925501 kextreme.kolachi.com 127.0.0.1 tsdbuser Updating
UPDATE TICKET SET QUANTITY='9200',STATUS='WORKING',DAYENDSEEN='0',TRADEDATE='2006-01-10',ALLOCATIONSTATUS='RCVD',ODEPARTMENTID='1000001N9Y',UNO='376', AVGPRICE=23759.708738 ,STP='0',EXECQUANTITY='5150',WORKINGQUANTITY='4050',SALESMANID='11',TRADER='296',BALQUANTITY='4050',TIKNUM='100000EF8V',COUNTRYC
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 14341 n bits 112 index `PRIMARY` of table `TS/TICKET` trx id 0 248835204 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 43; 1-byte offs FALSE; info bits 0
0: len 10; hex 31303030303045463856; asc 100000EF8V;; 1: len 6; hex 00000ed4e0cb; asc ;; 2: len 7; hex 00000000c20e1c; asc ;; 3: len 4; hex 80000178; asc x;; 4: len 6; hex 455155495459; asc EQUITY;; 5: len 8; hex 8000123e9bbb45a0; asc > E ;; 6: len 4; hex 53454c4c; asc SELL;; 7: len 6; hex 303030373030; asc 000700;; 8: len 8; hex 80000000000023f0; asc # ;; 9: len 8; hex 8000000000001068; asc h;; 10: len 1; hex 53 ; asc S;; 11: len 3; hex 4b5220; asc KR ;; 12: len 2; hex 4344; asc CD;; 13: SQL NULL, size 0 ; 14: SQL NULL, size 0 ; 15: len 10; hex 4f5645525448454 44159; asc OVERTHEDAY;; 16: len 3; hex 444159; asc DAY;; 17: len 7; hex 574f524b494e47; asc WORKING;; 18: len 4; hex 52435644; asc RCVD;; 19: len 8; h ex 8000000000001388; asc ;; 20: len 16; hex 2020202032333736302e303030303030; asc 23760.000000;; 21: SQL NULL, size 0 ; 22: SQL NULL, size 0 ; 23: len 22; hex 48616e6a696e205368697070696e6720436f204c7464; asc Hanjin Shipping Co Ltd;; 24: len 3; hex 4b5343; asc KSC;; 25: len 3; hex 8fac2a ; asc *;; 26: len 1; hex 30; asc 0;; 27: len 12; hex 4b5237303030373030303035; asc KR7000700005;; 28: len 3; hex 4b5257; asc KRW;; 29: len 8; hex 80 00000000001068; asc h;; 30: len 4; hex 80000128; asc (;; 31: len 1; hex 00; asc ;; 32: len 4; hex 80000128; asc (;; 33: SQL NULL, size 0 ; 34: len 6; hex 4b522d4b5343; asc KR-KSC;; 35: len 9; hex 3030303730302e4b53; asc 000700.KS;; 36: len 4; hex 00000128; asc (;; 37: len 10; hex 31 3030303030314e3959; asc 1000001N9Y;; 38: len 4; hex 8000000b; asc ;; 39: SQL NULL, size 3 ; 40: SQL NULL, size 0 ; 41: len 6; hex 313130323334; as c 110234;; 42: len 1; hex 80; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 14340 n bits 120 index `PRIMARY` of table `TS/TICKET` trx id 0 248835204 lock_mode X waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; 1-byte offs TRUE; info bits 0
0: len 9; hex 73757072656d756d00; asc supremum ;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 0 249446981
Purge done for trx's n:o < 0 249446707 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 28858, OS thread id 2921647024
MySQL thread id 5554, query id 9884425 localhost root
SHOW INNODB STATUS
---TRANSACTION 0 249443990, not started, process no 28858, OS thread id 2905693104
MySQL thread id 5533, query id 9884412 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249446979, not started, process no 28858, OS thread id 2906696624
MySQL thread id 5495, query id 9884395 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249443993, not started, process no 28858, OS thread id 2914601904
MySQL thread id 5494, query id 9877310 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249445029, not started, process no 28858, OS thread id 2907499440
MySQL thread id 5485, query id 9880954 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443986, not started, process no 28858, OS thread id 2906094512
MySQL thread id 5418, query id 9884404 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249443182, not started, process no 28858, OS thread id 2919275440
MySQL thread id 5344, query id 9874095 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443987, not started, process no 28858, OS thread id 2912394160
MySQL thread id 5242, query id 9877281 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249225337, not started, process no 28858, OS thread id 2911792048
MySQL thread id 5234, query id 9877220 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443991, not started, process no 28858, OS thread id 2901900208
MySQL thread id 5219, query id 9884422 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249443985, not started, process no 28858, OS thread id 2905291696
MySQL thread id 5210, query id 9884424 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249443998, not started, process no 28858, OS thread id 2911591344
MySQL thread id 5152, query id 9884408 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249446617, not started, process no 28858, OS thread id 2912193456
MySQL thread id 5115, query id 9884401 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 248526180, not started, process no 28858, OS thread id 2918271920
MySQL thread id 5065, query id 8276447 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 248802794, not started, process no 28858, OS thread id 2914401200
MySQL thread id 4671, query id 9877254 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 248525720, not started, process no 28858, OS thread id 2919639984
MySQL thread id 4670, query id 9877189 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443996, not started, process no 28858, OS thread id 2918071216
MySQL thread id 4657, query id 9877355 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249444683, not started, process no 28858, OS thread id 2920242096
MySQL thread id 4581, query id 9879306 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443531, not started, process no 28858, OS thread id 2901699504
MySQL thread id 4518, query id 9875080 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443980, not started, process no 28858, OS thread id 2902703024
MySQL thread id 4411, query id 9884418 trdelegate 202.82.29.214 tsdbuser
---TRANSACTION 0 249446208, not started, process no 28858, OS thread id 2909395888
MySQL thread id 4326, query id 9882590 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249446924, not started, process no 28858, OS thread id 2909596592
MySQL thread id 4324, query id 9884204 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443219, not started, process no 28858, OS thread id 2905893808
MySQL thread id 4241, query id 9874347 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249443301, not started, process no 28858, OS thread id 2921044912
MySQL thread id 4240, query id 9874431 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249446329, not started, process no 28858, OS thread id 2903104432
MySQL thread id 4237, query id 9882721 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249446234, not started, process no 28858, OS thread id 2900814768
MySQL thread id 4236, query id 9882618 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249446229, not started, process no 28858, OS thread id 2914200496
MySQL thread id 4235, query id 9882620 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249440342, not started, process no 28858, OS thread id 2906495920
MySQL thread id 4232, query id 9868186 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 243706206, not started, process no 28858, OS thread id 2922650544
MySQL thread id 11, query id 584749 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 243406588, not started, process no 28858, OS thread id 2923051952
MySQL thread id 9, query id 8248310 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 243406552, not started, process no 28858, OS thread id 2923252656
MySQL thread id 8, query id 1154 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249335166, not started, process no 28858, OS thread id 2923453360
MySQL thread id 7, query id 9724165 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249324848, not started, process no 28858, OS thread id 2923654064
MySQL thread id 6, query id 9712184 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249427090, not started, process no 28858, OS thread id 2923854768
MySQL thread id 5, query id 9853025 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249374646, not started, process no 28858, OS thread id 2924055472
MySQL thread id 4, query id 9777091 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249379087, not started, process no 28858, OS thread id 2924546992
MySQL thread id 2, query id 9782893 kextreme.kolachi.com 127.0.0.1 tsdbuser
---TRANSACTION 0 249446980, ACTIVE 1 sec, process no 28858, OS thread id 2913598384 fetching rows, thread declared inside InnoDB 204
mysql tables in use 4, locked 0
, holds adaptive hash latch
MySQL thread id 4238, query id 9884396 kextreme.kolachi.com 127.0.0.1 tsdbuser Copying to tmp table
SELECT
SUM(F.QUANTITY) QUANTITY,
SUM(F.QUANTITY * F.ACTUALPRICE)/SUM(F.QUANTITY) ACTUALPRICE
FROM
TICKETSGROUPDETAILS TGD,
TICKET T,
SUBMISSION S,
FILL F
WHERE 1 = 1
AND TGD.TIKNUM = F.TIKNUM AND T.TIKNUM = F.TIKNUM AND S.SUBNUM = F.SUBNUM A ND TGD.GROUPNUM
Trx read view will not see trx with id >= 0 249446981, sees < 0 249446981
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
45203800 OS file reads, 124949 OS file writes, 71773 OS fsyncs
558.76 reads/s, 120772 avg bytes/read, 1.13 writes/s, 0.67 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 1, free list len 0, seg size 2,
344 inserts, 344 merged recs, 212 merges
Hash table size 34679, used cells 8514, node heap has 11 buffer(s)
67072.46 hash searches/s, 58434.24 non-hash searches/s
---
LOG
---
Log sequence number 0 1353632632
Log flushed up to 0 1353632632
Last checkpoint at 0 1353631891
0 pending log writes, 0 pending chkp writes
49326 log i/o's done, 0.40 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 68263909; in additional pool allocated 2074880
Buffer pool size 512
Free buffers 0
Database pages 501
Modified db pages 7
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 339985295, created 1382, written 72381
4118.79 reads/s, 0.00 creates/s, 0.73 writes/s
Buffer pool hit rate 983 / 1000
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
Main thread process no. 28858, id 2943638448, state: sleeping
Number of rows inserted 41507, updated 33291, deleted 3468, read 2356647998
0.13 inserts/s, 0.13 updates/s, 0.00 deletes/s, 305248.45 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================