IT评测·应用市场-qidao123.com

标题: MYSQL批量插入并发场景下的DEADLOCK [打印本页]
作者: 灌篮少年    时间: 2023-11-18 11:08
标题: MYSQL批量插入并发场景下的DEADLOCK
一、背景

公元2023-10-12(周四)上午，组内的亚梅反馈，用户生成标签报死锁异常

 
 
二、排查异常日志

查到当时报错的日志

 
具体异常信息如下
  1. server-provider-info-2023-10-12.0.log:2023-10-12 09:40:50.593 [TID:bf623bded189486cbb0b6a64d81b64b4.357.16970748504097047] [4ed7b7943a8a47de912e4b644d70285e] [SimpleAsyncTaskExecutor-5080] INFO  com.emax.user.user.provider.UserTagAPIImpl:? - 签约完成，更新用户标签信息异常，用户id[1712282059297107970]org.apache.ibatis.exceptions.PersistenceException:
  2. server-provider-info-2023-10-12.0.log-### Error flushing statements.  Cause: org.apache.ibatis.executor.BatchExecutorException: com.emax.user.user.mapper.UserTagMapper.insert (batch index #1) failed. Cause: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
  3. server-provider-info-2023-10-12.0.log-### Cause: org.apache.ibatis.executor.BatchExecutorException: com.emax.user.user.mapper.UserTagMapper.insert (batch index #1)failed. Cause: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
  4. server-provider-info-2023-10-12.0.log-  at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
  5. server-provider-info-2023-10-12.0.log-  at org.apache.ibatis.session.defaults.DefaultSqlSession.flushStatements(DefaultSqlSession.java:254)
  6. server-provider-info-2023-10-12.0.log-  at com.baomidou.mybatisplus.extension.service.impl.ServiceImpl.saveBatch(ServiceImpl.java:127)
  7. server-provider-info-2023-10-12.0.log-  at com.baomidou.mybatisplus.extension.service.IService.saveBatch(IService.java:58)
  8. server-provider-info-2023-10-12.0.log-  at com.baomidou.mybatisplus.extension.service.IService$$FastClassBySpringCGLIB$$f8525d18.invoke(<generated>)
  9. server-provider-info-2023-10-12.0.log-  at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
  10. server-provider-info-2023-10-12.0.log-  at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)
  11. server-provider-info-2023-10-12.0.log-  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
  12. server-provider-info-2023-10-12.0.log-  at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:294)
  13. server-provider-info-2023-10-12.0.log-  at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
  14. server-provider-info-2023-10-12.0.log-  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
  15. server-provider-info-2023-10-12.0.log-  at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
  16. server-provider-info-2023-10-12.0.log-  at com.emax.user.user.service.UserTagManager$$EnhancerBySpringCGLIB$$67ca0067.saveBatch(<generated>)
  17. server-provider-info-2023-10-12.0.log-  at com.emax.user.user.provider.UserTagAPIImpl.addUserTagByUser(UserTagAPIImpl.java:236)
  18. server-provider-info-2023-10-12.0.log-  at com.emax.user.user.provider.UserTagAPIImpl.addTagAfterSign(UserTagAPIImpl.java:116)
  19. server-provider-info-2023-10-12.0.log-  at com.emax.user.user.provider.UserTagAPIImpl$$FastClassBySpringCGLIB$$2547ce26.invoke(<generated>)
  20. server-provider-info-2023-10-12.0.log-  at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
  21. server-provider-info-2023-10-12.0.log-  at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)
  22. --
  23. server-provider-info-2023-10-12.0.log-  at io.seata.rm.datasource.StatementProxy.lambda$executeBatch$9(StatementProxy.java:129)
  24. server-provider-info-2023-10-12.0.log-  at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:73)
  25. server-provider-info-2023-10-12.0.log-  at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:51)
  26. server-provider-info-2023-10-12.0.log-  at io.seata.rm.datasource.StatementProxy.executeBatch(StatementProxy.java:129)
  27. server-provider-info-2023-10-12.0.log-  at sun.reflect.GeneratedMethodAccessor1346.invoke(Unknown Source)
  28. server-provider-info-2023-10-12.0.log-  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  29. server-provider-info-2023-10-12.0.log-  at java.lang.reflect.Method.invoke(Method.java:498)
  30. server-provider-info-2023-10-12.0.log-  at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:78)
  31. server-provider-info-2023-10-12.0.log-  at com.sun.proxy.$Proxy501.executeBatch(Unknown Source)
  32. server-provider-info-2023-10-12.0.log-  at com.baomidou.mybatisplus.core.executor.MybatisBatchExecutor.doFlushStatements(MybatisBatchExecutor.java:132)
  33. server-provider-info-2023-10-12.0.log-  ... 71 common frames omitted
  34. server-provider-info-2023-10-12.0.log-Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
  35. server-provider-info-2023-10-12.0.log-  at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123)
  36. server-provider-info-2023-10-12.0.log-  at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
  37. server-provider-info-2023-10-12.0.log-  at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
  38. server-provider-info-2023-10-12.0.log-  at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:970)
  39. server-provider-info-2023-10-12.0.log-  at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1109)
  40. server-provider-info-2023-10-12.0.log-  at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchSerially(ClientPreparedStatement.java:849)
  41. server-provider-info-2023-10-12.0.log-  ... 89 common frames omitted
  42. server-provider-info-2023-10-12.0.log-
复制代码
 
三、代码所在地

查看发生Deadlock的代码现场。
代码如下：
  1.     /**
  2.      * 增加用户标签
  3.      * @param user 用户信息
  4.      * @param tagNameList 标签集合
  5.      */
  6.     private void addUserTagByUser(User user, List<String> tagNameList){
  7.         log.info("用户添加标签入参信息，当前用户id[{}]，标签信息[{}]", user.getUserId(), JSON.toJSONString(tagNameList));
  8.         Set<String> existTags = new HashSet<>();
  9.         final List<UserTag> userTagList = userTagManager.listUserTagByUserId(user.getUserId());
  10.         if(CollectionUtils.isNotEmpty(userTagList)){
  11.             existTags = userTagList.stream().map(UserTag::getTagName).collect(Collectors.toSet());
  12.         }
  13.         //遍历合集 如果不存在旧数据 直接都新增 存在 判断当前数据是否在旧数据中
  14.         List<UserTag> newInsertList = new ArrayList<>();
  15.         for(String name : tagNameList){
  16.             if (StringUtils.isNotBlank(name) && existTags.add(name)) {
  17.                 newInsertList.add(userTagManager.buildEntity(user.getUserId(), user.getIdcardNo(), name));
  18.             }
  19.         }
  20.         userTagManager.saveBatch(newInsertList);
  21.     }
复制代码
 
观察代码，大致逻辑是，先根据用户id查询出所有标签信息，计算出来需要新增的用户标签，批量入库。其中，user_tag表存储用户的标签数据。两个关键字段 user_id（用户id）和tag_name（标签）上面具有唯一索引，插入的数据也主要是这两个字段。
从这段代码并不容易判断出来如何会产生死锁。推测是多个线程同时操作相同的数据，并发插入导致的死锁。
 
四、并发操作日志

elk上查询方法入参日志。果然在发生异常的时间节点上，发现了两条插入相同数据的日志。相同时间点，两个traceId，可见当时发生了并发调用。

 
找到当时另一个线程的操作日志，日志无异常，数据入库成功。见下面截图。

 
 
 
五、数据库死锁日志验证推测

当天下午上班后，找运维大哥帮忙，找出死锁日志
执行命令 show ENGINE INNODB status 
得到信息如下
  1. =====================================
  2. 2023-10-12 13:49:17 0x7fea5ae87700 INNODB MONITOR OUTPUT
  3. =====================================
  4. Per second averages calculated from the last 61 seconds
  5. -----------------
  6. BACKGROUND THREAD
  7. -----------------
  8. srv_master_thread loops: 3123131 srv_active, 0 srv_shutdown, 7715544 srv_idle
  9. srv_master_thread log flush and writes: 10838675
  10. ----------
  11. SEMAPHORES
  12. ----------
  13. OS WAIT ARRAY INFO: reservation count 3905404
  14. OS WAIT ARRAY INFO: signal count 27617015
  15. RW-shared spins 0, rounds 21456656, OS waits 2772950
  16. RW-excl spins 0, rounds 41132727, OS waits 487320
  17. RW-sx spins 227170, rounds 4363782, OS waits 66152
  18. Spin rounds per wait: 21456656.00 RW-shared, 41132727.00 RW-excl, 19.21 RW-sx
  19. ------------------------
  20. LATEST DETECTED DEADLOCK
  21. ------------------------
  22. 2023-10-12 09:40:50 0x7fecedb1e700
  23. *** (1) TRANSACTION:
  24. TRANSACTION 404898333, ACTIVE 0 sec inserting
  25. mysql tables in use 1, locked 1
  26. LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
  27. MySQL thread id 11375251, OS thread handle 140644580488960, query id 1031478425 10.128.0.160 emax_base update
  28. INSERT INTO emax_user_tag  ( user_id,
  29. id_card_no,
  30. tag_name,
  31. create_time,
  32. update_time )  VALUES  ( 1712282059297107970,
  33. 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9',
  34. '市场推广',
  35. '2023-10-12 09:40:50.481',
  36. '2023-10-12 09:40:50.481' )
  37. *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
  38. RECORD LOCKS space id 1155 page no 65295 n bits 312 index uniq_user_id_tag_name of table `emax_base`.`emax_user_tag` trx id 404898333 lock mode S waiting
  39. Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  40. 0: len 8; hex 97c33f75fbadb002; asc   ?u    ;;
  41. 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc             ;;
  42. 2: len 8; hex 000000000044c0da; asc      D  ;;
  44. *** (2) TRANSACTION:
  45. TRANSACTION 404898332, ACTIVE 0 sec inserting
  46. mysql tables in use 1, locked 1
  47. 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
  48. MySQL thread id 11375224, OS thread handle 140655576868608, query id 1031478426 10.128.0.160 emax_base update
  49. INSERT INTO emax_user_tag  ( user_id,
  50. id_card_no,
  51. tag_name,
  52. create_time,
  53. update_time )  VALUES  ( 1712282059297107970,
  54. 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9',
  55. '信息技术服务',
  56. '2023-10-12 09:40:50.481',
  57. '2023-10-12 09:40:50.481' )
  58. *** (2) HOLDS THE LOCK(S):
  59. RECORD LOCKS space id 1155 page no 65295 n bits 312 index uniq_user_id_tag_name of table `emax_base`.`emax_user_tag` trx id 404898332 lock_mode X locks rec but not gap
  60. Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  61. 0: len 8; hex 97c33f75fbadb002; asc   ?u    ;;
  62. 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc             ;;
  63. 2: len 8; hex 000000000044c0da; asc      D  ;;
  65. *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
  66. RECORD LOCKS space id 1155 page no 65295 n bits 312 index uniq_user_id_tag_name of table `emax_base`.`emax_user_tag` trx id 404898332 lock_mode X locks gap before rec insert intention waiting
  67. Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  68. 0: len 8; hex 97c33f75fbadb002; asc   ?u    ;;
  69. 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc             ;;
  70. 2: len 8; hex 000000000044c0da; asc      D  ;;
  72. *** WE ROLL BACK TRANSACTION (1)
  73. <br>此处省略掉若干非关键信息行
  74. ----------------------------
  75. END OF INNODB MONITOR OUTPUT
  76. ============================
复制代码
 
该日志信息量很多，已省略掉若干非关键信息行，我们主要关注最后一次死锁相关信息。
六、死锁复现

sql准备
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '市场推广', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' );
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '信息技术服务', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' );
本地创建一个和生产一样的数据库emax_user_tag，同样，在user_id和tag_name两个字段上创建唯一索引。
 
操作步骤1

在窗口一执行
begin;
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '市场推广', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' );
 
操作步骤2

在窗口二执行
begin;
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '市场推广', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' );
 
操作步骤3

在窗口一执行
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '信息技术服务', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' );
commit;
 
操作步骤4

切回窗口二
 
操作步骤5

执行命令 show ENGINE INNODB status 查看死锁日志。与上面的情况一样。
  1. =====================================
  2. 2023-10-13 14:52:43 0x7fe759575700 INNODB MONITOR OUTPUT
  3. =====================================
  4. Per second averages calculated from the last 24 seconds
  5. -----------------
  6. BACKGROUND THREAD
  7. -----------------
  8. srv_master_thread loops: 137590 srv_active, 0 srv_shutdown, 2010475 srv_idle
  9. srv_master_thread log flush and writes: 2148065
  10. ----------
  11. SEMAPHORES
  12. ----------
  13. OS WAIT ARRAY INFO: reservation count 6627679
  14. OS WAIT ARRAY INFO: signal count 14339066
  15. RW-shared spins 0, rounds 22104735, OS waits 1859432
  16. RW-excl spins 0, rounds 258795010, OS waits 2238669
  17. RW-sx spins 6551822, rounds 136672247, OS waits 1786313
  18. Spin rounds per wait: 22104735.00 RW-shared, 258795010.00 RW-excl, 20.86 RW-sx
  19. ------------------------
  20. LATEST DETECTED DEADLOCK
  21. ------------------------
  22. 2023-10-13 14:50:31 0x7fe892ad0700
  23. *** (1) TRANSACTION:
  24. TRANSACTION 293171186, ACTIVE 10 sec inserting
  25. mysql tables in use 1, locked 1
  26. LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
  27. MySQL thread id 1266048, OS thread handle 140631613069056, query id 35172347 192.168.48.179 develop update
  28. /* ApplicationName=DBeaver 22.2.1 - SQLEditor <Script-4.sql> */ INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '市场推广', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' )
  29. *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
  30. RECORD LOCKS space id 14171 page no 4 n bits 72 index user_id_tag_name of table `dbsyncer_mf`.`emax_user_tag` trx id 293171186 lock mode S waiting
  31. Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  32. 0: len 8; hex 97c33f75fbadb002; asc   ?u    ;;
  33. 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc             ;;
  34. 2: len 8; hex 80000000000358d0; asc       X ;;
  36. *** (2) TRANSACTION:
  37. TRANSACTION 293171182, ACTIVE 19 sec inserting
  38. mysql tables in use 1, locked 1
  39. 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
  40. MySQL thread id 1266036, OS thread handle 140636869953280, query id 35172492 192.168.48.179 develop update
  41. /* ApplicationName=DBeaver 22.2.1 - SQLEditor <Script-1.sql> */ INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', '信息技术服务', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' )
  42. *** (2) HOLDS THE LOCK(S):
  43. RECORD LOCKS space id 14171 page no 4 n bits 72 index user_id_tag_name of table `dbsyncer_mf`.`emax_user_tag` trx id 293171182 lock_mode X locks rec but not gap
  44. Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  45. 0: len 8; hex 97c33f75fbadb002; asc   ?u    ;;
  46. 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc             ;;
  47. 2: len 8; hex 80000000000358d0; asc       X ;;
  49. *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
  50. RECORD LOCKS space id 14171 page no 4 n bits 72 index user_id_tag_name of table `dbsyncer_mf`.`emax_user_tag` trx id 293171182 lock_mode X locks gap before rec insert intention waiting
  51. Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  52. 0: len 8; hex 97c33f75fbadb002; asc   ?u    ;;
  53. 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc             ;;
  54. 2: len 8; hex 80000000000358d0; asc       X ;;
  56. *** WE ROLL BACK TRANSACTION (1)
复制代码
View Code 
 
七、死锁分析

根据死锁日志进行分析。
执行操作步骤一时：
事务一   获取到了插入意向锁
执行操作步骤二时：
事务二  将事务的意向锁升级为唯一索引排他锁，并且尝试获取唯一索引共享锁（还没有获得共享锁，排队中）
执行操作步骤三时：
事务一 尝试获取插入意向间隙锁
 
事务二等待事务一释放排他锁
事务一等待事务二释放共享锁
形成相互等待关系，死锁。
八、总结归纳

 
1.批量插入操作尽量保证数据有序性
2.可借助性能更高的redis进行并发拦截 或 同步处理控制
3.将参数 innodb_deadlock_detect 设置为 on，死锁时会进行回滚（数据库默认开启）
4.业务代码需要考虑数据库异常
5.当前mysql数据库版本是5.7.28-log。经细心的红洁同学验证，mysql-8.0版本针对这个场景做了优化，不会发生死锁。
 
 
文献参考 https://blog.csdn.net/minghao0508/article/details/129093202
 

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！



欢迎光临 IT评测·应用市场-qidao123.com (https://dis.qidao123.com/) Powered by Discuz! X3.4