1. Background
On the morning of 2023-10-12 (Thursday), Yamei in the group reported that a user-generated label reported a deadlock exception.
2. Check exception logs
Find the error log reported at that time
The specific exception information is as follows
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:? - Signing completed, user tag information updated abnormally, user id[1712282059297107970]org .apache.ibatis.exceptions.PersistenceException: 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 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 server-provider-info-2023-10-12.0.log- at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30) server-provider-info-2023-10-12.0.log- at org.apache.ibatis.session.defaults.DefaultSqlSession.flushStatements(DefaultSqlSession.java:254) server-provider-info-2023-10-12.0.log- at com.baomidou.mybatisplus.extension.service.impl.ServiceImpl.saveBatch(ServiceImpl.java:127) server-provider-info-2023-10-12.0.log- at com.baomidou.mybatisplus.extension.service.IService.saveBatch(IService.java:58) server-provider-info-2023-10-12.0.log- at com.baomidou.mybatisplus.extension.service.IService$$FastClassBySpringCGLIB$$f8525d18.invoke(<generated>) server-provider-info-2023-10-12.0.log- at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) server-provider-info-2023-10-12.0.log- at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749) server-provider-info-2023-10-12.0.log- at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) server-provider-info-2023-10-12.0.log- at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:294) server-provider-info-2023-10-12.0.log- at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98) server-provider-info-2023-10-12.0.log- at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) server-provider-info-2023-10-12.0.log- at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688) server-provider-info-2023-10-12.0.log- at com.emax.user.user.service.UserTagManager$$EnhancerBySpringCGLIB$$67ca0067.saveBatch(<generated>) server-provider-info-2023-10-12.0.log- at com.emax.user.user.provider.UserTagAPIImpl.addUserTagByUser(UserTagAPIImpl.java:236) server-provider-info-2023-10-12.0.log- at com.emax.user.user.provider.UserTagAPIImpl.addTagAfterSign(UserTagAPIImpl.java:116) server-provider-info-2023-10-12.0.log- at com.emax.user.user.provider.UserTagAPIImpl$$FastClassBySpringCGLIB$$2547ce26.invoke(<generated>) server-provider-info-2023-10-12.0.log- at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) server-provider-info-2023-10-12.0.log- at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749) -- server-provider-info-2023-10-12.0.log- at io.seata.rm.datasource.StatementProxy.lambda$executeBatch$9(StatementProxy.java:129) server-provider-info-2023-10-12.0.log- at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:73) server-provider-info-2023-10-12.0.log- at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:51) server-provider-info-2023-10-12.0.log- at io.seata.rm.datasource.StatementProxy.executeBatch(StatementProxy.java:129) server-provider-info-2023-10-12.0.log- at sun.reflect.GeneratedMethodAccessor1346.invoke(Unknown Source) server-provider-info-2023-10-12.0.log- at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) server-provider-info-2023-10-12.0.log- at java.lang.reflect.Method.invoke(Method.java:498) server-provider-info-2023-10-12.0.log- at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:78) server-provider-info-2023-10-12.0.log- at com.sun.proxy.$Proxy501.executeBatch(Unknown Source) server-provider-info-2023-10-12.0.log- at com.baomidou.mybatisplus.core.executor.MybatisBatchExecutor.doFlushStatements(MybatisBatchExecutor.java:132) server-provider-info-2023-10-12.0.log- ... 71 common frames omitted 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 server-provider-info-2023-10-12.0.log- at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123) server-provider-info-2023-10-12.0.log- at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) server-provider-info-2023-10-12.0.log- at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) server-provider-info-2023-10-12.0.log- at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:970) server-provider-info-2023-10-12.0.log- at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1109) server-provider-info-2023-10-12.0.log- at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchSerially(ClientPreparedStatement.java:849) server-provider-info-2023-10-12.0.log- ... 89 common frames omitted server-provider-info-2023-10-12.0.log- |
3. Code location
View the code scene where Deadlock occurred.
code show as below:
/**
* Add user tags
* @param user user information
* @param tagNameList tag collection
*/
private void addUserTagByUser(User user, List<String> tagNameList){
log.info("User adds tag input parameter information, current user id[{}], tag information[{}]", user.getUserId(), JSON.toJSONString(tagNameList));
Set<String> existTags = new HashSet<>();
final List<UserTag> userTagList = userTagManager.listUserTagByUserId(user.getUserId());
if(CollectionUtils.isNotEmpty(userTagList)){
existTags = userTagList.stream().map(UserTag::getTagName).collect(Collectors.toSet());
}
//Traverse the collection. If the old data does not exist, add it directly. If it exists, determine whether the current data is in the old data.
List<UserTag> newInsertList = new ArrayList<>();
for(String name : tagNameList){
if (StringUtils.isNotBlank(name) & amp; & amp; existTags.add(name)) {
newInsertList.add(userTagManager.buildEntity(user.getUserId(), user.getIdcardNo(), name));
}
}
userTagManager.saveBatch(newInsertList);
}
|
Observing the code, the general logic is to first query all tag information based on the user ID, calculate the user tags that need to be added, and store them in batches. Among them, the user_tag table stores user tag data. The two key fields user_id (user id) and tag_name (tag) have unique indexes, and the inserted data is mainly these two fields.
It is not easy to tell from this code how a deadlock occurs. It is speculated that multiple threads operate the same data at the same time and concurrent insertion causes deadlock.
4. Concurrent operation log
Query method input log on elk. Sure enough, at the time node when the exception occurred, two logs inserting the same data were found. At the same time point, two traceIds show that concurrent calls occurred at that time.
I found the operation log of another thread at that time. There was no exception in the log and the data was successfully entered into the database. See screenshot below.
5. Database deadlock log verification speculation
After going to work that afternoon, I asked the operation and maintenance brother for help to find the deadlock log.
Execute the command show ENGINE INNODB status
The information obtained is as follows
==================== ================== 2023-10-12 13:49:17 0x7fea5ae87700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 61 seconds ------------------ BACKGROUND THREAD ------------------ srv_master_thread loops: 3123131 srv_active, 0 srv_shutdown, 7715544 srv_idle srv_master_thread log flush and writes: 10838675 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 3905404 OS WAIT ARRAY INFO: signal count 27617015 RW-shared spins 0, rounds 21456656, OS waits 2772950 RW-excl spins 0, rounds 41132727, OS waits 487320 RW-sx spins 227170, rounds 4363782, OS waits 66152 Spin rounds per wait: 21456656.00 RW-shared, 41132727.00 RW-excl, 19.21 RW-sx -------------------------- LATEST DETECTED DEADLOCK -------------------------- 2023-10-12 09:40:50 0x7fecedb1e700 *** (1) TRANSACTION: TRANSACTION 404898333, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 11375251, OS thread handle 140644580488960, query id 1031478425 10.128.0.160 emax_base update INSERT INTO emax_user_tag (user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', 'Marketing', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' ) *** (1) WAITING FOR THIS LOCK TO BE GRANTED: 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 Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 97c33f75fbadb002; asc ?u ;; 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc ;; 2: len 8; hex 000000000044c0da; asc D ;; *** (2) TRANSACTION: TRANSACTION 404898332, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2 MySQL thread id 11375224, OS thread handle 140655576868608, query id 1031478426 10.128.0.160 emax_base update INSERT INTO emax_user_tag (user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, 'A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9', 'Information Technology Services', '2023-10-12 09:40:50.481', '2023-10-12 09:40:50.481' ) *** (2) HOLDS THE LOCK(S): 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 Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 97c33f75fbadb002; asc ?u ;; 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc ;; 2: len 8; hex 000000000044c0da; asc D ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: 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 Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 97c33f75fbadb002; asc ?u ;; 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc ;; 2: len 8; hex 000000000044c0da; asc D ;; *** WE ROLL BACK TRANSACTION (1) <br>Some non-key information lines are omitted here ---------------------------- END OF INNODB MONITOR OUTPUT ============================ |
The log contains a lot of information, and several non-critical information lines have been omitted. We mainly focus on the information related to the last deadlock.
6. Deadlock recurrence
sql preparation
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, ‘A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9’, ‘Market Promotion’, ‘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’, ‘Information Technical Services’, ‘2023-10-12 09:40:50.481’, ‘2023-10-12 09:40 :50.481’ );
Create a local database emax_user_tag that is the same as the production one. Similarly, create a unique index on the user_id and tag_name fields.
Operation Step 1
Execute in window one
begin;
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, ‘A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9’, ‘Market Promotion’, ‘2023-10-12 09:40:50.481’, ‘2023-10-12 09:40: 50.481’ );
Operation Step 2
Execute in window two
begin;
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, ‘A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9’, ‘Market Promotion’, ‘2023-10-12 09:40:50.481’, ‘2023-10-12 09:40: 50.481’ );
Operation Step 3
Execute in window one
INSERT INTO emax_user_tag ( user_id, id_card_no, tag_name, create_time, update_time ) VALUES ( 1712282059297107970, ‘A978B69811B82F4B08F929D26B360F2D980CDCB5F419F1DD46527FB90BE1E5A9’, ‘Information Technical Services’, ‘2023-10-12 09:40:50.481’, ‘2023-10-12 09:40 :50.481’ );
commit;
Operation Step 4
Switch back to window two
Operation Step 5
Execute the command show ENGINE INNODB status to view the deadlock log. Same situation as above.
====================================== 2023-10-13 14:52:43 0x7fe759575700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 24 seconds ------------------ BACKGROUND THREAD ------------------ srv_master_thread loops: 137590 srv_active, 0 srv_shutdown, 2010475 srv_idle srv_master_thread log flush and writes: 2148065 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 6627679 OS WAIT ARRAY INFO: signal count 14339066 RW-shared spins 0, rounds 22104735, OS waits 1859432 RW-excl spins 0, rounds 258795010, OS waits 2238669 RW-sx spins 6551822, rounds 136672247, OS waits 1786313 Spin rounds per wait: 22104735.00 RW-shared, 258795010.00 RW-excl, 20.86 RW-sx -------------------------- LATEST DETECTED DEADLOCK -------------------------- 2023-10-13 14:50:31 0x7fe892ad0700 *** (1) TRANSACTION: TRANSACTION 293171186, ACTIVE 10 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 1266048, OS thread handle 140631613069056, query id 35172347 192.168.48.179 develop update /* 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, 'A978B69811B82F4B08F929D26B360F2D9 80CDCB5F419F1DD46527FB90BE1E5A9', 'Marketing', '2023-10 -12 09:40:50.481', '2023-10-12 09:40:50.481' ) *** (1) WAITING FOR THIS LOCK TO BE GRANTED: 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 Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 97c33f75fbadb002; asc ?u ;; 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc ;; 2: len 8; hex 80000000000358d0; asc X ;; *** (2) TRANSACTION: TRANSACTION 293171182, ACTIVE 19 sec inserting mysql tables in use 1, locked 1 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2 MySQL thread id 1266036, OS thread handle 140636869953280, query id 35172492 192.168.48.179 develop update /* 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, 'A978B69811B82F4B08F929D26B360F2D9 80CDCB5F419F1DD46527FB90BE1E5A9', 'Information Technology Services', '2023- 10-12 09:40:50.481', '2023-10-12 09:40:50.481' ) *** (2) HOLDS THE LOCK(S): 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 Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 97c33f75fbadb002; asc ?u ;; 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc ;; 2: len 8; hex 80000000000358d0; asc X ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: 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 Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 97c33f75fbadb002; asc ?u ;; 1: len 12; hex e5b882e59cbae68ea8e5b9bf; asc ;; 2: len 8; hex 80000000000358d0; asc X ;; *** WE ROLL BACK TRANSACTION (1)
View Code
7. Deadlock analysis
Analyze based on deadlock logs.
When performing step one:
Transaction 1 acquired the insertion intention lock
When performing step two:
Transaction 2: Upgrade the intention lock of the transaction to a unique index exclusive lock, and try to obtain a unique index shared lock (the shared lock has not been obtained yet, and is queued)
When performing step three:
Transaction 1: Try to acquire the insertion intention gap lock
Transaction two waits for transaction one to release the exclusive lock
Transaction one waits for transaction two to release the shared lock
A mutual waiting relationship is formed, which is a deadlock.
8. Summary
1. Batch insert operations try to ensure data orderliness
2. You can use higher-performance redis for concurrent interception or synchronous processing control
3. Set the parameter innodb_deadlock_detect to on, and rollback will be performed in case of deadlock (the database is enabled by default)
4. Business code needs to consider database exceptions
5. The current mysql database version is 5.7.28-log. After careful verification by Hong Jie, mysql-8.0 version has been optimized for this scenario and no deadlock will occur.
Literature reference https://blog.csdn.net/minghao0508/article/details/129093202