MySQL concurrent insert causing deadlock outside of (explicit) transaction

Question

I am attempting to debug the following scenario: There are 2 concurrent processes, inserting exactly the same row into a table with a unique constraint. This is done outside of an explicit transaction (though I assume InnoDB handles this as a single statement w/ auto commit internally?)

Schema as follows:

CREATE TABLE locks (
    id bigint(20) UNSIGNED NOT NULL AUTO_INCREMENT,
    lock_uid varchar(255) NOT NULL,
    count smallint(6) NOT NULL,
    processor_id varchar(255) DEFAULT NULL,
    created_at timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
    updated_at timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
    PRIMARY KEY (id),
    UNIQUE INDEX locks_lock_uid_unique (lock_uid)
)

As you can see there is unique index on the lock_uid to prevent multiple rows with the same value being in the table.

Commands being run (for context, these are taken from general query log for complete sanity, there are no other statements on either thread outside of a collation command):

Thread 1:

insert into `locks` (`lock_uid`, `count`, `processor_id`, `created_at`, `updated_at`) 
values ('11161567', '0', NULL, '2017-11-07 10:46:36', '2017-11-07 10:46:36')

Thread 2:

insert into `locks` (`lock_uid`, `count`, `processor_id`, `created_at`, `updated_at`) 
values ('11161567', '0', NULL, '2017-11-07 10:46:36', '2017-11-07 10:46:36')

This resulted in the following deadlock:

LATEST DETECTED DEADLOCK
------------------------
2017-11-07 10:46:36 0x2ac88f791700
*** (1) TRANSACTION:
TRANSACTION 6089510736, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 1
MySQL thread id 177584962, OS thread handle 47059008030464, query id 13109086103 ec2-34-232-58-13.compute-1.amazonaws.com 34.232.58.13 appserver update
insert into `locks` (`lock_uid`, `count`, `processor_id`, `created_at`, `updated_at`) values ('11161567', '0', NULL, '2017-11-07 10:46:36', '2017-11-07 10:46:36')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6403 page no 4 n bits 176 index locks_lock_uid_unique of table `core`.`locks` trx id 6089510736 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 107 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
0: len 30; hex 636865636b6f75745265636f7665727950726f636573735f313131363137; asc 111617; (total 32 bytes);
1: len 8; hex 0000000003266637; asc      &f7;;

*** (2) TRANSACTION:
TRANSACTION 6089510734, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 1
MySQL thread id 177584971, OS thread handle 47040888903424, query id 13109086092 ec2-34-237-3-244.compute-1.amazonaws.com 34.237.3.244 appserver update
insert into `locks` (`lock_uid`, `count`, `processor_id`, `created_at`, `updated_at`) values ('11161567', '0', NULL, '2017-11-07 10:46:36', '2017-11-07 10:46:36')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 6403 page no 4 n bits 176 index locks_lock_uid_unique of table `core`.`locks` trx id 6089510734 lock mode S
Record lock, heap no 104 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
0: len 30; hex 636865636b6f75745265636f7665727950726f636573735f313131363135; asc 111615; (total 32 bytes);
1: len 8; hex 0000000003266632; asc      &f2;;

Record lock, heap no 105 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
0: len 30; hex 636865636b6f75745265636f7665727950726f636573735f313131363135; asc 111615; (total 32 bytes);
1: len 8; hex 0000000003266634; asc      &f4;;

Record lock, heap no 107 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
0: len 30; hex 636865636b6f75745265636f7665727950726f636573735f313131363137; asc 111617; (total 32 bytes);
1: len 8; hex 0000000003266637; asc      &f7;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6403 page no 4 n bits 176 index locks_lock_uid_unique of table `core`.`locks` trx id 6089510734 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 107 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
0: len 30; hex 636865636b6f75745265636f7665727950726f636573735f313131363137; asc 111617; (total 32 bytes);
1: len 8; hex 0000000003266637; asc      &f7;;

*** WE ROLL BACK TRANSACTION (2)

I have read similar answers (e.g. MySQL locking in Duplicate Key Error), but I can't quite understand what's happening in this case. The explanation doesn't match the deadlock output.

• Why does this deadlock occur on 2 inserts outside a transaction?
• Why does the T2 already hold S locks, before requesting X, where as the identical T1 does not?

Answer 1

Why does this deadlock occur on 2 inserts outside a transaction?

It still has a transaction https://dev.mysql.com/doc/refman/5.7/en/innodb-autocommit-commit-rollback.html

In InnoDB, all user activity occurs inside a transaction. If autocommit mode is enabled, each SQL statement forms a single transaction on its own

So your single queries can be treated as short-lived transactions

Why does the T2 already hold S locks, before requesting X, where as the identical T1 does not?

It has. This is just how the function printing the latest deadlock information works :-) It would not print the locks held by the first transaction. You can check it yourself by simulating a simple deadlock from 2 parallel mysql sessions. And here’s the code:

https://github.com/mysql/mysql-server/blob/5.7/storage/innobase/lock/lock0lock.cc#L7236

DeadlockChecker::notify(const lock_t* lock) const
{
    ut_ad(lock_mutex_own());

    start_print();

    print("\n*** (1) TRANSACTION:\n");

    print(m_wait_lock->trx, 3000);

    print("*** (1) WAITING FOR THIS LOCK TO BE GRANTED:\n");

    print(m_wait_lock);

    print("*** (2) TRANSACTION:\n");

    print(lock->trx, 3000);

    print("*** (2) HOLDS THE LOCK(S):\n");

    print(lock);

    /* It is possible that the joining transaction was granted its
    lock when we rolled back some other waiting transaction. */

    if (m_start->lock.wait_lock != 0) {
        print("*** (2) WAITING FOR THIS LOCK TO BE GRANTED:\n");

        print(m_start->lock.wait_lock);
    }

    DBUG_PRINT("ib_lock", ("deadlock detected"));
}

The explanation doesn't match the deadlock output

It's fairly close to what appears to be happening in your case. Here’s a simulation:

Preparation:

create table test (id int primary key, val int not null unique) engine=innodb;
insert into test values (1, 1), (2, 2), (3, 3);

Now lets open 3 shells and run the follow command:

1> begin;
2> begin;
3> begin;

and then

1>insert into test values (1, 1);
2>insert into test values (1, 1); (will hang)
3>insert into test values (1, 1); (will hang)

and now

1>rollback
2>would produce: ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
3>would produce: Query OK, 1 row affected

1>show engine innodb status;
...
------------------------
LATEST DETECTED DEADLOCK
------------------------
2017-11-15 23:21:47 0x700000d95000
*** (1) TRANSACTION:
TRANSACTION 2336, ACTIVE 8 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 8, OS thread handle 123145316831232, query id 58 localhost 127.0.0.1 root update
insert into test values (1, 1)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 26 page no 3 n bits 72 index PRIMARY of table `test`.`test` trx id 2336 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;;

*** (2) TRANSACTION:
TRANSACTION 2335, ACTIVE 13 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 5, OS thread handle 123145316552704, query id 57 localhost root update
insert into test values (1, 1)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 26 page no 3 n bits 72 index PRIMARY of table `test`.`test` trx id 2335 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 26 page no 3 n bits 72 index PRIMARY of table `test`.`test` trx id 2335 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 (2)

As you can see it’s close to your outcome