What does this deadlock report from MySQL mean?

Question

Here is the output:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2015-12-23 05:57:47 7f23d73c6700
*** (1) TRANSACTION:
TRANSACTION 32990178, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1184, 2 row lock(s)
MySQL thread id 314344, OS thread handle 0x7f23d6480700, query id 99645000 104.197.97.45 dsprod update
insert into pings (lastProcessTime, id, type) values (1450845, '52c7e28eebb26a86fb1505b5', 'INCIDENT')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 17 page no 4 n bits 376 index `PRIMARY` of table `alerts`.`pings` trx id 32990178 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 24; hex 353363336635646430636632336133633062623934613866; asc 53c3f5dd0cf23a3c0bb94a8f;;
 1: len 3; hex 415050; asc APP;;
 2: len 6; hex 000001f76076; asc     `v;;
 3: len 7; hex 5a000001e10b80; asc Z      ;;
 4: len 4; hex d67a36f8; asc  z6 ;;

*** (2) TRANSACTION:
TRANSACTION 32990184, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1184, 2 row lock(s)
MySQL thread id 314341, OS thread handle 0x7f23d73c6700, query id 99645014 104.197.97.45 dsprod update
insert into pings (lastProcessTime, id, type) values (1450848, '52c7e28eebb26a86fb1505b5', 'INCIDENT')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 17 page no 4 n bits 376 index `PRIMARY` of table `alerts`.`pings` trx id 32990184 lock_mode X locks gap before rec
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 24; hex 353363336635646430636632336133633062623934613866; asc 53c3f5dd0cf23a3c0bb94a8f;;
 1: len 3; hex 415050; asc APP;;
 2: len 6; hex 000001f76076; asc     `v;;
 3: len 7; hex 5a000001e10b80; asc Z      ;;
 4: len 4; hex d67a36f8; asc  z6 ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 17 page no 4 n bits 376 index `PRIMARY` of table `alerts`.`pings` trx id 32990184 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 24; hex 353363336635646430636632336133633062623934613866; asc 53c3f5dd0cf23a3c0bb94a8f;;
 1: len 3; hex 415050; asc APP;;
 2: len 6; hex 000001f76076; asc     `v;;
 3: len 7; hex 5a000001e10b80; asc Z      ;;
 4: len 4; hex d67a36f8; asc  z6 ;;

*** WE ROLL BACK TRANSACTION (2)

And here is the code that produces this:

@Autowired
private PingRepository repository;

@Transactional
public void processPing(Ping ping)
{
    Ping storedPing = repository.findById(ping.id);

    if (storedPing == null)
    {
        repository.save(ping);
    } else
    {
        if (ping.lastProcessTime > storedPing.lastProcessTime)
        {
            storedPing.setLastProcessTime(ping.lastProcessTime);
        }
    }
}

public interface PingRepository extends CrudRepository<Ping, PingKey>
{
    @Lock(LockModeType.PESSIMISTIC_WRITE)
    Ping findById(PingKey id);
}

Some questions:

1. What exactly is going on in the deadlock report?
2. it feels like txn 2 is trying to acquire a lock it already has. why?
3. this is the only txn in my code that accesses the pings table. why does this code deadlock at all?

Update:

Adding table schema:

CREATE TABLE `pings` (
  `id` varchar(255) NOT NULL,
  `type` varchar(20) NOT NULL DEFAULT '',
  `lastProcessTime` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`,`type`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

Answer 1

You didn't specify what language your code was in, but it appears that the PESSIMISTIC_WRITE is causing a FOR UPDATE type of select.

As such, the following is happening:

Transaction A

SELECT * FROM pings where id = '52c7e28eebb26a86fb1505b5' FOR UPDATE;

Transaction B

SELECT * FROM pings where id = '52c7e28eebb26a86fb1505b5' FOR UPDATE;

At this point, both transactions are holding a lock on the space you want to insert into.

Transaction A (continuing)

insert into pings (lastProcessTime, id, type) values (1450845, '52c7e28eebb26a86fb1505b5', 'INCIDENT')

Transaction A at this point will wait, as it wants B to release its lock before it continues.

Transaction B (continuing)

insert into pings (lastProcessTime, id, type) values (1450848, '52c7e28eebb26a86fb1505b5', 'INCIDENT')

However, B not only didn't release its lock, but it wants to insert the same record. The database says no way, and forces one (B, in this case) to deadlock and be undone.

This is actually extremely easy to replicate yourself. Just start 2 transactions (I used two Terminal windows to connect to my MySQL instance), one for each transaction, A and B. Start each with START TRANSACTION, and then just enter the commands in the same order as above, in each respective window. Any table with any primary key will work, just adjust the statements to each try to insert the same row.

Once you submit the second insert, you'll see the deadlock (generally applied to the transaction that tried to insert second.)

So, your issue is fully expected, as the FOR UPDATE on the SELECT statement is doing exactly what it is intended to do (which is to keep other transactions from changing the result of the SELECT until the transaction ends.)

Edit: Well, fully expected except for the fact that one would expect the SELECT ... FOR UPDATE to wait, regardless of whether there are any rows returned for the SELECT. However, if there are no rows, the behavior is as described above, but if there are rows returned, Transaction B will wait before returning any results from its SELECT. See this the bug report on this issue.

I would suggest changing your code to check for a duplicate key after inserting (either catching the exception or using ON DUPLICATE KEY ...), rather than trying to do a SELECT ... FOR UPDATE and then an insert.