记录一次mysql死锁

公司在做活动时有一个抽奖发红包的功能，老大告诉我线上日志出现了死锁信息，吓我一跳。

紧急查看代码，问了下线上人数。代码没看出什么问题，几个月了也做过几次活动，也没出现过，线上也就400-500人， 以前几千人上线都过来了。

原因猜测：

　　1、mysql压力过大，毕竟开源软件bug也不少；

       2、代码逻辑过于复杂，某个地方写错了；

      3、都是经验不丰富的程序员，使用的spring框架，事务嵌套足有10层，可能是哪里顺序没搞对。

解决方法：

  1、找出线上日志，这个死锁异常大多如下，几百人上来怎么也有几千个请求，这个异常出现的频率并不高，不超过10个，分析是高并发引起的，大多出现在活动开始的10分钟内

　　

 2、业务代码有些复杂，一步步分析太慢，定位到引发异常的位置

if(奖品已经发放过 > 0) {            
    throw new ...Exception("红包发放已经处理");
}

Entity record = new Entity();

do someting...
//保存红包记录
repository.save(record);
repository.flush();

网上查询到mysql并发时如果对记录先拿到共享锁，然后再插入时要再去加排它锁时要先等待共享锁释放，猜测是不是这里先count了再insert时出现了死锁

因此新建一张表

CREATE TABLE `gs_test` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL,
  `me_id` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `uk_me` (`me_id`),
  CONSTRAINT `uk_me` FOREIGN KEY (`me_id`) REFERENCES `test_me` (`id`)
)

//先count一下锁住表记录
long count = gsTestRepository.count();
GsTest n = new GsTest();
n.setName("sds");
//插入记录
gsTestRepository.save(n);
gsTestRepository.flush();    

使用jmeter进行压测，1000个线程并发也没出现死锁，郁闷。。。

此时灵光一现，业务表里面还有一个外键字段，在这段代码执行前还有代码对这个外键记录进行了更新，他们都在同一个事务中，猜想是否存在外键锁(对mysql锁机制不熟，只能瞎猜)，再新建一个表，原来表里面加一个外键

CREATE TABLE `gs_test` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL,
  `me_id` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `uk_me` (`me_id`),
  CONSTRAINT `uk_me` FOREIGN KEY (`me_id`) REFERENCES `test_me` (`id`)
)；
CREATE TABLE `test_me` (
  `id` int(255) NOT NULL AUTO_INCREMENT,
  `name` varchar(255) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
  PRIMARY KEY (`id`)
)

service代码改为

TestMe m1 = testMeRepository.findById(1).get();

m1.setName("" + new Random().nextInt());
        this.testMeRepository.saveAndFlush(m1);

        GsTest n = new GsTest();
        n.setName("sds");
        n.setMeId(1);
        this.gsTestRepository.save(n);
        this.gsTestRepository.flush();

再次压测，Deadlock的出现令我泪流满面，自己好聪明。

本以为事情到这里就结束了，然而在saveAndFlush父表的时候应该会加上排它锁，应该会阻塞在这里，后面不应该会死锁，然而线上的日志显示仍然到了下面。

网上找到一个好命令show engine innodb status来找mysql的事务引擎日志，结果发现死锁

LATEST DETECTED DEADLOCK
------------------------
2019-06-26 17:20:47 0x4ca8
*** (1) TRANSACTION:
TRANSACTION 859473, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 233, OS thread handle 8584, query id 2889659 localhost 127.0.0.1 root updating
update test_me set name='1971272098' where id=1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3702 page no 4 n bits 72 index PRIMARY of table `gs`.`test_me` trx id 859473 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 0000000d1d49; asc      I;;
 2: len 7; hex 02000002511803; asc     Q  ;;
 3: len 10; hex 2d383631383338363936; asc -861838696;;

*** (2) TRANSACTION:
TRANSACTION 859472, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
5 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 227, OS thread handle 19624, query id 2889667 localhost 127.0.0.1 root updating
update test_me set name='669576346' where id=1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 3702 page no 4 n bits 72 index PRIMARY of table `gs`.`test_me` trx id 859472 lock mode S locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 0000000d1d49; asc      I;;
 2: len 7; hex 02000002511803; asc     Q  ;;
 3: len 10; hex 2d383631383338363936; asc -861838696;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3702 page no 4 n bits 72 index PRIMARY of table `gs`.`test_me` trx id 859472 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 0000000d1d49; asc      I;;
 2: len 7; hex 02000002511803; asc     Q  ;;
 3: len 10; hex 2d383631383338363936; asc -861838696;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------

上面出现死锁是在对父表进行更新的时候，那么也就不是外键直接引发的死锁， 分析日志发现是3个事务同时在select后拿到了 X锁，其中一个事务拿到了S锁，但同时要等待其他事务释放X锁，其他事务在获取S锁的时候又要等待这个事务释放S锁，结果出现死锁。

查询线上的这个日志也发现死锁并不是jvm的异常出现位置(insert字表), 而是在外部事务中insert一个父表的时候。

结论分析：

学好mysql锁对并发编程大有裨益，不能完全相信jvm的日志，使用mysql就要学会看mysql的日志，否则只能是无头苍蝇乱撞。