In-depth analysis of MySQL deadlock issues

Preface

If our business is at a very early stage and the degree of concurrency is relatively low, then we may not encounter a deadlock problem for several years. On the contrary, if the degree of concurrency of our business is very high, then the deadlock problems that occur from time to time will definitely make us very puzzled. However, when a deadlock problem occurs, the first reaction of many inexperienced students is to become an ostrich: This thing is very advanced, I don’t understand it, just leave it to fate, it doesn’t happen all the time. In fact, if you carefully read the three articles we wrote before on the analysis of statement locking in MySQL, plus this article on the analysis of deadlock logs, then solving the deadlock problem should not be so confusing.

Preparation

In order for the story to develop smoothly, we need to build a table:

CREATE TABLE hero (
 id INT,
 name VARCHAR(100),
 country varchar(100),
 PRIMARY KEY (id),
 KEY idx_name (name)
) Engine=InnoDB CHARSET=utf8;

We created a clustered index for the id column of the hero table and a secondary index for the name column. This hero table is mainly used to store some heroes during the Three Kingdoms period. We insert some records into the table:

INSERT INTO hero VALUES
 (1, 'lLiu Bei', 'Shu'),
 (3, 'zZhuge Liang', 'Shu'),
 (8, 'cCao Cao', 'Wei'),
 (15, 'xXun Yu', 'Wei'),
 (20, 'sSun Quan', 'Wu');

The data in the table now looks like this:

mysql> SELECT * FROM hero;
+----+------------+---------+
| id | name | country |
+----+------------+---------+
| 1 | lLiu Bei| Shu|
| 3 | zZhuge Liang | Shu |
| 8 | cCao Cao | Wei |
| 15 | xXun Yu | Wei |
| 20 | sSun Quan | Wu |
+----+------------+---------+
5 rows in set (0.00 sec)

The preparations are complete.

Creating a Deadlock Scenario

Let's first create a deadlock scenario and execute two transactions in Session A and Session B respectively. The specific situation is as follows:

Let's analyze it:

• As can be seen from step ③, the transaction in Session A first adds an X-type positive record lock to the record with id value 1 in the clustered index of the hero table.
• As can be seen from step ④, the transaction in Session B adds an X-type positive record lock to the record with id value 3 in the clustered index of the hero table.
• As can be seen from step 5, the transaction in Session A then wants to add an X-type regular record lock to the record with id value 3 in the clustered index of the hero table, but it conflicts with the lock added by the transaction in Session B in step 4, so Session A enters a blocked state, waiting to acquire the lock.
• As can be seen from step 6, the transaction in Session B wants to add an X-type positive record lock to the record with id value 1 in the clustered index of the hero table, but it conflicts with the lock added by the transaction in Session A in step 3. At this time, the transactions in Session A and Session B are cyclically waiting for the lock held by each other, and a deadlock occurs. The deadlock detection mechanism of the MySQL server detects it, so a transaction is selected for rollback and a message is sent to the client:

ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

The above is our deadlock analysis from the perspective of what locks are added to the statements. However, in actual applications, we may not know which statements caused the deadlock at all. We need to reversely locate which statements caused the deadlock based on the deadlock log generated by MySQL when the deadlock occurs, so as to optimize our business.

View deadlock log

The guy who designed InnoDB provided us with the SHOW ENGINE INNODB STATUS command to view some status information about the InnoDB storage engine, including the locking status of the system when a deadlock occurred most recently. When the deadlock in the above example occurs, we run this command:

mysql> SHOW ENGINE INNODB STATUS\G
...a lot of other information is omitted------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-06-20 13:39:19 0x70000697e000
*** (1) TRANSACTION:
TRANSACTION 30477, ACTIVE 10 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 2, OS thread handle 123145412648960, query id 46 localhost 127.0.0.1 root statistics
select * from hero where id = 3 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30477 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc ;;
 1: len 6; hex 000000007517; asc u ;;
 2: len 7; hex 80000001d0011d; asc ;;
 3: len 10; hex 7ae8afb8e8919be4baae; asc z ;;
 4: len 3; hex e89c80; asc ;;

*** (2) TRANSACTION:
TRANSACTION 30478, ACTIVE 8 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 3, OS thread handle 123145412927488, query id 47 localhost 127.0.0.1 root statistics
select * from hero where id = 1 for update
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc ;;
 1: len 6; hex 000000007517; asc u ;;
 2: len 7; hex 80000001d0011d; asc ;;
 3: len 10; hex 7ae8afb8e8919be4baae; asc z ;;
 4: len 3; hex e89c80; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000001; asc ;;
 1: len 6; hex 000000007517; asc u ;;
 2: len 7; hex 80000001d00110; asc ;;
 3: len 7; hex 6ce58898e5a487; asc l ;;
 4: len 3; hex e89c80; asc ;;

*** WE ROLL BACK TRANSACTION (2)
------------
...a lot of other information is omitted

We only care about the most recent deadlock information, so we will analyze the LATEST DETECTED DEADLOCK section separately. Let's take a look at what the deadlock log output means line by line:

First look at the first sentence:

2019-06-20 13:39:19 0x70000697e000

This sentence means that the time when the deadlock occurred is: 2019-06-20 13:39:19, and the following string of hexadecimal 0x70000697e000 represents the thread id of the thread assigned by the operating system to the current session.

Then there is information about the first transaction when the deadlock occurred:

*** (1) TRANSACTION:

# The transaction id is 30477. The transaction has been in ACTIVE state for 10 seconds. The operation currently being performed by the transaction is: "starting index read"
TRANSACTION 30477, ACTIVE 10 sec starting index read

# This transaction uses 1 table and locks 1 table (this does not mean that a table lock is added to the table. As long as the table is not read consistently, it needs to be locked. For specific ways to lock, please refer to the lock statement analysis or the booklet chapter)
mysql tables in use 1, locked 1

# This transaction is in LOCK WAIT state, with 3 lock structures (2 row lock structures, 1 table-level X-type intention lock structure, the lock structure is introduced in detail in the booklet), heap size is the memory size requested for storing the lock structure (we can ignore it), there are 2 row lock structures LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)

# The thread id of this transaction is 2 (MySQL's own thread id). The thread id at the operating system level is the long string of numbers. The id of the current query is 46 (MySQL internal use, can be ignored), and there is also user name and host information MySQL thread id 2, OS thread handle 123145412648960, query id 46 localhost 127.0.0.1 root statistics

# The statement that blocks this transaction select * from hero where id = 3 for update

# The lock that this transaction is currently waiting to acquire:
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

# The tablespace ID to be acquired is 151, page number is 3, that is, the lock of a record in the PRIMAY index of the hero table (n_bits is a string of memory space allocated to store the lock information of this page, which is described in detail in the brochure). The lock type is X-type rec but not gap lock
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30477 lock_mode X locks rec but not gap waiting

# The heap_no of this record in the page is 2. The specific record information is as follows:
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0

# This is the primary key value 0: len 4; hex 80000003; asc ;;

# This is trx_id hidden column 1: len 6; hex 000000007517; asc u ;;

# This is roll_pointer hidden column 2: len 7; hex 80000001d0011d; asc ;;

# This is name column 3: len 10; hex 7ae8afb8e8919be4baae; asc z ;;

# This is country column 4: len 3; hex e89c80; asc ;;

From this information, we can see that the transaction in Session A generated lock structures for two records, but the X-type regular record lock (rec but not gap) on one of the records was not acquired. The location of the record that was not locked is: tablespace ID is 151, page number is 3, and heap_no is 2. Of course, the guy who designed InnoDB also kindly gave the details of this record. Its primary key value is 80000003, which is actually the format used for internal storage in InnoDB. It actually represents the number 3, which means that the transaction is waiting to obtain the X-type regular record lock of the record with the primary key value of 3 in the clustered index of the hero table.

Then there is information about the second transaction when the deadlock occurred:

We have already introduced most of the information, so we will just mention the important ones:

*** (2) TRANSACTION:
TRANSACTION 30478, ACTIVE 8 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 3, OS thread handle 123145412927488, query id 47 localhost 127.0.0.1 root statistics
select * from hero where id = 1 for update

# Indicates the lock information obtained by the transaction*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0

# The primary key value is 3
0: len 4; hex 80000003; asc ;;
1: len 6; hex 000000007517; asc u ;;
2: len 7; hex 80000001d0011d; asc ;;
3: len 10; hex 7ae8afb8e8919be4baae; asc z ;;
4: len 3; hex e89c80; asc ;;

# Indicates the lock information that the transaction is waiting to obtain*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0

# The primary key value is 1
0: len 4; hex 80000001; asc ;;
1: len 6; hex 000000007517; asc u ;;
2: len 7; hex 80000001d00110; asc ;;
3: len 7; hex 6ce58898e5a487; asc l ;;
4: len 3; hex e89c80; asc ;;

From the above output, we can see that the transaction in Session B has acquired the X-type proper record lock for the record with the primary key value of 3 in the clustered index of the hero table, and is waiting to acquire the X-type proper record lock for the record with the primary key value of 1 in the clustered index of the hero table (the implicit meaning is that the X-type proper record lock for the record with the primary key value of 1 in the clustered index of the hero table has been acquired by the transaction in SESSION A).

Look at the last part:

*** WE ROLL BACK TRANSACTION (2)

Finally, the InnoDB storage engine decides to roll back the second transaction, which is the transaction in Session B.

Deadlock analysis ideas

1. When checking the deadlock log, first check what statements the deadlocked transaction is waiting for to acquire the lock.

In this example, the statement that blocks SESSION A is:

select * from hero where id = 3 for update

The statement in which SESSION B is blocked is:

select * from hero where id = 1 for update

Then remember: find other statements in the transaction where these two statements are located in your own business code.

2. After finding all the statements in the transaction where the deadlock occurs, analyze the deadlock process by comparing the information about the locks obtained by the transaction and the locks being waited for.

From the deadlock log, we can see that SESSION A obtains the X-type regular record lock of the record with id value 1 of the clustered index of the hero table (this is actually obtained from the lock that SESSION B is waiting for). Looking at the statements in SESSION A, we find that the following statement is the cause (refer to the three articles on statement locking analysis):

select * from hero where id = 1 for update;

In addition, SESSION B obtains an X-type regular record lock for the record with the clustered index id value of 3 in the hero table. Looking at the statements in SESSION B, it is found that the following statement is the cause (refer to the three articles on statement locking analysis):

select * from hero where id = 3 for update;

Then we can see that SESSION A is waiting for the X-type regular record lock of the record with the clustered index id value of 3 in the hero table. This is caused by the following statement:

select * from hero where id = 3 for update;

Then we see that SESSION B is waiting for the X-type regular record lock of the record with the clustered index id value of 1 in the hero table. This is caused by the following statement:

select * from hero where id = 1 for update;

Then the entire deadlock formation process is restored based on the deadlock log.

Summarize

The above is the full content of this article. I hope that the content of this article will have certain reference learning value for your study or work. Thank you for your support of 123WORDPRESS.COM.