现象

压测过程中游戏server端出现错误日志：

2020/06/23 12:00:14 [error] 546#0: *24612413 FastCGI sent in stderr: "PHP message: [500] /api/v2/item/ext_exchange SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction, query was: DELETE FROM `UserExpirationItem_p33` WHERE (id IN (106085, 106131, 106144, 106143, 106142, 106141, 106140, 106145, 106138, 106129, 106147, 106130, 106128, 106127, 106132, 106133, 106134, 106084, 106146, 106137, 106125, 106102, 106083, 106148, 104660, 106151, 106152, 106155, 106154, 106153, 106156, 106139, 106157, 106159, 106149, 106168, 106101, 106150, 106103, 196593, 196592, 196591, 196590, 196617, 196602, 196589, 196619, 196595, 196594, 196604, 196596, 196597, 196598, 196599, 196600, 196601, 196603, 196616, 196605, 196606, 196644, 196645, 196625, 196643, 196630, 196620, 196621, 196622, 196623, 196624, 196608, 196626, 196627, 196628, 196629, 196631, 196642, 196633, 196618, 196634, 196635, 196636, 196637, 196638, 196639, 196640, 196641, 196607, 196448, 196609, 196437, 196457, 196458, 196459, 196460, 196461, 196462, 196463, 196464," while reading response header from upstreamt ......"

显然程序出现mysql死锁了。

原因分析

1、 找到死锁更多信息

使用语句：show engine innodb status

上面语句输出内容太多，输出到文件：

mysql -u aetes_dev -h your_ip -p --execute="show engine innodb status \G" > ./mysql.log

more命令查看到如下内容：

*** (1) TRANSACTION:

TRANSACTION 13096646, ACTIVE 9 sec fetching rows

mysql tables in use 1, locked 1

LOCK WAIT 32 lock struct(s), heap size 3520, 3342 row lock(s), undo log entries 6601

MySQL thread id 688878, OS thread handle 140313170929408, query id 46108164 10.80.18.12 aetes_dev updating

DELETE FROM `UserExpirationItem_p04` WHERE (id IN (188838, 188847, 188841, 188842, 188862, 188843, 188844, 188845, 188846, 188849, 188863, 188854, 188856

, 188858, 188859, 188860, 188861, 188850, 188962, 188848, 188840, 188951, 188956, 188865, 188868, 188873, 188910, 188912, 188952, 188953, 188950, 188954,

188957, 188958, 188959, 188960, 188961, 188963, 188864, 188964, 202869, 202839, 202841, 202870, 202864, 202868, 202867, 202866, 202807, 202865, 202815,

202822, 202808, 202809, 202810, 202811, 202812, 202813, 202814, 202816, 202817, 202862, 202863, 202842, 202861, 202848, 202804, 202806, 202871, 202855, 2

02819, 202843, 202844, 202845, 202846, 202847, 202849, 202860, 202850, 202851, 202852, 202853, 202854, 202856, 202840, 202857, 202858, 202859, 202818, 20

3538, 202820, 204251, 204241, 204242, 204243, 204244, 204245, 204246, 204247, 204249, 204233, 204250, 204252, 204239, 204253, 204254, 204255, 204256, 2

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

RECORD LOCKS space id 9016 page no 59 n bits 368 index PRIMARY of table `alice_user_04`.`UserExpirationItem_p04` trx id 13096646 lock_mode X locks rec but not gap waiting

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

0: len 8; hex 00000000000323d0; asc # ;;

1: len 6; hex 000000c7d802; asc ;;

2: len 7; hex e3000001fe0110; asc ;;

3: len 4; hex 3b9accc0; asc ; ;;

4: len 4; hex cf34b4c3; asc 4 ;;

5: len 1; hex 00; asc ;;

6: len 5; hex 99a72cde5e; asc , ^;;

7: len 5; hex 99a6aede5e; asc ^;;

8: len 5; hex 99a6aede5e; asc ^;;

*** (2) TRANSACTION:

TRANSACTION 13096962, ACTIVE 6 sec fetching rows

mysql tables in use 1, locked 1

21 lock struct(s), heap size 3520, 3 row lock(s), undo log entries 3301

MySQL thread id 688901, OS thread handle 140313175684864, query id 46108334 10.80.18.12 aetes_dev updating

DELETE FROM `UserExpirationItem_p04` WHERE (id IN (192012, 190613, 191994, 191995, 191996, 192002, 191998, 191983, 191988, 191981, 191975, 192001, 191949

, 191982, 191950, 191971, 191973, 191974, 191997, 191976, 191978, 191979, 191980, 192006, 191993, 191977, 191992, 192254, 191990, 192008, 192009, 192010,

192011, 192204, 192092, 192094, 192197, 192198, 192007, 191999, 191985, 192004, 191987, 191986, 191989, 191984, 191991, 192003, 192000, 192005, 206041,

206082, 206083, 206084, 206085, 206086, 206059, 206057, 206088, 206081, 206032, 206028, 206029, 206030, 206031, 206033, 206034, 206035, 206036, 206037, 2

06038, 206080, 206039, 206068, 206079, 206065, 206042, 206153, 206151, 206027, 206072, 206060, 206061, 206062, 206063, 206064, 206066, 206078, 206067, 20

6069, 206070, 206071, 206073, 206058, 206074, 206075, 206076, 206077, 206040, 206130, 206056, 206143, 206133, 206134, 206136, 206121, 206137, 206138, 2

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

RECORD LOCKS space id 9016 page no 59 n bits 368 index PRIMARY of table `alice_user_04`.`UserExpirationItem_p04` trx id 13096962 lock_mode X locks rec but not gap waiting

说明：

1) 从php错误日志和mysql查询到的数据都说明是执行一个delete from UserExpirationItem_p04 where id in(…)的语句出现死锁了，这里where in后面的数据还比较多，导致没有打印完整。

2) delete where id in后面怎么会有这么多id？

3) id是主键字段，delete 语句实际是1条读加1条写的复合操作，理论上应该是加的行锁(X锁)，是否是因为存在重复id导致死锁？

2、 结合代码分析

找到/api/v2/item/ext_exchange具体执行逻辑：

1) 将玩家gacha_point全部兑换掉；测试玩家身上每次登陆会发送一种能兑换ticket_001_01的道具的属性gacha_point 330000点，100点能兑换一个ticket_001_01

2) 添加3300个ticket_001_01道具到玩家背包中，ticket_001_01是不可重叠有过期时间的道具，即对应UserExpirationItem类型；添加前有个上限检查逻辑：计算删除的旧道具数量 = 当前拥有数+这次添加数量-最大上限数，由于上限数是50这里算出需要删除数量是3250，所以相当于delete where in后面有3000多个id，这与日志不完整吻合，解释了问题2)。

这里删除逻辑是：先添加道具，后找到需要删除的道具id，进行批量删除(前面的计算看不懂没问题，重点在这个删除)

批量删除函数：

将所有id放到in后面里中，调用一次delete。

综上逻辑实际发现调用接口都是根据用户id添加自己的道具，删除自己的超出数量道具，并不会出现id重复情况，那为什么会出现死锁呢？猜测原因：

delete语句后面id过多，导致没有使用到索引，直接全表扫描发生表级锁进而导致的死锁？

构造一个3000多id的delete语句，使用explain查看执行计划：

从上图看出扫描行数接近全表数量，基本可以看出是全表扫描了，可以论断猜测。

解决办法

delete where in 效率本身不高，不建议并发使用，2种解决办法：

1) 统一改成delete where id=，保证每次走索引，发生行锁；但是会造成需要执行大量条sql的情况；

2) 将id分批，保证1批where in后面的id数据较少；

显然第2种方法更合适，将in后面的id拆分批次处理(每次100个)，最终代码如下：

修改后相同环境重新测试多次没有再出现死锁报错情况，说明死锁问题得以解决。