一次诡异的线上数据库的死锁问题排查过程

GitHub 1.8k Star 的Java工程师成神之路 ，不来了解一下吗?

GitHub 1.8k Star 的Java工程师成神之路 ，真的不来了解一下吗?

GitHub 1.8k Star 的Java工程师成神之路 ，真的肯定不来了解一下吗?

现象

某天晚上，同事正在发布，忽然线上大量报警，不少是关于数据库死锁的，报警提示信息以下：

{"errorCode":"SYSTEM_ERROR","errorMsg":"nested exception is org.apache.ibatis.exceptions.PersistenceException: 

Error updating database. Cause: ERR-CODE: [TDDL-4614][ERR_EXECUTE_ON_MYSQL] 

Deadlock found when trying to get lock; 

The error occurred while setting parameters\n### SQL: 

update fund_transfer_stream set gmt_modified=now(),state = ? where fund_transfer_order_no = ? and seller_id = ? and state = 'NEW'
复制代码

经过报警，咱们基本能够定位到发生死锁的数据库以及数据库表。先来介绍下本文案例中涉及到的数据库相关信息。

背景状况

咱们使用的数据库是Mysql 5.7，引擎是InnoDB，事务隔离级别是READ-COMMITED。

数据库版本查询方法：

SELECT version();
复制代码

引擎查询方法：

show create table fund_transfer_stream;
复制代码

建表语句中会显示存储引擎信息，形如：ENGINE=InnoDB

事务隔离级别查询方法：

select @@tx_isolation;
复制代码

事务隔离级别设置方法（只对当前Session生效）：

set session transaction isolation level read committed;
复制代码

PS：注意，若是数据库是分库的，以上几条SQL语句须要在单库上执行，不要在逻辑库执行。

发生死锁的表结构及索引状况（隐去了部分无关字段和索引）：

CREATE TABLE `fund_transfer_stream` ( 
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT '主键',
  `gmt_create` datetime NOT NULL COMMENT '建立时间',
  `gmt_modified` datetime NOT NULL COMMENT '修改时间', 
  `pay_scene_name` varchar(256) NOT NULL COMMENT '支付场景名称', 
  `pay_scene_version` varchar(256) DEFAULT NULL COMMENT '支付场景版本',
  `identifier` varchar(256) NOT NULL COMMENT '惟一性标识',
  `seller_id` varchar(64) NOT NULL COMMENT '卖家Id',
  `state` varchar(64) DEFAULT NULL COMMENT '状态', `fund_transfer_order_no` varchar(256) 
  DEFAULT NULL COMMENT '资金平台返回的状态', 
  PRIMARY KEY (`id`),UNIQUE KEY `uk_scene_identifier` 
  (KEY `idx_seller` (`seller_id`),
  KEY `idx_seller_transNo` (`seller_id`,`fund_transfer_order_no`(20))
  ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COMMENT='资金流水';
复制代码

该数据库共有三个索引，1个聚簇索引（主键索引），2个非聚簇索（非主键索引）引。

聚簇索引：

PRIMARY KEY (`id`)
复制代码

非聚簇索引：

KEY `idx_seller` (`seller_id`),

KEY `idx_seller_transNo` (`seller_id`,`fund_transfer_order_no`(20))
复制代码

以上两个索引，其实idx_seller_transNo已经覆盖到了idx_seller，因为历史缘由，由于该表以seller_id分表，因此是先有的idx_seller，后有的idx_seller_transNo

死锁日志

当数据库发生死锁时，能够经过如下命令获取死锁日志：

show engine innodb status
复制代码

发生死锁，第一时间查看死锁日志，获得死锁日志内容以下：

Transactions deadlock detected, dumping detailed information.
2019-03-19T21:44:23.516263+08:00 5877341 [Note] InnoDB: 

*** (1) TRANSACTION:
TRANSACTION 173268495, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 304 lock struct(s), heap size 41168, 6 row lock(s), undo log entries 1
MySQL thread id 5877358, OS thread handle 47356539049728, query id 557970181 11.183.244.150 fin_instant_app updating

update `fund_transfer_stream` set `gmt_modified` = NOW(), `state` = 'PROCESSING' where ((`state` = 'NEW') AND (`seller_id` = '38921111') AND (`fund_transfer_order_no` = '99010015000805619031958363857'))
2019-03-19T21:44:23.516321+08:00 5877341 [Note] InnoDB: 

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 173 page no 13726 n bits 248 index idx_seller_transNo of table `xxx`.`fund_transfer_stream` trx id 173268495 lock_mode X locks rec but not gap
Record lock, heap no 168 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

2019-03-19T21:44:23.516565+08:00 5877341 [Note] InnoDB: 

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 173 page no 12416 n bits 128 index PRIMARY of table `xxx`.`fund_transfer_stream` trx id 173268495 lock_mode X locks rec but not gap waiting
Record lock, heap no 56 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
2019-03-19T21:44:23.517793+08:00 5877341 [Note] InnoDB: 

*** (2) TRANSACTION:
TRANSACTION 173268500, ACTIVE 0 sec fetching rows, thread declared inside InnoDB 81
mysql tables in use 1, locked 1
302 lock struct(s), heap size 41168, 2 row lock(s), undo log entries 1
MySQL thread id 5877341, OS thread handle 47362313119488, query id 557970189 11.131.81.107 fin_instant_app updating

update `fund_transfer_stream_0056` set `gmt_modified` = NOW(), `state` = 'PROCESSING' where ((`state` = 'NEW') AND (`seller_id` = '38921111') AND (`fund_transfer_order_no` = '99010015000805619031957477256'))
2019-03-19T21:44:23.517855+08:00 5877341 [Note] InnoDB: 

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 173 page no 12416 n bits 128 index PRIMARY of table `fin_instant_0003`.`fund_transfer_stream_0056` trx id 173268500 lock_mode X locks rec but not gap
Record lock, heap no 56 PHYSICAL RECORD: n_fields 17; compact format; info bits 0

2019-03-19T21:44:23.519053+08:00 5877341 [Note] InnoDB: 

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 173 page no 13726 n bits 248 index idx_seller_transNo of table `fin_instant_0003`.`fund_transfer_stream_0056` trx id 173268500 lock_mode X locks rec but not gap waiting
Record lock, heap no 168 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

2019-03-19T21:44:23.519297+08:00 5877341 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)
复制代码

简单解读一下死锁日志，能够获得如下信息：

一、致使死锁的两条SQL语句分别是：

update `fund_transfer_stream_0056` 
set `gmt_modified` = NOW(), `state` = 'PROCESSING' 
where ((`state` = 'NEW') AND (`seller_id` = '38921111') AND (`fund_transfer_order_no` = '99010015000805619031957477256'))
复制代码

和

update `fund_transfer_stream_0056` 
set `gmt_modified` = NOW(), `state` = 'PROCESSING' 
where ((`state` = 'NEW') AND (`seller_id` = '38921111') AND (`fund_transfer_order_no` = '99010015000805619031958363857'))
复制代码

二、事务1，持有索引idx_seller_transNo的锁，在等待获取PRIMARY的锁。

三、事务2，持有PRIMARY的锁，在等待获取idx_seller_transNo的锁。

四、因事务1和事务2之间发生循环等待，故发生死锁。

同时，经过cloud DBA也能看到发生死锁时资源占有及等待状况以下图，和死锁日志中获得的信息基本一致。

五、事务1和事务2当前持有的锁均为：lock_mode X locks rec but not gap

两个事务对记录加的都是X 锁，No Gap锁，即对当行记录加锁，并为加间隙锁。

X锁：排他锁、又称写锁。若事务T对数据对象A加上X锁，事务T能够读A也能够修改A，其余事务不能再对A加任何锁，直到T释放A上的锁。这保证了其余事务在T释放A上的锁以前不能再读取和修改A。

与之对应的是S锁：共享锁，又称读锁，若事务T对数据对象A加上S锁，则事务T能够读A但不能修改A，其余事务只能再对A加S锁，而不能加X锁，直到T释放A上的S锁。这保证了其余事务能够读A，但在T释放A上的S锁以前不能对A作任何修改。

Gap Lock：间隙锁，锁定一个范围，但不包括记录自己。GAP锁的目的，是为了防止同一事务的两次当前读，出现幻读的状况。

Next-Key Lock：1+2，锁定一个范围，而且锁定记录自己。对于行的查询，都是采用该方法，主要目的是解决幻读的问题。

详见：www.cnblogs.com/zhoujinyi/p… 、 dev.mysql.com/doc/refman/…

问题排查

根据咱们目前已知的数据库相关信息，以及死锁的日志，咱们基本能够作一些简单的断定。

首先，这次死锁必定是和Gap锁以及Next-Key Lock没有关系的。由于咱们的数据库隔离级别是RC（READ-COMMITED）的，这种隔离级别是不会添加Gap锁的。前面的死锁日志也提到这一点。

而后，就要翻代码了，看看咱们的代码中事务究竟是怎么作的。核心代码及SQL以下：

@Transactional(rollbackFor = Exception.class)
public int doProcessing(String sellerId, Long id, String fundTransferOrderNo) {
    fundTreansferStreamDAO.updateFundStreamId(sellerId, id, fundTransferOrderNo);
    return fundTreansferStreamDAO.updateStatus(sellerId, fundTransferOrderNo, FundTransferStreamState.PROCESSING.name());
}
复制代码

该代码的目的是前后修改同一条记录的两个不一样字段，updateFundStreamId SQL：

update fund_transfer_stream
        set gmt_modified=now(),fund_transfer_order_no = #{fundTransferOrderNo}
        where id = #{id} and seller_id = #{sellerId}
复制代码

updateStatus SQL：

update fund_transfer_stream
    set gmt_modified=now(),state = #{state}
    where fund_transfer_order_no = #{fundTransferOrderNo} and seller_id = #{sellerId}
    and state = 'NEW'
复制代码

能够看到，咱们的同一个事务中执行了两条Update语句，这里分别查看下两条SQL的执行计划：



updateFundStreamId执行的时候使用到的是PRIMARY索引。



updateStatus执行的时候使用到的是idx_seller_transNo索引。

经过执行计划，咱们发现updateStatus实际上是有两个索引能够用的，执行的时候真正使用的是idx_seller_transNo索引。这是由于MySQL查询优化器是基于代价（cost-based）的查询方式。所以，在查询过程当中，最重要的一部分是根据查询的SQL语句，依据多种索引，计算查询须要的代价，从而选择最优的索引方式生成查询计划。

咱们查询执行计划是在死锁发生以后作的，过后查询的执行计划和发生死锁那一刻的索引使用状况并不必定相同的。可是，咱们结合死锁日志，也能够定位到以上两条SQL语句执行的时候使用到的索引。即updateFundStreamId执行的时候使用到的是PRIMARY索引，updateStatus执行的时候使用到的是idx_seller_transNo索引。

有了以上这些已知信息，咱们就能够开始排查死锁缘由及其背后的原理了。经过分析死锁日志，再结合咱们的代码以及数据库建表语句，咱们发现主要问题出在咱们的idx_seller_transNo索引上面：

KEY `idx_seller_transNo` (`seller_id`,`fund_transfer_order_no`(20))
复制代码

索引建立语句中，咱们使用了前缀索引，为了节约索引空间，提升索引效率，咱们只选择了fund_transfer_order_no字段的前20位做为索引值。

由于fund_transfer_order_no只是普通索引，而非惟一性索引。又由于在一种特殊状况下，会有同一个用户的两个fund_transfer_order_no的前20位相同，这就致使两条不一样的记录的索引值同样（由于seller_id 和fund_transfer_order_no(20)都相同 ）。

就如本文中的例子，发生死锁的两条记录的fund_transfer_order_no字段的值：99010015000805619031958363857和99010015000805619031957477256这两个就是前20位相同的。



那么为何fund_transfer_order_no的前20位相同会致使死锁呢？

加锁原理

咱们就拿本次的案例来看一下MySql数据库加锁的原理是怎样的，本文的死锁背后又发生了什么。

咱们在数据库上模拟死锁场景，执行顺序以下：

咱们知道，在MySQL中，行级锁并非直接锁记录，而是锁索引。索引分为主键索引和非主键索引两种，若是一条sql语句操做了主键索引，MySQL就会锁定这条主键索引；若是一条语句操做了非主键索引，MySQL会先锁定该非主键索引，再锁定相关的主键索引。

主键索引的叶子节点存的是整行数据。在InnoDB中，主键索引也被称为聚簇索引（clustered index）

非主键索引的叶子节点的内容是主键的值，在InnoDB中，非主键索引也被称为非聚簇索引（secondary index）

因此，本文的示例中涉及到的索引结构（索引是B+树，简化成表格了）如图：



死锁的发生与否，并不在于事务中有多少条SQL语句，**死锁的关键在于：两个(或以上)的Session加锁的顺序不一致。**那么接下来就看下上面的例子中两个事务的加锁顺序是怎样的：



下图是分解图，每一条SQL执行的时候加锁状况：



结合以上两张图，咱们发现了致使死锁的缘由： 事务1执行update1占用PRIMARY = 1的锁 ——> 事务2执行update1 占有PRIMARY = 2的锁； 事务1执行update2占有idx_seller_transNo = (3111095611，99010015000805619031)的锁，尝试占有PRIMARY = 2锁失败（阻塞）； 事务2执行update2尝试占有idx_seller_transNo = (3111095611，99010015000805619031)的锁失败（死锁）；

事务在以非主键索引为where条件进行Update的时候，会先对该非主键索引加锁，而后再查询该非主键索引对应的主键索引都有哪些，再对这些主键索引进行加锁。）

解决方法

至此，咱们分析清楚了致使死锁的根本原理以及其背后的原理。那么这个问题解决起来就不难了。

能够从两方面入手，分别是修改索引和修改代码（包含SQL语句）。

修改索引：只要咱们把前缀索引 idx_seller_transNo中fund_transfer_order_no的前缀长度修改下就能够了。好比改为50。便可避免死锁。

可是，改了idx_seller_transNo的前缀长度后，能够解决死锁的前提条件是update语句真正执行的时候，会用到fund_transfer_order_no索引。若是MySQL查询优化器在代价分析以后，决定使用索引 KEY idx_seller(seller_id)，那么仍是会存在死锁问题。原理和本文相似。

因此，根本解决办法就是改代码：

* 全部update都经过主键ID进行。
* 在同一个事务中，避免出现多条update语句修改同一条记录。
复制代码

总结与思考

在死锁发生以后的一周内，我几乎天天都会抽空研究一会，问题早早的就定位到了，修改方案也有了，可是其中原理一直没搞清楚。

前先后后作过不少中种推断及假设，又都被本身一次次推翻。最终仍是要靠实践来验证本身的想法。因而我本身在本地安装了数据库，实战的作了些测试，并实时查看数据库锁状况。show engine innodb status ;能够查看锁状况。最终才搞清楚原理。

简单说几点思考：

一、遇到问题，不要猜！！！亲手复现下问题，而后再来分析。

二、不要忽略上下文！！！我刚开始就是只关注死锁日志，一直忽略了代码中的事务其实还执行了另一条SQL语句（updateFundStreamId）。

三、理论知识再充足，关键时刻不必定想的起来！！！

四、坑都是本身埋的！！！

有道无术，术可成；有术无道，止于道；欢迎关注【Java之道】公众号，一块儿以道御术，以术识道；

参考资料： MySQL 加锁处理分析

innodb 事务隔离级别

《MySql实战45讲》

MySQL中的行级锁,表级锁,页级锁