JAVA知识体系之问题处理篇（一）——记一次神奇的mysql死锁排查过程

2022-02-26 07:28:31

1、问题

由于公司业务和技术性需求，新上线一个独立支付系统，其中部分退款功能在进行并发测试时出现偶发性mysql死锁：

[2021-09-22 15:46:18,760][c.b.a.s.i.ReverseServiceImpl][thread0][ERROR][816fbe90-a4fa-4dea-b52c-719f1f2a8c37][]call [ReverseServiceImpl][refund] EXCEPTION:Cause[org.springframework.dao.DeadlockLoserDataAccessException: 
### Error updating database.  Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
### The error may exist in com/xxx/xxx/dal/mapper/OrderMapper.java (best guess)
### The error may involve com.xxx.xxx.dal.mapper.OrderMapper.updateRefundAmountByPayNo-Inline
### The error occurred while setting parameters
### SQL: UPDATE t_xxx_pay_order SET updated_by = ?, refund_amount = ?, cancel_flag = ?, updated_at = now(3) WHERE (pay_no = ? AND cancel_flag = ? AND refund_amount = ?)
### Cause: com.mysql.cj.jdbc.exceptions.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.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
	at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:267)
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
	at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:88)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:440)
	at com.sun.proxy.$Proxy123.update(Unknown Source)
	at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:287)
	at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:67)
	at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:93)
	at com.sun.proxy.$Proxy128.updateRefundAmountByPayNo(Unknown Source)

退款功能介绍：

用户在完成一笔订单后可以发起退款，并且只要退款总金额不大于原订单金额就允许多次退款，所以需要在原订单记录总退款金额。
支付时可能涉及用户+营销金额支付，退款时同样存在退回资金到营销的场景。例如一笔订单100，用户支付80，营销优惠20，退款时可以指定用户退5，营销退2。
在进行一笔交易（支付/退款）时会涉及3张主要的表操作，分别是order表（记录订单信息），fund表（记录用户支付信息），innermarket表（记录营销信息）。
所有更新原订单的操作以金额作乐观锁更新，sql语句伪代码如下：

update xxx set refund_amount = ? where pay_no = ? and refund_amount = ?(原退款金额)

退款处理流程：

执行退款前事务（事务X）：处理之前插入退款单到order表、innermarket表；更新原订单order表、fund表、innermarket表的退款金额。
执行退款。
执行退款后事务（事务Y）：更新退款单order表、fund表、innermarket表退款结果；如果退款执行失败，需要回退原订单order表、fund表、innermarket表中的退款金额。

2、初步解决

出现问题时，刚好边上有一个大佬，推测是由于一个线程（线程A）在执行事务X更新原订单表的流程，另一个线程（线程B）在执行事务Y退款失败回退原订单表的流程，且更新顺序不一致导致。
检查代码，发现事务X中更新原单的顺序是order表->fund表->innermarket表，事务Y中回退原订单退款金额的顺序是fund表->order表->innermarket表。由于原单是同一笔订单，A更新order表持有行锁尝试竞争fund表行锁，B更新fund表持有行锁尝试竞争order表行锁，会导致死锁。
调试代码，问题复现。
解决问题，修改回退原订单退款金额的操作，更新顺序改为order表->fund表->innermarket表。
调试代码，问题消失。
此时大家都以为问题解决，我脑海里闪现过一丝疑问：好像发生死锁的时候，并没有出现调用失败回滚的场景，事实上测试人员并发测试的结果是线程A执行成功，而线程B在进行执行事务X抛出死锁异常。但没有放在心上。

3、问题重现

第二天，测试人员继续进行并发测试，问题重现。

4、问题无法复现

本地调试，无法复现，并发执行时，由于乐观锁控制，仅线程A更新成功，线程B由于金额发生变动，没有更新到记录，同时也没有抛出死锁异常。
为了保证同时执行，引入循环屏障CyclicBarrier，仍无法复现。

    CyclicBarrier cyclicBarrier = new CyclicBarrier(20);
    
    @Test
    public void test() {
        
        for (int i=0;i<20;i++) {
            new Thread(() -> {
                log.info("等待执行");
                try {
                    cyclicBarrier.await();
                } catch (Exception e) {
                    e.printStackTrace();
                }
                log.info("开始执行");
                refundTest();
            }, "thread" + i).start();
        }
    }

5、拉取mysql数据库日志

找不到原因，拉取mysql报错日志：

2021-09-22T09:17:22.420170+08:00 338572 [Note] InnoDB: 
*** (1) TRANSACTION:

TRANSACTION 28286381, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
MySQL thread id 338566, OS thread handle 140158367102720, query id 1295050108 172.17.241.83 xxx updating
UPDATE t_xxx_order
SET updated_by = 'Hardy', refund_amount = 10, cancel_flag = 'FALSE', updated_at = now(3)
WHERE (pay_no = 'xxx' 'FALSE' AND refund_amount = 0)
2021-09-22T09:17:22.420317+08:00 338572 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 64 page no 5 n bits 288 index UIDX_PAY_NO of table `xxx`.`xxx_order` trx id 28286381 lock_mode X locks rec but not gap waiting
Record lock, heap no 213 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 323032313039323232303030303031303030303130303030303030303033; asc 202109222000001000010000000003; (total 32 bytes);
 1: len 8; hex 00000000000000db; asc         ;;

2021-09-22T09:17:22.437466+08:00 338572 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 28286382, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
11 lock struct(s), heap size 1136, 117 row lock(s), undo log entries 5
MySQL thread id 338572, OS thread handle 140158405760768, query id 1295050112 172.17.241.83 xxx updating
UPDATE xxx_innermarket
SET updated_by = 'Hardy', refund_amt = 5, updated_at = now(3)
WHERE (account_no = 'xxx' AND pay_no = 'xxx')
2021-09-22T09:17:22.437566+08:00 338572 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 64 page no 5 n bits 288 index UIDX_PAY_NO of table `xxx`.`xxx_order` trx id 28286382 lock_mode X locks rec but not gap
Record lock, heap no 213 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 323032313039323232303030303031303030303130303030303030303033; asc 202109222000001000010000000003; (total 32 bytes);
 1: len 8; hex 00000000000000db; asc         ;;

2021-09-22T09:17:22.438068+08:00 338572 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 33 page no 5 n bits 136 index PRIMARY of table `xxx`.`xxx_innermarket` trx id 28286382 lock_mode X waiting
Record lock, heap no 63 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
 0: len 8; hex 0000000000000071; asc        q;;
 1: len 6; hex 000001af9dad; asc       ;;
 2: len 7; hex d2000001a40120; asc        ;;
 3: len 3; hex 8fcb36; asc   6;;
 4: len 7; hex 99aaac94560e24; asc     V $;;
 5: len 5; hex 4861726479; asc Hardy;;
 6: len 7; hex 99aaac94560e24; asc     V $;;
 7: len 5; hex 4861726479; asc Hardy;;
 8: len 30; hex 323032313039323232303030303031303030303130303030303030303033; asc 202109222000001000010000000003; (total 32 bytes);
 9: len 6; hex 524546554e44; asc REFUND;;
 10: len 18; hex 383831313336303530303030303339313536; asc xxx;;
 11: len 7; hex 42414c414e4345; asc BALANCE;;
 12: len 8; hex 8000000000000005; asc         ;;
 13: len 8; hex 8000000000000000; asc         ;;
 14: len 4; hex 494e5445; asc INTE;;
 15: len 0; hex ; asc ;;
 16: len 30; hex 323032313039323232303030303031303030303130303030303030303033; asc 202109222000001000010000000003; (total 32 bytes);

2021-09-22T09:17:22.439896+08:00 338572 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1)

日志分析结论：

死锁在两个线程都执行事务X时发生，与事务Y没有关系。
其中一个锁与update order有关，另一个貌似与update innermarket有关。

6、问题复现与思考

根据分析结论猜测，调试没有复现问题是由于发起的退款没有退innermarket（退款方式是自定义的，可以选择只退fund或者只退innermarket，也可以fund和innermarket一起退，原本以为只与update order有关，没有发起innermarket退款），发起退款时带上innermarket，问题复现。
定位异常场景：线程A执行事务X的最后一步update innermarket时，同时线程B执行事务X的update order时，抛出死锁异常。
仍然没有想明白的是：死锁只有在线程A获得锁M尝试获取锁N，线程B获得锁N尝试获取锁M时才会出现。而本场景中两个线程执行的是同一段代码，且同样保持先update order再update innermarket的更新顺序，二者不相符。
天马行空的想法：JIT优化？延迟释放锁？表级锁？

7、得出结论

了解到，mysql的锁针对的是索引而不是记录，当查询条件包含唯一索引的时候，只会锁当前记录的索引，当查询索引是一个范围的话会锁一个范围的索引，考虑是不是sql语句没有走索引的问题。
检查代码中更新sql，写法没有问题：

update xxx set refund_amount = ? where pay_no = ? and refund_amount = ?(原退款金额)

抱着试一试的心态查了innermarket表，发现innermarket表没有加索引，这张表是团队中一个小伙伴在开发过程中增加的，而我也没有再次进行检查。回想起来，事务X刚好在update order之前有insert innermarket的操作。

至此，问题水落石出

线程A在执行事务X过程中，获取了update order行级锁M。
线程B在执行事务X过程中，获取了insert innermarket（营销退款单插入操作）行级锁N，执行到update order，尝试获取锁M，进入锁等待。
线程A执行到update innermarket的时候需要锁全表，但由于线程B持有了行级锁N，进入锁等待。
mysql检测到死锁，关闭并回滚线程B的事务，线程A执行成功，线程B执行失败。

8、问题解决

innermarket表增加索引pay_no，问题解决。

9、问题反思

蝴蝶效应在本次事例中体现得淋漓尽致。细节决定成败，代码不会骗人，设计开发过程中一定要对自己的代码负责，实际上做每一份工作都要对自己的工作负责，只是这个问题在IT行业很容易被放大。
没有人能保证永远不出问题，那么解决问题的能力就很关键。同样一个问题有些人一瞬间就能猜到答案，有些人想破脑袋好几天都解决不了。这个能力需要技术和经验的结合，经验需要沉淀，那么技术就需要学习。团队成员普遍对mysql底层原理了解不够透彻，也是问题解决缓慢的重要因素。

码农公寓