At Percona Managed Services, sometimes clients’ applications face deadlock situations and need all historic deadlock information for application tuning.
We could get the LATEST DETECTED DEADLOCK from SHOW ENGINE INNODB STATUSG:
1 2 3 4 5 6 7 8 9 10 | …. ------------------------ LATEST DETECTED DEADLOCK ------------------------ *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78507 lock_mode X waiting *** (2) TRANSACTION: TRANSACTION 78508, ACTIVE 155 sec starting index read mysql tables in use 1, locked 1 …. |
But how could we view all past deadlock information?
We could enable innodb_print_all_deadlocks, and all deadlocks in InnoDB user transactions will be recorded in the MySQL error log.
Let‘s start the test.
Create the test database and insert some test data
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 | mysql> create database deadlock_test; Query OK, 1 row affected (0.01 sec) mysql> use deadlock_test; Database changed mysql> --===================== CREATE TABLE t (i INT, c1 varchar(20)) ENGINE = InnoDB; INSERT INTO t (i,c1) VALUES(1,'test1'); INSERT INTO t (i,c1) VALUES(2,'test2'); mysql> select * from t; +------+-------+ | i | c1 | +------+-------+ | 1 | test1 | | 2 | test2 | +------+-------+ |
Deadlock simulation on record 1 of table t (i=1)
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 | -- session 1 : mysql> START TRANSACTION; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM t WHERE i = 1 LOCK IN SHARE MODE; --session 2 : mysql> START TRANSACTION; Query OK, 0 rows affected (0.00 sec) mysql> DELETE FROM t WHERE i = 1; # This statement will wait here We go back to session 1 and run -- session 1 : mysql> DELETE FROM t WHERE i = 1; Query OK, 1 row affected (0.00 sec) , Then on session 2 , we would get -- on session 2, you will find ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction mysql> And SHOW ENGINE INNODB STATUS would show ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2022-10-26 09:45:37 0x7fb09c1ed700 *** (1) TRANSACTION: TRANSACTION 78507, ACTIVE 84 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 2 row lock(s) MySQL thread id 23, OS thread handle 140396446037760, query id 1398 localhost root updating DELETE FROM t WHERE i = 1 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78507 lock_mode X waiting *** (2) TRANSACTION: TRANSACTION 78508, ACTIVE 155 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 4 row lock(s) MySQL thread id 22, OS thread handle 140396510238464, query id 1399 localhost root updating <strong>DELETE FROM t WHERE i = 1</strong> *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78508 lock mode S *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78508 lock_mode X waiting *** WE ROLL BACK TRANSACTION (1) |
This is expected.
Enable innodb_print_all_deadlocks dynamic parameter
1 2 3 4 5 6 7 8 9 | mysql> select @@innodb_print_all_deadlocks; +------------------------------+ | @@innodb_print_all_deadlocks | +------------------------------+ | 0 | +------------------------------+ 1 row in set (0.00 sec) mysql> set global innodb_print_all_deadlocks=1; |
If we run the deadlock simulation on record 1 of table t ( i=1), we‘ll get the deadlock error both in show engine InnoDB status G and MySQL error log.
The deadlock information in MySQL error log is similar to show engine InnoDB status G, like below:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 | tail -f /var/log/mysqld.log 2022-10-26T13:50:36.678728Z 22 [Note] InnoDB: Transactions deadlock detected, dumping detailed information. 2022-10-26T13:50:36.678760Z 22 [Note] InnoDB: *** (1) TRANSACTION: TRANSACTION 78510, ACTIVE 18 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 23, OS thread handle 140396446037760, query id 1409 localhost root updating DELETE FROM t WHERE i = 1 2022-10-26T13:50:36.678785Z 22 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78510 lock_mode X waiting 2022-10-26T13:50:36.678958Z 22 [Note] InnoDB: *** (2) TRANSACTION: TRANSACTION 78511, ACTIVE 33 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 3 row lock(s) MySQL thread id 22, OS thread handle 140396510238464, query id 1410 localhost root updating DELETE FROM t WHERE i = 1 2022-10-26T13:50:36.679113Z 22 [Note] InnoDB: *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78511 lock mode S 2022-10-26T13:50:36.679159Z 22 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78511 lock_mode X waiting 2022-10-26T13:50:36.679195Z 22 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1) |
Let‘s simulate another deadlock by dealing with record 2 (i=2)
Deadlock simulation on record 2 of table t (i=2):
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 | -- session 1 : mysql> START TRANSACTION; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM t WHERE i = 2 LOCK IN SHARE MODE; --session 2 : mysql> use deadlock_test; mysql> START TRANSACTION; Query OK, 0 rows affected (0.00 sec) mysql> DELETE FROM t WHERE i = 2; # This statement will wait here Let’s go back to session 1 -- session 1 : mysql> DELETE FROM t WHERE i = 2; Query OK, 1 row affected (0.00 sec) -- on session 2, you will find ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction i = 2 mysql> |
SHOW ENGINE INNODB STATUS would just keep the last detected deadlock information.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 | ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2022-10-26 09:53:02 0x7fb09c1ed700 *** (1) TRANSACTION: TRANSACTION 78512, ACTIVE 14 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 23, OS thread handle 140396446037760, query id 1414 localhost root updating DELETE FROM t WHERE i = 2 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78512 lock_mode X waiting *** (2) TRANSACTION: TRANSACTION 78513, ACTIVE 26 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 3 row lock(s) MySQL thread id 22, OS thread handle 140396510238464, query id 1415 localhost root updating DELETE FROM t WHERE i = 2 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78513 lock mode S *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78513 lock_mode X waiting *** WE ROLL BACK TRANSACTION (1) ------------ |
We could get all history deadlock information from the MySQL error log.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 | <strong> ======================================================= 1st deadlock error after we enabled innodb_print_all_deadlocks ======================================================= </strong> 2022-10-25T22:59:30.834488Z 6 [Note] Aborted connection 6 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error reading communication packets) 2022-10-26T13:50:36.678728Z 22 [Note] InnoDB: Transactions deadlock detected, dumping detailed information. 2022-10-26T13:50:36.678760Z 22 [Note] InnoDB: *** (1) TRANSACTION: TRANSACTION 78510, ACTIVE 18 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 23, OS thread handle 140396446037760, query id 1409 localhost root updating DELETE FROM t WHERE i = 1 2022-10-26T13:50:36.678785Z 22 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78510 lock_mode X waiting 2022-10-26T13:50:36.678958Z 22 [Note] InnoDB: *** (2) TRANSACTION: TRANSACTION 78511, ACTIVE 33 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 3 row lock(s) MySQL thread id 22, OS thread handle 140396510238464, query id 1410 localhost root updating DELETE FROM t WHERE i = 1 2022-10-26T13:50:36.679113Z 22 [Note] InnoDB: *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78511 lock mode S 2022-10-26T13:50:36.679159Z 22 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78511 lock_mode X waiting 2022-10-26T13:50:36.679195Z 22 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1) <strong>=======================================================</strong> <strong> 2nd deadlock error after we enabled innodb_print_all_deadlocks</strong> <strong>=======================================================</strong> 2022-10-26T13:53:02.858247Z 22 [Note] InnoDB: Transactions deadlock detected, dumping detailed information. 2022-10-26T13:53:02.858266Z 22 [Note] InnoDB: *** (1) TRANSACTION: TRANSACTION 78512, ACTIVE 14 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 23, OS thread handle 140396446037760, query id 1414 localhost root updating DELETE FROM t WHERE i = 2 2022-10-26T13:53:02.858296Z 22 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78512 lock_mode X waiting 2022-10-26T13:53:02.858316Z 22 [Note] InnoDB: *** (2) TRANSACTION: TRANSACTION 78513, ACTIVE 26 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 3 row lock(s) MySQL thread id 22, OS thread handle 140396510238464, query id 1415 localhost root updating DELETE FROM t WHERE i = 2 2022-10-26T13:53:02.858338Z 22 [Note] InnoDB: *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78513 lock mode S 2022-10-26T13:53:02.858351Z 22 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 163 page no 3 n bits 72 index GEN_CLUST_INDEX of table `deadlock_test`.`t` trx id 78513 lock_mode X waiting 2022-10-26T13:53:02.858366Z 22 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1) |
Notes: on MySQL 8 (especially in >8.0.4), it’s better to set log_error_verbosity = 3 (default log_error_verbosity = 2) as well, otherwise, you will get partial deadlock outputs in the error log, which are not really usable.
Please see details in this bug report https://bugs.mysql.com/bug.php?id=108891 that Agustín G filed.
Conclusion
Innodb_print_all_deadlocks dynamic parameter has been available since MySQL 5.6, and we can enable it to get all the deadlock information in the MySQL error log file.
Hope this is helpful for your application tuning.
Subscribe
Login
0 Comments
