数据库
首页 > 数据库> > JAVA知识体系之问题处理篇(一)——记一次神奇的mysql死锁排查过程

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

作者:互联网

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)

退款功能介绍:

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

退款处理流程:

  1. 执行退款前事务(事务X):处理之前插入退款单到order表、innermarket表;更新原订单order表、fund表、innermarket表的退款金额。
  2. 执行退款。
  3. 执行退款后事务(事务Y):更新退款单order表、fund表、innermarket表退款结果;如果退款执行失败,需要回退原订单order表、fund表、innermarket表中的退款金额。

2、初步解决

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)

日志分析结论:

6、问题复现与思考

7、得出结论

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

至此,问题水落石出

8、问题解决

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

9、问题反思

标签:innermarket,JAVA,xxx,len,asc,死锁,mysql,退款,order
来源: https://blog.csdn.net/qsmiley10/article/details/120418939