由Mysql死锁引发的服务高可用探讨

一、背景

最近在公司遇到两个服务可用性问题，一个是生产环境的，另一个是在联调环境中出现的。今天先聊一下在联调环境中出现的一个死锁问题。在整个排查过程中也学到了如何理解MySQL死锁日志，同时对整个调用链路的高可用问题有一些思考。

二、业务流程介绍

业务背景是业务方在购买商品后需要调用交易系统接口进行分账，然后调用支付系统进行分账请求，整个请求链路其实会比较长。如下时序图：简单概括下，就是在交易调用支付分账的时候接口返回有几种情况，但是另外也会有消息回来。在支付对接下游渠道的时候也是这种方式，但是交易这边是认为接口返回成功之后不会理会消息的。由此导致了本次死锁问题的触发。

三、死锁问题排查

3.1 死锁异常

由于没有保留Spring框架打出的异常，这里直接分析下代码层面导致的报错吧。报错是在消息消费的逻辑代码中，消息消费的逻辑是这样的：

1.在账单上累加已分账金额(update trade_bill_payxxxx ...)
//Spring框架抛出的异常指向下面这一行操作
2.修改分账详情为分账成功(update trade_xxx_order_detail set ...)

经过排查发现同步调用返回的交易侧处理逻辑如下：


1.修改分账详情为分账成功(update trade_settle_xxx_detail set ...)
2.在账单上累加已分账金额(update trade_bill_payxxxx ...)

这里使用的是rocketMq+Dubbo+SpringBoot的技术栈,经过对数据库持久化数据的分析发现当前的分账请求是返回处理成功了的，但是后面消息也回调说成功了。不过消息回调的太快，交易侧的同步还没来得及提交事务消息就回来了，紧接着开启事务并进行数据操作。然后出现了死锁。

3.2 MySql死锁事务日志

现在我们重点分析下死锁日志，看看发生了什么

=====================================
# 查询死锁日志的时间
2022-06-15 15:34:28 0x7fabfc57b700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 7 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1092962 srv_active, 0 srv_shutdown, 3391062 srv_idle
srv_master_thread log flush and writes: 4484024
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 17070353
OS WAIT ARRAY INFO: signal count 20471638
RW-shared spins 0, rounds 30005720, OS waits 9071635
RW-excl spins 0, rounds 251587519, OS waits 4470097
RW-sx spins 13613, rounds 374124, OS waits 9249
Spin rounds per wait: 30005720.00 RW-shared, 251587519.00 RW-excl, 27.48 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-06-15 15:14:05 0x7fabec0c8700
*** (1) TRANSACTION:

# TRANSACTION 80128574, 80128574为事务编号

# ACTIVE 0 sec 表示事务活动时间， 
# starting index read 表示读取表索引， 
# tables in use 1表示有一张表被使用，
# 1 lock struct(s) 表示该事务的锁链表的长度为 1，
# 每个链表节点代表该事务持有的一个锁结构，包括表锁，记录锁以及 autoinc 锁等
# heap size 1128 为事务分配的锁堆内存大小。
# 2 row lock(s) 表示当前事务持有的行锁个数。


TRANSACTION 80128574, 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 1
MySQL thread id 862696, OS thread handle 140376649942784, query id 173406577 172.xx.xx.xx xxxxx_rw updating
update trade_bill_payxxxx set splitted_amount = splitted_amount + 2040000, date_update = current_timestamp
        where pay_trade_order_no = '1536967158910427136'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

# lock type : 锁的类型 这里指RECORD LOCKS（记录锁）
# space id : 锁对象的space id
# page no ：事务锁定页的数量，若是表锁，该值为null
# index ：锁住的索引，这里指的是idx_payment_pay_trade_order_xx索引
# table：要加锁的表，这里是xxx数据库的trade_bill_payxxxx表
# trx id：事务id，这里是80128574
# lock_mode : 锁的模式，这边指的是加了一个X lock(写锁，排它锁)


RECORD LOCKS space id 7056 page no 490 n bits 528 index idx_payment_pay_trade_order_xx of table `xxx`.`trade_bill_payxxxx` 
trx id 80128574 lock_mode X locks rec but not gap waiting

Record lock, heap no 461 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 19; hex 31353336393637313538393130343237313336; asc 1536967158910427136;;
 1: len 8; hex 8000000000007675; asc       vu;;

*** (2) TRANSACTION:
TRANSACTION 80128573, ACTIVE 0 sec starting index read, thread declared inside InnoDB 5000
mysql tables in use 1, locked 1

5 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
MySQL thread id 862695, OS thread handle 140376376379136, query id 173406579 172.xx.xx.xx xxx_rw updating
update trade_settle_xxx_xxx
         SET request_no = '1536970*******',
            
                settle_order_code = '1536970*******',
            
                status = xx,
            
# 事务2正在持有的锁            
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 7056 page no 490 n bits 528 index idx_payment_pay_trade_order_xx of table `xxx`.`trade_bill_payxxx` trx id 80128573 lock_mode X locks rec but not gap
Record lock, heap no 461 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 19; hex 31353336393637313538393130343237313336; asc 1536967158910427136;;
 1: len 8; hex 8000000000007675; asc       vu;;

# 事务2 正在等待的锁
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8128 page no 7 n bits 80 index PRIMARY of table `xxxx`.`trade_settle_order_xxxx` trx id 80128573 lock_mode X locks rec but not gap waiting
Record lock, heap no 14 PHYSICAL RECORD: n_fields 19; compact format; info bits 0
 0: len 4; hex 00000066; asc    f;;
 1: len 6; hex 000004c6aa3e; asc      >;;
 2: len 7; hex 7b000000372966; asc {   7)f;;
 3: len 19; hex 31353336393730323734393731343834343536; asc 1536970274971484456;;
 4: len 19; hex 31353336393730323735343131383836383533; asc 1536970275411886853;;
 5: len 19; hex 31353336393637313538393130343237313336; asc 1536967158910427136;;
 6: len 8; hex 80000000001f20c0; asc         ;;
 7: len 12; hex 333030303030303031393335; asc 300000001935;;
 8: SQL NULL;
 9: SQL NULL;
 10: SQL NULL;
 11: SQL NULL;
 12: len 30; hex 7b22636f6465223a2253554343455353222c226d7367223a22e58f97e790; asc {"code":"SUCCESS","msg":"     ; (total 182 bytes);
 13: len 8; hex 80000000000000f0; asc         ;;
 14: len 18; hex 323539343838353335303236303332363432; asc 259488535026032642;;
 15: len 30; hex 544f4e474c49414e323032323036303030303236383553484152452d5445; asc TONGLIAN20220600002685SHARE-TE; (total 32 bytes);
 16: len 4; hex 80000001; asc     ;;
 17: len 4; hex 62a986bc; asc b   ;;
 18: len 4; hex 62a986bc; asc b   ;;


#Mysql根据InnoDB存储引擎会选择回滚undo量最小的事务,也是链锁表的长度，越短就越被回滚
*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 80128757
Purge done for trx's n:o < 80128757 undo n:o < 0 state: running but idle
History list length 7
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421853276231296, not started

3.3 死锁逻辑流程梳理

这里根据网上的日志解析发现两个事务的活动时间都很短，另外一方面这种情况是两个表之间的执行顺序不一致，导致了两个事务相互等待对方释放锁。这种情况不是并发对一张表进行修改，而是两张表的操作，另外在排查问题的时候单纯的认为支付侧不会在同步处理成功的时候发消息，导致排查问题耽误了一些时间。而Mysql则根据InnoDB存储引擎的规则去回滚了事务1。

四、高可用优化方案

问题发现了之后就需要进行解决，首先需要确定的是支付侧的整个逻辑是否如第二节的时序图那样(这里根据支付侧反馈是的)。交易侧可以做的方案如下：

调整同步处理逻辑和异步消费逻辑操作数据库的一致性
交易侧重构同步和异步的分账处理逻辑，保留一套代码
在同步处理前按分账详情列表一一加锁
在消息消费处进行幂等查询，查询当前分账明细是否已处理完成，如果已经完成则默认消费成功。

跟支付侧沟通后支付侧不会将同步和异步方案改到统一，所以支付侧改动希望不大。所以对于交易侧来说需要完成第一个方案，同时完成第四个方案保障代码基本没有问题。在后面的评估中发现即使加锁和消息消费的幂等查询都有可能会导致失误失败，因为消息来的太快了，另外加锁对交易侧来说改动量会大一些，所以方案3暂时先不落地。对于方案2来说无异于核心逻辑的重构，但是这依然无法解决分账结果并发执行的问题。

回到MQ上面来看，如果让支付侧在同步返回之后延迟一点时间发送消息则可以基本解决并发的问题。因此跟支付侧沟通之后让支付侧在发分账结果消息的时候延迟1秒的时间。这个时间是根据交易侧消费逻辑处理内容来判定的，同时支付侧也不希望延迟太长时间，对于交易侧来说事务处理部分不会超过1秒，消息到来也没有问题，相当于串行化了。对于同步和异步来说只要有处理结果那么对于交易侧来说都会回调到业务方并告知，对于同步异步并行的逻辑却是可以保障高可用，但是也引起了一些麻烦。在阿里前两天的分布式应用技术分享的时候钉钉XRocketMQ方面的实践有这一张ppt跟这个问题类似：这里简单对上面的PPT做一下说明：receiver收到消息之后先写入RocketMq，然后调用processor服务进行消息推送，同时在recevier端进行redolog的持久化，定时任务进行回归放到rocketmq.也就是说会通过RocketMq发两次消息。本文中的案例则是在同步返回结果的同时发消息。那么在服务调用之间的可用性需要怎么做呢？常规情况看有以下场景：

a—>b请求写数据—->b同步返回到a
a—>b请求写数据—->b返回消息
a—>b请求写数据—->b返回消息(or b进行接口回调)—–>a在一定时间内回调b读数据

但是为了高可用的话，a—>请求写数据其实是不可靠的，也就是说在极端场景下失败的概率会更高，为了让写请求成功则需要冗余写，也就是说需要写多份。因为对于b来说b非常希望a可以100%的把数据给过来。另外一方面，这种方案也不是适用于所有场景，因为写多次的时候必然会导致代码很复杂，比如页面到服务器的写请求，或者说不重要的服务之间写数据。也就是说在服务之间调用为了保障高可用的话起码需要投入很多资源，至于是否值得就得看业务了，但是常规的做法来说只有同步调用或者只有消息回调其可用性可能没有双保险或者三保险来的高。不过就具体场景来看还需要保证数据的一致性还有幂等操作。