记录一次由于logback死锁引起的生产事故

Posted 2023-04-23

参考技术A 基本诊断是应用问题：

诊断过程中，突然间另一个机房的容器出现了线程数暴涨的问题。

马上登陆容器，取dump文件，打开后发现大量死锁线程：

再查看官网的： https://jira.qos.ch/browse/LOGBACK-1378
发现 logback1.1.11有死锁问题。作者回复已在 logback1.2.x已经解决。升级版本继续观察吧。

MySQL大无语事件：一次生产环境的死锁事故，看看我怎么排查

今天要分享的是在生产环境中出现的一次算得上比较诡异的死锁事件, 不过庆幸的是没有产生较大的业务损失.

1. 背景

某日线上产生了多封报警邮件, 邮件内容均如下, 由于生产环境这里简化了表格结构如下

CREATE TABLE `student`  (
  `id` int(11) NOT NULL AUTO_INCREMENT COMMENT '自增主键',
  `name` varchar(64) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT '名称',
  `age` int(3) NOT NULL COMMENT '年龄',
  `school` varchar(64) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT '学校',
  PRIMARY KEY (`id`) USING BTREE,
  UNIQUE INDEX `name_age`(`name`, age) USING BTREE
) ENGINE = InnoDB AUTO_INCREMENT = 1 CHARACTER SET = utf8 COLLATE = utf8_bin ROW_FORMAT = Compact;

报警邮件内容如下

### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
### The error occurred while setting parameters
### SQL: update student SET school = "清华" WHERE ( name = '小明' )
### 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

2. 代码还原

根据报警邮件中的日志信息, 我们针对代码位置进行定位, 代码逻辑如下, 这里依旧简化了代码

业务1

    开启事务

    .... 业务普通查询

    for ( ... 循环条件 ) 

        .... Student对象构建

        .... 将构建好的对象 Student 进行insert入库

        .... 将构建好的对象 Student 发送mq进行异步处理

        .... 业务剩余条件

    

   .... 业务剩余条件

   提交事务

针对异步处理的代码逻辑如下

业务2

    .... 接受到消息Student

    .... 计算需要变更的参数

    .... 将计算好的参数 赋值给Student `school`字段

    .... 将Student 在表中的数据进行更新(这里产生了死锁)

3. 问题分析

初步猜测, 由于业务1中是在开启事务后循环插入数据, 最后在提交事务的, 那么异步发送出的消息也就是业务2在执行更新的时候都会由于业务1的事务未提交而一直出于blocked, 可能在这blocked期间产生了死锁, 但是死锁产生的原理还是没有整明白, 且不是100%必现, 我们针对问题进行深层次的分析.

追踪MYSQL innodb 状态

首先我们进去mysql, 执行

show engine innodb status;

获取信息非常多, 提取LATEST DETECTED DEADLOCK信息, 也就是最后一次死锁的信息如下

------------------------
LATEST DETECTED DEADLOCK
------------------------
191028 13:33:14
*** (1) TRANSACTION:
TRANSACTION 2656E7, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 879805, OS thread handle 0x7f8d26308700, query id 3761780 XXXXXXXXXXXXX root Updating
update student SET school = "清华" WHERE ( name = '小明' )
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 1362 n bits 376 index `name_age` of table `数据库1`.`student` trx id 2656E7 lock_mode X waiting
XXXXXX

*** (2) TRANSACTION:
TRANSACTION 2656E2, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 3
MySQL thread id 879796, OS thread handle 0x7f8d261c3700, query id 3761781 XXXXXXXXXXXXX root update
insert into student (XXXXXXXXXXXXXXXXXXXXXXXX)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 1362 n bits 376 index `name_age` of table `数据库1`.`student` trx id 2656E2 lock_mode X locks rec but not gap
XXXXXX

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 1362 n bits 376 index `name_age` of table `数据库1`.`student` trx id 2656E2 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 292 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
XXXXXX

*** WE ROLL BACK TRANSACTION (1)
------------

信息概念储备

为了能解读这里的日志信息，我们需要对MYSQL的锁的知识进行说明

锁模式解读 lock_mode

锁模式在 MySQL 的源码中定义如下：

/* Basic lock modes */
enum lock_mode 
    LOCK_IS = 0, /* intention shared */
    LOCK_IX,    /* intention exclusive */
    LOCK_S,     /* shared */
    LOCK_X,     /* exclusive */
    LOCK_AUTO_INC,  /* locks the auto-inc counter of a table in an exclusive mode*/
    ...
;

LOCK_IS：读意向锁 LOCK_IX：写意向锁 LOCK_S：读锁 LOCK_X：写锁 LOCK_AUTO_INC：自增锁

篇幅有限这里解释下最普通的读写锁 LOCK_S与LOCK_X:
读锁, 又称共享锁（Share locks，简称 S 锁）, 加了读锁的记录，所有的事务都可以读取, 但是不能修改，并且可同时有多个事务对记录加读锁.
写锁, 又称排他锁（Exclusive locks，简称 X 锁）, 或独占锁，对记录加了排他锁之后, 只有拥有该锁的事务可以读取和修改, 其他事务都不可以读取和修改, 并且同一时间只能有一个事务加写锁.

Innodb下行锁类型

Innodb行锁类型解释

记录锁（Record Locks）, 行级锁, 也就是所谓的行锁，锁定的是索引记录，行锁就是索引记录锁. 间隙锁（Gap Locks），行级锁，RR特有, gap锁加在指定索引值前面的间隙，通常是对第一个不满足条件的索引值加gap锁。 下一键锁（Next-Key Locks），行级锁，RR特有, 是特殊的gap锁，是索引值record锁和gap锁的合体。

特殊锁

插入意向锁（Insert Intention Locks），行级锁，RR特有, 是一种特殊的间隙锁（所以有的地方把它简写成 II GAP），这个锁表示插入的意向，只有在 INSERT 的时候才会有这个锁。注意，这个锁虽然也叫意向锁，本质依旧是间隙锁

信息解读

在事务(1)中, 执行SQL为更新操作, update student SET school = “清华” WHERE ( name = ‘小明’ ) 等待锁 name对应索引行值为name_age的写锁 也就是lock_mode X

在事务(2)中, 执行SQL为插入操作, insert into student (XXXXXXXXXXXXXXXXXXXXXXXX)
持有锁 HOLDS THE LOCK(S): name对应索引行值为name_age的记录锁写锁 lock_mode X locks rec but not gap
等待锁 WAITING FOR THIS LOCK TO BE GRANTED: 在插入意向锁之前等待间隙锁写锁释放 及lock_mode X locks gap before rec insert intention waiting

最终由于事务(1)权重小我们进行了回滚操作

4. 问题定位

这里我们事先在数据库中先插入两条现有数据

insert student(name, age, school) values("test1", 10, "value1");
insert student(name, age, school) values("test10", 10, "value2");

模拟线上数据库执行操作

这里分别列举了2种情况, 去描述数据中的执行操作

4.1 对比结果

为什么明明一样的执行顺序, 在name字段值不一样的情况下结果不一致呢？

• 核心概念1: Next-key Lock优化机制, 当查询的索引含有唯一属性时 Next-Key Lock进行优化，将其降级为Record Lock
• 核心概念2: Next-key Lock加锁顺序分为两步, 第一步加间隙锁, 第二步加行锁
• 核心概念3: 插入意向锁（Insert Intention Locks）是一种特殊的间隙锁, 在插入时判断是否有和插入意向锁冲突的锁, 如果有, 加插入意向锁, 进入锁等待；如果没有, 直接写数据, 不加任何锁

4.2 解读试验结果

当建表student时, 默认数据都如下：

情况1:

• 事务1: 执行SQL插入第一条 name = test15时 判断是否和插入意向锁(test10, 10) ~ (+∞)存在冲突, 没有那么直接插入数据, 获得(test15, 10)这一行的写锁
• 事务2: 执行SQL更新 修改name = test15的记录shcool为’XX’, 尝试获取Next-key, 此时由于where条件中只有name并不满足唯一索引条件不进行优化, 先尝试获取间隙锁(test10, 10) ~ (test15, 10)获取成功, 获取(test15, 10)这行的行锁时发现被事务1占住那么blocked住
• 事务1: 执行SQL插入第二条 name = test16时 判断是否和插入意向锁(test15, 10) ~ (+∞)存在冲突, 没有那么直接插入数据, 获得(test16, 10)这一行的写锁
• 事务3执行SQL更新 修改name = test16的记录 等同与事务2 获得(test15, 10) ~ ((+∞))间隙锁, 被(test16, 10)行锁blocked住
• 事务1: 提交释放行锁 事务2 3: 获得行锁执行成功

情况2

• 事务1: 执行SQL插入第一条 name = test15时 判断是否和插入意向锁(test10, 10) ~ (+∞)存在冲突, 没有那么直接插入数据, 获得(test15, 10)这一行的写锁
• 事务2: 执行SQL更新 修改name = test15的记录shcool为’XX’, 尝试获取Next-key, 此时由于where条件中只有name并不满足唯一索引条件不进行优化, 先尝试获取间隙锁(test10, 10) ~ (test15, 10)获取成功, 获取(test15, 10)这行的行锁时发现被事务1占住那么blocked住
• 事务1: 执行SQL插入第二条 name = test14时 判断是否和插入意向锁(test10, 10) ~ (test15, 10)存在冲突, 此时发现事务2占有间隙锁, 那么需要加插入意向锁, 此时进入锁等待, Innodb发现事务1与事务2存在死锁关系, 由于事务2权重小直接回滚释放间隙锁, 事务1加插入意向锁成功, 插入数据(test14, 10)
• 事务3: 执行SQL更新 修改name = test14记录, 尝试获取Next-key, 此时由于where条件中只有name并不满足唯一索引条件不进行优化, 先尝试获取间隙锁(test10, 10) ~ (test14, 10)获取成功, 获取(test14, 10)这行的行锁时发现被事务1占住那么blocked住
• 事务1: 提交释放行锁
• 事务3: 获得行锁执行成功

5.结论

在使用where条件时, 由于没有使用联合唯一索引, 导致了Next-key Lock没有进行优化降级为Record Lock, Next-key Lock的加锁顺序分为两步, 第一步加间隙锁, 第二步加行锁, 在成功执行完第一步后, bolcked在第二步, 导致了与之后的插入意向锁产生了冲突, 从而造成两个事务相互等待产生了死锁。