mysql死锁后回滚事务_记一次Mysql事务死锁触发Rollback异常的排查经历

整个事件起源于一个Error，日志如下：

2019-10-31 12:55:53,953 ERROR [http-apr-8080-exec-5] com.jollycorp.pop.web.PopExceptionResolver.doResolveException(PopExceptionResolver.java:73) unresolved exception!

### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

### The error may involve com.jollycorp.pop.entity.pop.goods.PopGoodsMapper.updateByPrimaryKeySelective-Inline

### The error occurred while setting parameters

### SQL: update pop_goods SET ... where goods_id = ?

...

### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

; Deadlock found when trying to get lock; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

...

日志说的很明白，更新某行数据时发现死锁，并抛了个MySQLTransactionRollbackException异常。

那么问题来了，为什么死锁了？

Mysql InnoDB 提供了死锁检测机制，通过Wait-For-Graph算法实现。简单讲就是将事务及它等待的锁维护成一个有向图，然后进行环检测，如果发现有环则表示发生了死锁，InnoDB需要回滚掉一个事务以打破环，因此抛出了上面的异常。

所以，对于日志上的update，肯定有另一个事务和这个update所在的事务有相互的锁等待。为了找到另外一个事务，可以在数据库执行show engine innodb status查询最近的一次死锁情况，日志如下：

LATEST DETECTED DEADLOCK

------------------------

2019-10-29 16:15:09 7f3c0eba1700

*** (1) TRANSACTION:

TRANSACTION 872050326, ACTIVE 0 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 42 lock struct(s), heap size 6544, 3 row lock(s), undo log entries 1

MySQL thread id 79774, OS thread handle 0x7f3c93c5c700, query id 57613264 172.*.*.10 pop_mq Searching rows for update

update pop_sku_relation set status = 0 where goods_rec_id ...

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 5155 page no 23 n bits 144 index `PRIMARY` of table `jolly_pop_center`.`pop_sku_relation` trx id 872050326 lock_mode X locks rec but not gap waiting

Record lock, heap no 38 PHYSICAL RECORD: n_fields 41; compact format; info bits 0

0: len 4; hex 0000070d; asc ;;

...

40: len 1; hex 81; asc ;;

*** (2) TRANSACTION:

TRANSACTION 872050288, ACTIVE 0 sec starting index read

mysql tables in use 1, locked 1

4 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1

MySQL thread id 79171, OS thread handle 0x7f3c0eba1700, query id 57613277 172.*.*.10 pop_seller updating

update pop_goods ... where goods_id = 1253

*** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 5155 page no 23 n bits 144 index `PRIMARY` of table `jolly_pop_center`.`pop_sku_relation` trx id 872050288 lock_mode X locks rec but not gap

Record lock, heap no 38 PHYSICAL RECORD: n_fields 41; compact format; info bits 0

0: len 4; hex 0000070d; asc ;;

...

40: len 1; hex 81; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 11311 page no 66 n bits 96 index `PRIMARY` of table `jolly_pop_center`.`pop_goods` trx id 872050288 lock_mode X locks rec but not gap waiting

Record lock, heap no 23 PHYSICAL RECORD: n_fields 92; compact format; info bits 0

0: len 3; hex 0004e5; asc ;;

...

91: len 1; hex 80; asc ;;

*** WE ROLL BACK TRANSACTION (2)

可以看到，事务1(xid 872050326)等待pop_sku_relation的一个X锁:

RECORD LOCKS space id 5155 page no 23 n bits 144 index PRIMARY of table jolly_pop_center.pop_sku_relation trx id 872050326 lock_mode X locks rec but not gap waiting Record lock

事务2(xid 872050288)持有pop_sku_relation的一个X锁(注意是一行记录):

RECORD LOCKS space id 5155 page no 23 n bits 144 index PRIMARY of table jolly_pop_center.pop_sku_relation trx id 872050288 lock_mode X locks rec but not gap Record lock

然后事务2(xid 872050288)还等待pop_goods的一个X锁：

RECORD LOCKS space id 11311 page no 66 n bits 96 index PRIMARY of table jolly_pop_center.pop_goods trx id 872050288 lock_mode X locks rec but not gap waiting Record lock

然后事务2(xid 872050288)被回滚了：

*** WE ROLL BACK TRANSACTION (2)

这里可以让DBA帮忙捞事务1(xid 872050326)的binlog， 因为事务2回滚后，死锁解除，事务1执行成功则会记录binlog日志。应该能发现事务1也对pop_goods的同一行进行了操作。

最后跟踪代码，果然发现有一个事务首先更新了pop_goods，然后再更新pop_sku_relation。另一个事务中先更新了pop_sku_relation,然后更新pop_goods。在并发的情况下就会发生上面日志的情况：

事务1对pop_goods中id=1253的记录上X锁

事务2对pop_sku_relation中id=14616485的记录上X锁

事务1申请pop_sku_realtion中id=14616485的记录的X锁，因为事务2已经锁了所以等待

事务2申请pop_goods中id=1253的记录的X锁，因为事务1已经锁了所以等待

发现事务1和事务2相互等待，回滚事务2

最后修改代码，使update顺序保持一致。 本例中是对不同表的修改不一致，其实对同一张表不同记录如果两个事务乱序，也会产生死锁现象。因此如果有多记录更新的时候，不同表需要固定一个更新顺序，同一张表的不同记录需要进行排序再更新，从而避免死锁的发生。