Mysql – Dead Locks between an insert ignore and and an update

deadlockinnodbMySQL

Using MySQL InnoDB.

As far as I know and read so many time dead locks only happens when one transaction is locking resource A and waiting for B and another transaction does the opposite.

So with that logic my conclusion is that an insert ignore (without any select/join or use of another resource) will never create a deadlock…(since it uses only 1 resource), in the worse case a lock wait will be created.

But when I look in the show engine innodb status I can see a deadlock for that kind of transaction.

I am confused now, why did it happen?

Transaction A (2 in status):

INSERT IGNORE INTO indicators.fileso (hostId, sha256, p_runningUser, NTFSOwner, fullPath, 
                                    fileName, s_serviceName, d_driverName, p_commandLineParams,
                                    p_ParentPath ,ar_regPath, ar_regKey, ar_regValue, hostName, extension, p_parentUser,
                                    uniqueness, riskLevel) 
     VALUES ('8662', ...)

Transaction B, (1 in status):

    insert ignore into tableB(..)
    select ... from tableA
    where..
    on duplicate ...


UPDATE indicators.filesi fi
JOIN
(
    SELECT fo.sha256
    FROM indicators.filesoi foi
    JOIN indicators.fileso fo ON foi.uniqueness = fo.uniqueness
    WHERE fo.lastSeen > '2016-03-16 11:10:22'  AND foi.fileType IN (3, 4, 50, 52, 53, 54, 56, 57, 58, 59, 60, 
    61,62,63,64,65,66,67)
) x ON x.sha256=fi.sha256 
SET hasAutorunOccurances=1

Link to the full InnoDB status.

InnoDB Status:

=====================================
2016-03-16 11:17:44 1d70 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 35 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2170553 srv_active, 0 srv_shutdown, 17765 srv_idle
srv_master_thread log flush and writes: 2188289
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 21290331
OS WAIT ARRAY INFO: signal count 182953746
Mutex spin waits 1874358645, rounds 2924569106, OS waits 9765301
RW-shared spins 54053744, rounds 303369969, OS waits 5382871
RW-excl spins 34533419, rounds 461727431, OS waits 5449320
Spin rounds per wait: 1.56 mutex, 5.61 RW-shared, 13.37 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2016-03-16 11:15:24 2580
*** (1) TRANSACTION:
TRANSACTION 2264758566, ACTIVE 1 sec fetching rows
mysql tables in use 3, locked 3
LOCK WAIT 13566 lock struct(s), heap size 1603112, 43921 row lock(s)
MySQL thread id 1319, OS thread handle 0x1c64, query id 260771445 localhost 127.0.0.1 root Sending data
UPDATE indicators.filesi fi
JOIN
(
    SELECT fo.sha256
    FROM indicators.filesoi foi
    JOIN indicators.fileso fo ON foi.uniqueness = fo.uniqueness
    WHERE fo.lastSeen > '2016-03-16 11:10:22'  AND foi.fileType IN (3, 4, 50, 52, 53, 54, 56, 57, 58, 59, 60, 
    61,62,63,64,65,66,67)
) x ON x.sha256=fi.sha256 
SET hasAutorunOccurances=1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 859892 page no 1508578 n bits 888 index `lastSeen` of table `indicators`.`fileso` trx id 2264758566 lock mode S waiting
*** (2) TRANSACTION:
TRANSACTION 2264758569, ACTIVE 1 sec updating or deleting
mysql tables in use 1, locked 1
42 lock struct(s), heap size 6544, 72 row lock(s), undo log entries 39
MySQL thread id 1310, OS thread handle 0x2580, query id 260771450 localhost 127.0.0.1 root update
INSERT IGNORE INTO indicators.fileso (hostId, sha256, p_runningUser, NTFSOwner, fullPath, 
                                    fileName, s_serviceName, d_driverName, p_commandLineParams,
                                    p_ParentPath ,ar_regPath, ar_regKey, ar_regValue, hostName, extension, p_parentUser,
                                    uniqueness, riskLevel) VALUES ('8662',0xB2816FFDF5D612811E9A6CBDCD16C4271A7C16179E410E7C9F8CDE40BB6CC38B,'NT AUTHORITY\\SYSTEM','NT SERVICE\\TrustedInstaller','c:\\windows\\system32\\conhost.exe','conhost.exe','','','"-6004143636298202223525083761531271068-1940101893-8600483621900200321-29408863','c:\\windows\\system32\\csrss.exe','',
                                    '','','DAVIDMI','exe','NT AUTHORITY\\SYSTEM',0x1fdecd56f60185cf77581b1841d6ffe7ebdd100de05471c55aa01b238d40ac34,'-45'),('9143',0xB2816FFDF5D612811E9A6CBDCD16C4271A7C16179E410E7C9F8CDE40BB6CC38B,'NT AUTHOR
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 859892 page no 1508578 n bits 888 index `lastSeen` of table `indicators`.`fileso` trx id 2264758569 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 859892 page no 1508578 n bits 904 index `lastSeen` of table `indicators`.`fileso` trx id 2264758569 lock_mode X locks gap before rec insert intention waiting
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 2264766654
Purge done for trx's n:o < 2264766653 undo n:o < 0 state: running but idle
History list length 377
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 2264766634, not started
MySQL thread id 1341, OS thread handle 0x1180, query id 260784535 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766605, not started
MySQL thread id 1331, OS thread handle 0x1d70, query id 260784485 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766617, not started
MySQL thread id 1320, OS thread handle 0x1d70, query id 260784506 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766584, not started
MySQL thread id 1343, OS thread handle 0x2058, query id 260784450 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766625, not started
MySQL thread id 1333, OS thread handle 0x1d70, query id 260784520 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766637, not started
MySQL thread id 1330, OS thread handle 0x1180, query id 260784541 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766612, not started
MySQL thread id 1344, OS thread handle 0x1d70, query id 260784497 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766627, not started
MySQL thread id 1332, OS thread handle 0x2058, query id 260784524 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766588, not started
MySQL thread id 1337, OS thread handle 0x1d70, query id 260784458 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766651, not started
MySQL thread id 1345, OS thread handle 0x28dc, query id 260784569 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766619, not started
MySQL thread id 1323, OS thread handle 0x1d70, query id 260784508 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766649, not started
MySQL thread id 1340, OS thread handle 0x1d70, query id 260784565 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766636, not started
MySQL thread id 1312, OS thread handle 0x1180, query id 260784539 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766621, not started
MySQL thread id 1326, OS thread handle 0x2058, query id 260784513 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766586, not started
MySQL thread id 1346, OS thread handle 0x1d70, query id 260784454 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766592, not started
MySQL thread id 1339, OS thread handle 0x1d70, query id 260784464 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766603, not started
MySQL thread id 1342, OS thread handle 0x1d70, query id 260784482 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766610, not started
MySQL thread id 1325, OS thread handle 0x1d70, query id 260784493 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766596, not started
MySQL thread id 1329, OS thread handle 0x1d70, query id 260784470 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766615, not started
MySQL thread id 1319, OS thread handle 0x1d70, query id 260784504 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766597, not started
MySQL thread id 1315, OS thread handle 0x1d70, query id 260784472 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766606, not started
MySQL thread id 1334, OS thread handle 0x1d70, query id 260784487 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766626, not started
MySQL thread id 1322, OS thread handle 0x1d70, query id 260784523 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766624, not started
MySQL thread id 1321, OS thread handle 0x2058, query id 260784519 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766635, not started
MySQL thread id 1336, OS thread handle 0x1180, query id 260784537 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766644, not started
MySQL thread id 1335, OS thread handle 0x1d70, query id 260784555 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766645, not started
MySQL thread id 1313, OS thread handle 0x1d70, query id 260784557 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766650, not started
MySQL thread id 1324, OS thread handle 0x28dc, query id 260784567 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766648, not started
MySQL thread id 1314, OS thread handle 0x1d70, query id 260784563 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766602, not started
MySQL thread id 1327, OS thread handle 0x1d70, query id 260784480 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766589, not started
MySQL thread id 1316, OS thread handle 0x1d70, query id 260784460 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766639, not started
MySQL thread id 1317, OS thread handle 0x1d70, query id 260784545 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766608, not started
MySQL thread id 1318, OS thread handle 0x1d70, query id 260784491 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766587, not started
MySQL thread id 1328, OS thread handle 0x1d70, query id 260784456 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766638, not started
MySQL thread id 1311, OS thread handle 0x1d70, query id 260784543 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766613, not started
MySQL thread id 1310, OS thread handle 0x1d70, query id 260784499 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766632, not started
MySQL thread id 1309, OS thread handle 0x1180, query id 260784533 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766629, not started
MySQL thread id 1308, OS thread handle 0x2058, query id 260784529 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766583, not started
MySQL thread id 1307, OS thread handle 0x1d70, query id 260784449 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766585, not started
MySQL thread id 1305, OS thread handle 0x1d70, query id 260784452 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766600, not started
MySQL thread id 1306, OS thread handle 0x1d70, query id 260784476 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766590, not started
MySQL thread id 1304, OS thread handle 0x1d70, query id 260784462 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766630, not started
MySQL thread id 1303, OS thread handle 0x1d70, query id 260784530 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766614, not started
MySQL thread id 1302, OS thread handle 0x2058, query id 260784503 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766593, not started
MySQL thread id 1301, OS thread handle 0x1d70, query id 260784466 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766642, not started
MySQL thread id 1300, OS thread handle 0x1d70, query id 260784551 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766628, not started
MySQL thread id 1299, OS thread handle 0x28dc, query id 260784526 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766643, not started
MySQL thread id 1298, OS thread handle 0x1180, query id 260784554 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766640, not started
MySQL thread id 1296, OS thread handle 0x1d70, query id 260784547 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766641, not started
MySQL thread id 1297, OS thread handle 0x1180, query id 260784550 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766623, not started
MySQL thread id 1294, OS thread handle 0x1d70, query id 260784516 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766578, not started
MySQL thread id 1295, OS thread handle 0x28dc, query id 260784438 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766611, not started
MySQL thread id 1293, OS thread handle 0x1d70, query id 260784495 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766599, not started
MySQL thread id 1292, OS thread handle 0x1d70, query id 260784474 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766595, not started
MySQL thread id 1290, OS thread handle 0x1d70, query id 260784468 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766647, not started
MySQL thread id 1291, OS thread handle 0x1d70, query id 260784561 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766620, not started
MySQL thread id 1289, OS thread handle 0x1d70, query id 260784514 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766601, not started
MySQL thread id 1288, OS thread handle 0x1d70, query id 260784478 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766646, not started
MySQL thread id 1287, OS thread handle 0x1d70, query id 260784559 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766607, not started
MySQL thread id 1286, OS thread handle 0x1d70, query id 260784489 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2260497764, not started
MySQL thread id 857, OS thread handle 0x1d70, query id 260784572 localhost 127.0.0.1 root init
show engine innodb status
---TRANSACTION 2264542263, not started
MySQL thread id 849, OS thread handle 0x2058, query id 260784527 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766653, ACTIVE 0 sec fetching rows
mysql tables in use 2, locked 2
574 lock struct(s), heap size 63016, 10049 row lock(s)
MySQL thread id 1338, OS thread handle 0x28dc, query id 260784571 localhost 127.0.0.1 root Copying to tmp table
INSERT IGNORE INTO temp.userfilesntfscount(userId,sha256)
SELECT fileso.NTFSOwnerId, sha256 from indicators.fileso 
WHERE fileso.lastSeen > '2016-03-16 11:12:43' AND fileso.NTFSOwnerId !=-1
GROUP BY fileso.NTFSOwnerId, fileso.sha256
ON DUPLICATE KEY UPDATE lastSeen=NOW()
TABLE LOCK table `indicators`.`fileso` trx id 2264766653 lock mode IS
RECORD LOCKS space id 859892 page no 582502 n bits 624 index `lastSeen` of table `indicators`.`fileso` trx id 2264766653 lock mode S
RECORD LOCKS space id 859892 page no 313592 n bits 128 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 824730 n bits 112 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 2023283 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 309994 n bits 128 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 626989 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 1300995 n bits 112 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 28586 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 28587 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
--------
FILE I/O
--------
I/O thread 0 state: native aio handle (insert buffer thread)
I/O thread 1 state: native aio handle (log thread)
I/O thread 2 state: native aio handle (read thread)
I/O thread 3 state: native aio handle (read thread)
I/O thread 4 state: native aio handle (read thread)
I/O thread 5 state: native aio handle (read thread)
I/O thread 6 state: native aio handle (write thread)
I/O thread 7 state: native aio handle (write thread)
I/O thread 8 state: native aio handle (write thread)
I/O thread 9 state: native aio handle (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
164849987 OS file reads, 207918640 OS file writes, 17611131 OS fsyncs
21.63 reads/s, 16384 avg bytes/read, 124.23 writes/s, 7.11 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 222879, seg size 222881, 2675373 merges
merged operations:
 insert 6806735, delete mark 18516923, delete 1583485
discarded operations:
 insert 0, delete mark 0, delete 0
1035.14 hash searches/s, 1270.22 non-hash searches/s
---
LOG
---
Log sequence number 54411565930479
Log flushed up to   54411565929791
Pages flushed up to 54410707374233
Last checkpoint at  54410699443626
Max checkpoint age    1738750649
Checkpoint age target 1684414692
Modified age          858556246
Checkpoint age        866486853
0 pending log writes, 0 pending chkp writes
55137584 log i/o's done, 22.91 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 6975520768; in additional pool allocated 0
Total memory allocated by read views 29503648
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 428088160   (107907832 + 8910114920)
    Page hash           843928 (buffer pool 0 only)
    Dictionary cache    56425856    (53955152 + 2470704)
    File system         1010632     (812272 + 198360)
    Lock system         18854864    (18769528 + 85336)
    Recovery system     0   (0 + 0)
Dictionary memory allocated 2470704
Buffer pool size        415992
Buffer pool size, bytes 6815612928
Free buffers            8189
Database pages          388258
Old database pages      143158
Modified db pages       61982
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 69871034, not young 3752309224
8.46 youngs/s, 112.48 non-youngs/s
Pages read 164825103, created 26955781, written 145327867
21.63 reads/s, 1.89 creates/s, 98.85 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 388258, unzip_LRU len: 0
I/O sum[49040]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size        51999
Buffer pool size, bytes 851951616
Free buffers            1023
Database pages          48519
Old database pages      17890
Modified db pages       8060
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 9277012, not young 500813660
1.31 youngs/s, 13.74 non-youngs/s
Pages read 21279774, created 3503837, written 19235016
3.54 reads/s, 0.11 creates/s, 13.09 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 48519, unzip_LRU len: 0
I/O sum[6130]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size        51999
Buffer pool size, bytes 851951616
Free buffers            1023
Database pages          48569
Old database pages      17908
Modified db pages       7773
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8709956, not young 433177443
1.09 youngs/s, 8.66 non-youngs/s
Pages read 20990262, created 3365756, written 18419504
2.43 reads/s, 0.23 creates/s, 12.77 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 48569, unzip_LRU len: 0
I/O sum[6130]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2

-- several rows removed to keep the 30K characters SO limit.

---BUFFER POOL 7
Buffer pool size        51999
Buffer pool size, bytes 851951616
Free buffers            1023
Database pages          48503
Old database pages      17884
Modified db pages       7640
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8699911, not young 454128206
0.86 youngs/s, 12.57 non-youngs/s
Pages read 20737336, created 3357602, written 17298796
3.03 reads/s, 0.14 creates/s, 13.86 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 48503, unzip_LRU len: 0
I/O sum[6130]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
1 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
1 out of 1000 descriptors used
Main thread id 1656, state: sleeping
Number of rows inserted 694391636, updated 4609654205, deleted 333821819, read 352837957564
79.91 inserts/s, 73.77 updates/s, 2.57 deletes/s, 88348.96 reads/s
------------------------
LATEST DETECTED DEADLOCK
------------------------
2016-03-16 11:15:24 2580
*** (1) TRANSACTION:
TRANSACTION 2264758566, ACTIVE 1 sec fetching rows
mysql tables in use 3, locked 3
LOCK WAIT 13566 lock struct(s), heap size 1603112, 43921 row lock(s)
MySQL thread id 1319, OS thread handle 0x1c64, query id 260771445 localhost 127.0.0.1 root Sending data
UPDATE indicators.filesi fi
JOIN
(
    SELECT fo.sha256
    FROM indicators.filesoi foi
    JOIN indicators.fileso fo ON foi.uniqueness = fo.uniqueness
    WHERE fo.lastSeen > '2016-03-16 11:10:22'  AND foi.fileType IN (3, 4, 50, 52, 53, 54, 56, 57, 58, 59, 60, 
    61,62,63,64,65,66,67)
) x ON x.sha256=fi.sha256 
SET hasAutorunOccurances=1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 859892 page no 1508578 n bits 888 index `lastSeen` of table `indicators`.`fileso` trx id 2264758566 lock mode S waiting
*** (2) TRANSACTION:
TRANSACTION 2264758569, ACTIVE 1 sec updating or deleting
mysql tables in use 1, locked 1
42 lock struct(s), heap size 6544, 72 row lock(s), undo log entries 39
MySQL thread id 1310, OS thread handle 0x2580, query id 260771450 localhost 127.0.0.1 root update
INSERT IGNORE INTO indicators.fileso (hostId, sha256, p_runningUser, NTFSOwner, fullPath, 
                                    fileName, s_serviceName, d_driverName, p_commandLineParams,
                                    p_ParentPath ,ar_regPath, ar_regKey, ar_regValue, hostName, extension, p_parentUser,
                                    uniqueness, riskLevel) VALUES ('8662',0xB2816FFDF5D612811E9A6CBDCD16C4271A7C16179E410E7C9F8CDE40BB6CC38B,'NT AUTHORITY\\SYSTEM','NT SERVICE\\TrustedInstaller','c:\\windows\\system32\\conhost.exe','conhost.exe','','','"-6004143636298202223525083761531271068-1940101893-8600483621900200321-29408863','c:\\windows\\system32\\csrss.exe','',
                                    '','','DAVIDMI','exe','NT AUTHORITY\\SYSTEM',0x1fdecd56f60185cf77581b1841d6ffe7ebdd100de05471c55aa01b238d40ac34,'-45'),('9143',0xB2816FFDF5D612811E9A6CBDCD16C4271A7C16179E410E7C9F8CDE40BB6CC38B,'NT AUTHOR
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 859892 page no 1508578 n bits 888 index `lastSeen` of table `indicators`.`fileso` trx id 2264758569 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 859892 page no 1508578 n bits 904 index `lastSeen` of table `indicators`.`fileso` trx id 2264758569 lock_mode X locks gap before rec insert intention waiting
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 2264766654
Purge done for trx's n:o < 2264766653 undo n:o < 0 state: running but idle
History list length 377
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 2264766634, not started
MySQL thread id 1341, OS thread handle 0x1180, query id 260784535 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766605, not started
MySQL thread id 1331, OS thread handle 0x1d70, query id 260784485 localhost 127.0.0.1 root cleaning up

-- several rows removed to keep the 30K characters SO limit.

---TRANSACTION 2260497764, not started
MySQL thread id 857, OS thread handle 0x1d70, query id 260784572 localhost 127.0.0.1 root init
show engine innodb status
---TRANSACTION 2264542263, not started
MySQL thread id 849, OS thread handle 0x2058, query id 260784527 localhost 127.0.0.1 root cleaning up
---TRANSACTION 2264766653, ACTIVE 0 sec fetching rows
mysql tables in use 2, locked 2
576 lock struct(s), heap size 63016, 10209 row lock(s)
MySQL thread id 1338, OS thread handle 0x28dc, query id 260784571 localhost 127.0.0.1 root Copying to tmp table
INSERT IGNORE INTO temp.userfilesntfscount(userId,sha256)
SELECT fileso.NTFSOwnerId, sha256 from indicators.fileso 
WHERE fileso.lastSeen > '2016-03-16 11:12:43' AND fileso.NTFSOwnerId !=-1
GROUP BY fileso.NTFSOwnerId, fileso.sha256
ON DUPLICATE KEY UPDATE lastSeen=NOW()
TABLE LOCK table `indicators`.`fileso` trx id 2264766653 lock mode IS
RECORD LOCKS space id 859892 page no 582502 n bits 624 index `lastSeen` of table `indicators`.`fileso` trx id 2264766653 lock mode S
RECORD LOCKS space id 859892 page no 313592 n bits 128 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 824730 n bits 112 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 2023283 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 309994 n bits 128 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 626989 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 1300995 n bits 112 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 28586 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
RECORD LOCKS space id 859892 page no 28587 n bits 120 index `PRIMARY` of table `indicators`.`fileso` trx id 2264766653 lock mode S locks rec but not gap
TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Best Answer

I think that the problem must be searched is into the insert ignore statements. It is multiinsert, and I presume it has the same effect of executing the rolling out statements in sequence. It is a single statements but it is the same of executing multiple statements. So the locks will be acquired step by step. Furthermore the clause on duplicate key update has the effect to acquire more locks when it is fired.

Let me try to explain it. I guess what happened from the show engine innodb status. We have two transactions T1 and T2, I have extracted the last statements of each transactions from the log. For clarity, I have truncated the queries and added the missing part from the comments.

T1:

UPDATE indicators.filesi fi
JOIN(
    SELECT fo.sha256
    FROM indicators.filesoi foi
    JOIN indicators.fileso fo ON foi.uniqueness = fo.uniqueness
    WHERE fo.lastSeen > '2016-03-16 11:10:22'  ...
) x ON x.sha256=fi.sha256

T2:

INSERT IGNORE INTO indicators.fileso (hostId, ...) 
VALUES                                  
('8662', ...),                          
('9143', ...),
on duplicate key update ....

From the log, I supposed the lock are acquired in the following sequence.

Time 1

T2 starts to execute and acquire a lock on single index record in exclusive mode, but it don't acquire the gap between indexes record. Maybe the on duplicate key was fired.

RECORD LOCKS space id 859892 page no 1508578 n bits 888 
index `lastSeen` of table `indicators`.`fileso` trx id 2264758569 
lock_mode X locks rec but not gap

Time 2

T1 starts and it stops trying to acquire a shared lock on the same records of T2. Maybe at the end of the index because the condition contains lastSeen > ...

RECORD LOCKS space id 859892 page no 1508578 n bits 888 
index `lastSeen` of table `indicators`.`fileso` trx id 2264758566 
lock mode S waiting

Time 3

T2 tries to acquire another lock, but it finds T1 waiting for a shared lock on the same page.

RECORD LOCKS space id 859892 page no 1508578 n bits 904 
index `lastSeen` of table `indicators`.`fileso` trx id 2264758569 
lock_mode X locks gap before rec insert intention waiting

Deadlock is detects.

I have tried to replicate the behavior. I don't know if I have got it right.

CREATE TABLE t (
  `i1` int(11) NOT NULL,
  `i2` int(11) DEFAULT NULL,
  PRIMARY KEY (`i1`)
) ENGINE=InnoDB;

insert into t values(10,10), (20,20), (30,30), (40, 40), (50,50),(60,60);

let starts session 2. We try to simulate T2 (insert ignore)

session2> begin;
Query OK, 0 rows affected (0.00 sec)
session2> update t set i2=60 where i1=60;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0

switch to the session 1, try to simulate T1

session1> begin;
Query OK, 0 rows affected (0.00 sec)

session1> select * from t where i1 >= 50 lock in share mode;
<session1 blocked>

in the session2 we try to acquire a gap lock:

session2> insert t values(55,55);
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

There is the output of show engine innodb status:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2016-03-17 18:38:51 0x700000e61000
*** (1) TRANSACTION:
TRANSACTION 281479505194560, ACTIVE 178 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 2, OS thread handle 123145316274176, query id 1644 localhost msandbox Sending data
select * from t where i1 >= 50 lock in share mode
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 38 page no 3 n bits 80 index PRIMARY of table `test_dbaexchange`.`t` trx id 281479505194560 lock mode S waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 8000003c; asc    <;;
 1: len 6; hex 000000001008; asc       ;;
 2: len 7; hex 2f00000147048c; asc /   G  ;;
 3: len 4; hex 8000003c; asc    <;;

*** (2) TRANSACTION:
TRANSACTION 4104, ACTIVE 303 sec inserting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 7, OS thread handle 123145317388288, query id 1645 localhost msandbox update
insert t values(55,55)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 38 page no 3 n bits 80 index PRIMARY of table `test_dbaexchange`.`t` trx id 4104 lock_mode X locks rec but not gap
Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 8000003c; asc    <;;
 1: len 6; hex 000000001008; asc       ;;
 2: len 7; hex 2f00000147048c; asc /   G  ;;
 3: len 4; hex 8000003c; asc    <;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 38 page no 3 n bits 80 index PRIMARY of table `test_dbaexchange`.`t` trx id 4104 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 8000003c; asc    <;;
 1: len 6; hex 000000001008; asc       ;;
 2: len 7; hex 2f00000147048c; asc /   G  ;;
 3: len 4; hex 8000003c; asc    <;;

*** WE ROLL BACK TRANSACTION (2)

You can note that:

  • T1 is waiting for a shared lock on table t
  • T2 has an exclusive lock on table t without gap
  • T2 has tried to acquire a lock with gap on table t

Hope this help!

Related Question