MySQL print deadlock log

Foreword:

In the process of MySQL operation and maintenance, it is inevitable that you will encounter MySQL deadlock. Once the online business becomes more and more complicated, lock conflicts will often occur between various business operations, and some will cause deadlock abnormalities. This kind of deadlock exception generally only reappears at a specific time for specific data and specific business operations, and sometimes it is clueless to deal with, and generally only starts from the deadlock log. In this article, let's take a look at the deadlock log of MySQL.

1. Manually print the deadlock log

When a deadlock occurs in the business, first the online error log reports an abnormal deadlock, and some stack information will also be prompted, and then it will be fed back to the database level for troubleshooting. We generally execute show engine innodb status\G on the command line to output the deadlock log. The function of \G is to display a field and field value in each line of the query result for easy viewing.

show engine innodb status is a tool provided by MySQL to view the system information of the innodb engine. It will output a large amount of internal information, the content is divided into many small sections, each section corresponds to the information of a different part of the innodb storage engine, and the LATEST DETECTED DEADLOCK part shows the most recent deadlock information.

Let's create a deadlock manually and take a look at the related information of the deadlock log:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2021-11-10 17:03:10 0x7fb040672700
*** (1) TRANSACTION:
TRANSACTION 46913, ACTIVE 142 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
MySQL thread id 2997198, OS thread handle 140394973071104, query id 9145673 localhost root updating
update test_tb set stu_name = 'lisi' where stu_id = 1006
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 224 page no 4 n bits 80 index uk_stu_id of table `testdb`.`test_tb` trx id 46913 lock_mode X locks rec but not gap waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 800003ee; asc     ;;
 1: len 4; hex 80000006; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 46914, ACTIVE 103 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
MySQL thread id 2997201, OS thread handle 140394971473664, query id 9145681 localhost root updating
update test_tb set age = 21  where stu_id = 1005
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 224 page no 4 n bits 80 index uk_stu_id of table `testdb`.`test_tb` trx id 46914 lock_mode X locks rec but not gap
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 800003ee; asc     ;;
 1: len 4; hex 80000006; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 224 page no 4 n bits 80 index uk_stu_id of table `testdb`.`test_tb` trx id 46914 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 800003ed; asc     ;;
 1: len 4; hex 80000005; asc     ;;

*** WE ROLL BACK TRANSACTION (2)

# 以上为原文 下面增加个人分析
------------------------
LATEST DETECTED DEADLOCK
------------------------
2021-11-10 17:03:10 0x7fb040672700 #这里显示了最近一次发生死锁的日期和时间
*** (1) TRANSACTION: #死锁相关的第一个事务
TRANSACTION 46913, ACTIVE 142 sec starting index read
#这行表示事务id为46913，事务处于活跃状态142s，starting index read表示正在使用索引读取数据行
mysql tables in use 1, locked 1
#这行表示该事务正在使用1个表，且涉及锁的表有1个
LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
#这行表示在等待4把锁，占用内存1136字节，涉及3行记录
MySQL thread id 2997198, OS thread handle 140394973071104, query id 9145673 localhost root updating
#这行表示该事务的线程ID信息，操作系统句柄信息，连接来源、用户
update test_tb set stu_name = 'lisi' where stu_id = 1006
#这行表示事务执行的最后一条SQL信息
*** (1) WAITING FOR THIS LOCK TO BE GRANTED: #事务1想要获取的锁
RECORD LOCKS space id 224 page no 4 n bits 80 index uk_stu_id of table `testdb`.`test_tb` trx id 46913 lock_mode X locks rec but not gap waiting
#这行信息表示等待的锁是一个record lock，空间id是224，页编号为4，大概位置在页的80位处，锁发生在表testdb.test_tb的uk_stu_id索引上，是一个X锁，但是不是gap lock，waiting表示正在等待锁
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 800003ee; asc     ;;
 1: len 4; hex 80000006; asc     ;;

*** (2) TRANSACTION: #死锁相关的第一个事务
TRANSACTION 46914, ACTIVE 103 sec starting index read
#这行表示事务2的id为46914，事务处于活跃状态103s
mysql tables in use 1, locked 1
#正在使用1个表，涉及锁的表有1个
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
#涉及4把锁，3行记录
MySQL thread id 2997201, OS thread handle 140394971473664, query id 9145681 localhost root updating
#事务2的线程ID信息，操作系统句柄信息，连接来源、用户
update test_tb set age = 21  where stu_id = 1005
#第二个事务的SQL
*** (2) HOLDS THE LOCK(S): # 事务2持有的锁 正是事务1想要获取的锁
RECORD LOCKS space id 224 page no 4 n bits 80 index uk_stu_id of table `testdb`.`test_tb` trx id 46914 lock_mode X locks rec but not gap
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 800003ee; asc     ;;
 1: len 4; hex 80000006; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 224 page no 4 n bits 80 index uk_stu_id of table `testdb`.`test_tb` trx id 46914 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 800003ed; asc     ;;
 1: len 4; hex 80000005; asc     ;;
#上面这部分是事务二正在等待的锁，从信息上看，等待的是同一个表，同一个索引，同一个page上的record lock X锁，但是heap no位置不同，即不同的行上的锁

*** WE ROLL BACK TRANSACTION (2) #表示事务2被回滚

From the deadlock log, you can see related information about the two transactions. When a transaction holds a lock required by another transaction and at the same time wants to obtain a lock held by another transaction, a loop will occur in the waiting relationship. Innodb does not All held and waiting locks will be displayed, but the deadlock log also displays relevant information to help you determine and troubleshoot the index where the deadlock occurred. This is of great value for you to determine whether you can avoid the deadlock.

2. Automatically save deadlock log

From the above content, we know that the deadlock of MySQL can be viewed through show engine innodb status, but this command needs to be executed manually and can only display the latest deadlock. This method cannot fully capture the deadlock information that occurs in the system. Is there a way to record all deadlock logs? Let's take a look at the system parameters of MySQL.

The MySQL system provides an innodb_print_all_deadlocks parameter, which is turned off by default. After it is turned on, the deadlock information can be automatically recorded in the MySQL error log. Let's take a look at the role of this parameter:

# 查看参数是否开启
mysql> show variables like 'innodb_print_all_deadlocks';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| innodb_print_all_deadlocks | OFF   |
+----------------------------+-------+

# 开启innodb_print_all_deadlocks,此参数是全局参数，可以动态调整。记得要加入到配置文件中
mysql> set global innodb_print_all_deadlocks = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'innodb_print_all_deadlocks';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| innodb_print_all_deadlocks | ON    |
+----------------------------+-------+

It is recommended to set the innodb_print_all_deadlocks parameter to 1, so that every time a deadlock occurs, the system will automatically output the deadlock information to the error log. It should be noted that when this parameter is turned on, only part of the deadlock information will be recorded instead of innodb. For other related information, only the LATEST DETECTED DEADLOCK part of show engine innodb status will be recorded.

In fact, the InnoDB storage engine also provides an InnoDB Monitor monitor, which can periodically output InnoDB status information to the error log. It is mainly controlled by the innodb_status_output and innodb_status_output_locks parameters. These two system variables are used to enable standard InnoDB monitoring and InnoDB lock monitoring. After it is turned on, the monitoring results will be output to the error log, which is output approximately every 15 seconds, and the output content is consistent with show engine innodb status. However, this will cause the error log to explode, and it is generally not recommended to enable these two parameters.

summary:

This article introduces how to obtain the MySQL deadlock log. After a deadlock occurs, you can also obtain relevant information based on the deadlock log. Enabling the innodb_print_all_deadlocks parameter can automatically output the deadlock information to the error log, which helps us discover and deal with deadlock exceptions in time.