Why does that query cause lock wait timeouts?

From time to time, I find a lot of these errors in my PHP error log:

MYSQL.1213: Deadlock found when trying to get lock; try restarting transactionSQL

The problem persists for about 2 or 3 minutes. Thanks to stackoverflow, the reason was quite easy to find:

``
------------------------
LATEST DETECTED DEADLOCK
------------------------
130320 15:53:37
*** (1) TRANSACTION:
TRANSACTION 0 83395751, ACTIVE 35 sec, process no 26405, OS thread id 140507872417536 starting index read
mysql tables in use 3, locked 3
LOCK WAIT 3 lock struct(s), heap size 1216, 2 row lock(s)
MySQL thread id 1163191, query id 199629038 localhost sosci Updating
UPDATE database.table SET invalidate='2013-03-21 03:53:02' WHERE ((token='C7G8X3HABCDEFGH') AND (invalidate IS NULL)) AND (project=26118) LIMIT 1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 65548 n bits 192 index PRIMARY of table database.table trx id 0 83395751 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 4; hex 000c2591; asc % ;; 1: len 6; hex 000004e36ace; asc j ;; 2: len 7; hex 8000000a830110; asc ;; 3: len 4; hex 80000001; asc ;; 4: len 4; hex 80006606; asc f ;; 5: len 1; hex 07; asc ;; 6: len 16; hex 32455637363853485447444734584252; asc 2EV768SHTGDG4XBR;; 7: SQL NULL; 8: len 30; hex 3935363436362c656e672c616e6e612e63616d706f7265736940676d6169; asc 956466,eng,anna.camporesi@gmai;...(truncated); 9: SQL NULL; 10: len 8; hex 8000124ef477640e; asc N wd ;; 11: len 8; hex 8000124ef495e88e; asc N ;;

*** (2) TRANSACTION:
TRANSACTION 0 83395676, ACTIVE 37 sec, process no 26405, OS thread id 140507856160512 fetching rows, thread declared inside InnoDB 451
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1216, 53 row lock(s), undo log entries 1
MySQL thread id 1163198, query id 199628885 localhost sosci updating
DELETE FROM database.table` WHERE ((action="limit"

First Transaction

------------------------
LATEST DETECTED DEADLOCK
------------------------
130320 15:53:37
*** (1) TRANSACTION:
TRANSACTION 0 83395751, ACTIVE 35 sec, process no 26405, OS thread id 140507872417536 starting index read
mysql tables in use 3, locked 3
LOCK WAIT 3 lock struct(s), heap size 1216, 2 row lock(s)
MySQL thread id 1163191, query id 199629038 localhost sosci Updating
UPDATE `database`.`table` SET `invalidate`='2013-03-21 03:53:02' WHERE ((token='C7G8X3HABCDEFGH') AND (invalidate IS NULL)) AND (project=26118) LIMIT 1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 65548 n bits 192 index `PRIMARY` of table `database`.`table` trx id 0 83395751 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
 0: len 4; hex 000c2591; asc   % ;; 1: len 6; hex 000004e36ace; asc     j ;; 2: len 7; hex 8000000a830110; asc        ;; 3: len 4; hex 80000001; asc     ;; 4: len 4; hex 80006606; asc   f ;; 5: len 1; hex 07; asc  ;; 6: len 16; hex 32455637363853485447444734584252; asc 2EV768SHTGDG4XBR;; 7: SQL NULL; 8: len 30; hex 3935363436362c656e672c616e6e612e63616d706f7265736940676d6169; asc 956466,eng,anna.camporesi@gmai;...(truncated); 9: SQL NULL; 10: len 8; hex 8000124ef477640e; asc    N wd ;; 11: len 8; hex 8000124ef495e88e; asc    N    ;;

Second Transaction

*** (2) TRANSACTION:
TRANSACTION 0 83395676, ACTIVE 37 sec, process no 26405, OS thread id 140507856160512 fetching rows, thread declared inside InnoDB 451
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1216, 53 row lock(s), undo log entries 1
MySQL thread id 1163198, query id 199628885 localhost sosci updating
DELETE FROM `database`.`table` WHERE ((action="limit") AND (info='login') AND (creation < DATE_SUB(NOW(), INTERVAL 10 MINUTE)))
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 65548 n bits 192 index `PRIMARY` of table `database`.`table` trx id 0 83395676 lock_mode X
Record lock, heap no 4 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
 0: len 4; hex 000c2591; asc   % ;; 1: len 6; hex 000004e36ace; asc     j ;; 2: len 7; hex 8000000a830110; asc        ;; 3: len 4; hex 80000001; asc     ;; 4: len 4; hex 80006606; asc   f ;; 5: len 1; hex 07; asc  ;; 6: len 16; hex 32455637363853485447444734584252; asc 2EV768SHTGDG4XBR;; 7: SQL NULL; 8: len 30; hex 3935363436362c656e672c616e6e612e63616d706f7265736940676d6169; asc 956466,eng,anna.camporesi@gmai;...(truncated); 9: SQL NULL; 10: len 8; hex 8000124ef477640e; asc    N wd ;; 11: len 8; hex 8000124ef495e88e; asc    N    ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 65548 n bits 192 index `PRIMARY` of table `database`.`table` trx id 0 83395676 lock_mode X waiting
Record lock, heap no 117 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
 0: len 4; hex 000c31d2; asc   1 ;; 1: len 6; hex 000004f884fc; asc       ;; 2: len 7; hex 80000011040110; asc        ;; 3: len 4; hex 80000001; asc     ;; 4: SQL NULL; 5: len 1; hex 06; asc  ;; 6: SQL NULL; 7: len 15; hex 3133322e3139392e3132312e313632; asc 132.199.121.162;; 8: len 5; hex 6c6f67696e; asc login;; 9: len 1; hex 81; asc  ;; 10: len 8; hex 8000124ef49502aa; asc    N    ;; 11: SQL NULL;

*** WE ROLL BACK TRANSACTION (1)

What Do They Have in Common ?

Each transaction is trying to get an exclusive lock on the the same part of the PRIMARY KEY : page no 65548 n bits 192

RECORD LOCKS space id 0 page no 65548 n bits 192 index `PRIMARY` of table `database`.`table` trx id 0 83395751 lock_mode X locks rec but not gap waiting
RECORD LOCKS space id 0 page no 65548 n bits 192 index `PRIMARY` of table `database`.`table` trx id 0 83395676 lock_mode X

Thus, somebody had to rollback. The result: Transaction #1 rolled back.

The query from Transaction #2 got to execute

DELETE FROM `database`.`table` WHERE ((action="limit") AND (info='login') AND (creation < DATE_SUB(NOW(), INTERVAL 10 MINUTE)))

Read your error log. Somewhere in it should be the rollback message and that transaction #1 was restarted.

You just asked


Why did this "situation" block the access to the table (or at least to some entries) for more than one minute? And why are the two transactions (dead-)locking each other - instead of running one after the other?

Look at the Locks Again. Each transaction is locking the PRIMARY KEY. The PRIMARY KEY lives in the Clustered Index (See my post Best of MyISAM and InnoDB for a description of the Clustered Index). Certain keys live together on the same space, page, and bit. Now look at the queries:

Transaction #1

UPDATE `database`.`table` SET `invalidate`='2013-03-21 03:53:02' WHERE ((token='C7G8X3HABCDEFGH') AND (invalidate IS NULL)) AND (project=26118) LIMIT 1

Transaction #2

DELETE FROM `database`.`table` WHERE ((action="limit") AND (info='login') AND (creation < DATE_SUB(NOW(), INTERVAL 10 MINUTE)))

It just so happens that th

StackExchange Database Administrators Q#37187, answer score: 9