mysql deadlock log_MYSQL:1213 Deadlock问题排查历程

mark下自己近期在电商开发中遇到的一个问题－数据库死锁及其排查过程。

先抛一个业务报错日志做为这次梳理的开始

上图是我接收到的错误报警，SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction，错误信息显示我们业务中有一条数据库操作遇到了死锁情况。接下来就开始我们的追查之旅。

1.执行“show engine innodb status”获取INNODB引擎当前信息(show engine innodb status 详细介绍)

------------------------

LATEST DETECTED DEADLOCK

------------------------

2017-01-04 09:25:17 7f553477d700

*** (1) TRANSACTION:

TRANSACTION 124378994, ACTIVE 0.007 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 4 lock struct(s), heap size 1184, 8 row lock(s), undo log entries 7

LOCK BLOCKING MySQL thread id: 11573556 block 11572504

MySQL thread id 11572504, OS thread handle 0x7f56342fb700, query id 3368968901 10.44.182.0 shzfstore updating

UPDATE `sku` SET `quantity`=quantity-'1',`lock_stock`=lock_stock+'1',`sys_version`=sys_version+1 WHERE `id` = '15608' AND `quantity` >= '1' limit 1

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 393 page no 45 n bits 248 index `PRIMARY` of table `store_product`.`sku` trx id 124378994 lock_mode X locks rec but not gap waiting

Record lock, heap no 19 PHYSICAL RECORD: n_fields 19; compact format; info bits 0

......

*** (2) TRANSACTION:

TRANSACTION 124378995, ACTIVE 0.004 sec starting index read

mysql tables in use 1, locked 1

3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1

MySQL thread id 11573556, OS thread handle 0x7f553477d700, query id 3368968902 10.172.221.117 shzfstore updating

UPDATE `sku` SET `quantity`=quantity-'1',`lock_stock`=lock_stock+'1',`sys_version`=sys_version+1 WHERE `id` = '15504' AND `quantity` >= '1' limit 1

*** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 393 page no 45 n bits 248 index `PRIMARY` of table `store_product`.`sku` trx id 124378995 lock_mode X locks rec but not gap

Record lock, heap no 19 PHYSICAL RECORD: n_fields 19; compact format; info bits 0

......

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 393 page no 43 n bits 240 index `PRIMARY` of table `store_product`.`sku` trx id 124378995 lock_mode X locks rec but not gap waiting

Record lock, heap no 81 PHYSICAL RECORD: n_fields 19; compact format; info bits 0

......

*** WE ROLL BACK TRANSACTION (2)

LATEST DETECTED DEADLOCK记录了最近一次的死锁情况。

2017-01-04 09:25:17时间跟我们接收到的报错日志时间吻合。

上面还可以看出两个事务之间发生锁竞争时，给我们留下的部分数据

事务1

UPDATEskuSETquantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHEREid= '15608' ANDquantity>= '1' limit 1

事务2

UPDATEskuSETquantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHEREid= '15504' ANDquantity>= '1' limit 1

死锁的两个资源均被lock_mode X locks了

最后，mysql给了很重要的一个数据“WE ROLL BACK TRANSACTION (2)” MYSQL回滚了事务2。既然mysql回滚了事务2，那么肯定是事务2的语句触发了死锁，被mysql回滚了，也就是应该为报错日志所记录的那部分。同时，MYSQL执行了事务1，那么事务1的SQL语句肯定被记录在BINLOG中了。

2.查看binlog日志，找出事务1所执行的语句

查找依据：

SQL语句,根据LATEST DETECTED DEADLOCK提供的死锁时记录的sql语句。

线程ID(mysql的唯一标识): MySQL thread id 11572504

执行时间(时间线):2017-01-04 09:25:17 7f553477d700

根据以上三个标识，以及BINLOG的起始标志“BEGIN、COMMIT”，几乎可以100%确定事务1所包含的SQL语句。

binlog信息大致如下

#170104 9:25:17 server id 3194178605 end_log_pos 137170469 CRC32 0x1b6559de Query thread_id=11572504 exec_time=0 error_code=0

SET TIMESTAMP=1483493117/*!*/;

BEGIN

......

### UPDATE `store_product`.`sku`

### WHERE

### @1=15504

### @2=11516

### @3=0.01

### @4=120065

### @5=109433

### @6=19

### SET

### @1=15504

### @2=11516

### @3=0.01

### @4=120065

### @5=109432

### @6=20

# at 137172557

......

### UPDATE `store_product`.`sku`

### WHERE

### @1=15608

### @2=11551

### @3=0.01

### @4=120077

### @5=109426

### @6=19

### SET

### @1=15608

### @2=11551

### @3=0.01

### @4=120077

### @5=109425

### @6=20

......

COMMIT/*!*/;

3.还原事务2所包含的执行语句

事务1的语句找齐了，接下来找事务2的语句，还记得我们开头提供的报错日志吗，那个日志里也详细记录了发起请求时的参数情况(截图未展示)，根据参数和我们处理业务的代码，可以复现事务2所要执行的语句

BEGIN

......

### UPDATE `store_product`.`sku`

### WHERE

### @1=15608

### @2=11516

### @3=0.01

### @4=120065

### @5=109433

### @6=19

### SET

### @1=15608

### @2=11516

### @3=0.01

### @4=120065

### @5=109432

### @6=20

......

### UPDATE `store_product`.`sku`

### WHERE

### @1=15504

### @2=11551

### @3=0.01

### @4=120077

### @5=109426

### @6=19

### SET

### @1=15504

### @2=11551

### @3=0.01

### @4=120077

### @5=109425

### @6=20

......

COMMIT/*!*/;

根据两个事务所执行的sql语句，目前可以还原死锁产生的原因了

4.查看两个事务执行语句的顺序：

顺序

事务1

事务2

说明

1

begin

2

begin

3

UPDATE sku

SET quantity=quantity-'1',

lock_stock=lock_stock+'1',

sys_version=sys_version+1

WHERE id = '15504' AND

quantity >= '1' limit 1

事务1 给 sku表 id 15504记录上 X 锁

4

UPDATE sku

SET quantity=quantity-'1',

lock_stock=lock_stock+'1',

sys_version=sys_version+1

WHERE id = '15608' AND

quantity >= '1' limit 1

事务2 给 sku表 id 15608记录上 X 锁

5

UPDATE sku

SET quantity=quantity-'1',

lock_stock=lock_stock+'1',

sys_version=sys_version+1 WHERE id = '15608' AND

quantity >= '1' limit 1

这里是关键，事务1想给sku表 id 15608上X锁，发现被别人(事务2)上锁了，等待锁释放

6

UPDATE sku

SET quantity=quantity-'1',

lock_stock=lock_stock+'1',

sys_version=sys_version+1

WHERE id = '15504' AND

quantity >= '1' limit 1

事物2打算给sku表id为15504记录上 X 排它锁，发现被其他事务上了，而且此事务居然还在等他提交，这时MYSQL立刻回滚事务2…(php发现MYSQL返回死锁信息，记录该信息到错误日志…发送回滚指令…mysql已经“帮”他回滚了…)

7

执行成功

事务1发现别人的锁释放了，获得X锁，执行成功

8

commit

事务1执行成功，记录binlog日志

解决方案

减小事务中的语句数量

在业务中调整语句的执行顺序，例如可以按照where条件中字段的大小进行一下排序，按照排序后顺序执行，让死锁变为锁等待。

相关补充

innodb的行锁，锁的是查询条件中的索引字段，以及索引字段对应的primary key字段