deadlock-found-when-trying-to-get-lock

Posted wangziqiang123

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了deadlock-found-when-trying-to-get-lock相关的知识，希望对你有一定的参考价值。

mysql锁机制分为表级锁和行级锁：

共享锁又称为读锁，简称S锁，顾名思义，共享锁就是多个事务对于同一数据可以共享一把锁，都能访问到数据，但是只能读不能修改。

排他锁又称为写锁，简称X锁，顾名思义，排他锁就是不能与其他所并存，如一个事务获取了一个数据行的排他锁，其他事务就不能再获取该行的其他锁，包括共享锁和排他锁，但是获取排他锁的事务是可以对数据就行读取和修改。

对于共享锁大家可能很好理解，就是多个事务只能读数据不能改数据，对于排他锁大家的理解可能就有些差别，我当初就犯了一个错误，以为排他锁锁住一行数据后，其他事务就不能读取和修改该行数据，其实不是这样的。排他锁指的是一个事务在一行数据加上排他锁后，其他事务不能再在其上加其他的锁。mysql InnoDB引擎默认的修改数据语句，update,delete,insert都会自动给涉及到的数据加上排他锁，select语句默认不会加任何锁类型，如果加排他锁可以使用select …for update语句，加共享锁可以使用select … lock in share mode语句。所以加过排他锁的数据行在其他事务种是不能修改数据的，也不能通过for update和lock in share mode锁的方式查询数据，但可以直接通过select …from…查询数据，因为普通查询没有任何锁机制。

技术图片

案发现场

API网关在30ms内收到6次相同请求，错误日志：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.754 [http-apr-8080-exec-1379] INFO  h.a.a.f.AppPlatformRateLimiterFilter - parameter=_appCrypt_=VDzT76Hdrp9QAO4lSbQuJeIaKnQ8VZnqljK+YmN2W1tyBSv1JqIhTrDHrBlWM9K8yg3kcLOUmENr1OUc+6xWSL13Z2jaBhCJDrMYWad/H971ilDd4eQMrakZP84dCbXC&_t_=HBStockWarningios_3.6.4&ticket=7.BdzpPOeP2_7JV6IYArPBIOC36NO2PoCMhVPHiISIEM_tAo7-unTlp_baBhZ79TZskD-HBIBmSnk-7y_tv24wD2IiSgTHlj7x5DTHEV7CacwVdw9jmTCuVdePd4mUaM11k5XGRSsPzqzQmomKMu7aGm8R48Nq-ECE7WpSNtQmExU&
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.756 [http-apr-8080-exec-1379] INFO  sky.app.api.filter.RateLimiter - userId:3245964, 在 5s 内第1次 执行操作 http:
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.756 [http-apr-8080-exec-1319] INFO  sky.app.api.filter.RateLimiter - userId:3245964, 在 5s 内第2次 执行操作 http:
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.757 [http-apr-8080-exec-1319] DEBUG h.p.commons.web.HbecApiHandleAdapter - param-sha1 : null, appCrypt<1> : VDzT76Hdrp9QAO4lSbQuJeIaKnQ8VZnqljK+YmN2W1tyBSv1JqIhTrDHrBlWM9K8yg3kcLOUmENr1OUc+6xWSL13Z2jaBhCJDrMYWad/H971ilDd4eQMrakZP84dCbXC, dataKey=l7g19q1$g#*o9v-1
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.755 [http-apr-8080-exec-1414] INFO  h.a.a.f.AppPlatformRateLimiterFilter - http request=http://api.*.com/followStockService.follow
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.755 [http-apr-8080-exec-1414] INFO  h.a.a.f.AppPlatformRateLimiterFilter - 
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.757 [http-apr-8080-exec-1414] INFO  sky.app.api.filter.RateLimiter - userId:3245964, 在 5s 内第3次 执行操作 http:
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.756 [http-apr-8080-exec-1457] INFO  h.a.a.f.AppPlatformRateLimiterFilter - http request=http://api.*.com/followStockService.follow
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.756 [http-apr-8080-exec-1457] INFO  h.a.a.f.AppPlatformRateLimiterFilter - 
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.757 [http-apr-8080-exec-1457] INFO  sky.app.api.filter.RateLimiter - userId:3245964, 在 5s 内第4次 执行操作 http:
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.757 [http-apr-8080-exec-1334] INFO  h.a.a.f.AppPlatformRateLimiterFilter - http request=http://api.*.com/followStockService.follow
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.757 [http-apr-8080-exec-1334] INFO  h.a.a.f.AppPlatformRateLimiterFilter - parameter=_appCrypt_=VDzT76Hdrp9QAO4lSbQuJeIaKnQ8VZnqljK+YmN2W1tyBSv1JqIhTrDHrBlWM9K8yg3kcLOUmENr1OUc+6xWSL13Z2jaBhCJDrMYWad/H971ilDd4eQMrakZP84dCbXC&_t_=HBStockWarningIos_3.6.4&ticket=7.BdzpPOeP2_7JV6IYArPBIOC36NO2PoCMhVPHiISIEM_tAo7-unTlp_baBhZ79TZskD-HBIBmSnk-7y_tv24wD2IiSgTHlj7x5DTHEV7CacwVdw9jmTCuVdePd4mUaM11k5XGRSsPzqzQmomKMu7aGm8R48Nq-ECE7WpSNtQmExU&
Jul 23 17:12:50 iZ23qpg65e4Z api_qianqian1 2017-07-23 17:12:50.759 [http-apr-8080-exec-1334] INFO  sky.app.api.filter.RateLimiter - userId:3245964, 在 5s 内第5次 执行操作 http:

业务日志

追踪到业务节点后，发现mysql出现死锁问题：Deadlock found when trying to get lock; try restarting transaction

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
Jul 23 17:12:50 iZ2360o6lpyZ warn1 17-07-23 17:12:50.779 ERROR[DubboServerHandler-10.253.17.105:20880-thread-193 DbService.execute:1247] {}
Jul 23 17:12:50 iZ2360o6lpyZ warn1 sky.platform.commons.exceptions.HbecDbServiceException: service=db,message=sky.platform.commons.exceptions.HbecDbServiceException: service=db,message=
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error may involve WarnFollowMapper.follow-Inline
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error occurred while setting parameters
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### SQL: insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort)         values (?, ?,  ?,                 ?,?, ?,                 (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = ?) )         on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= ?)
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.platform.runtime.DbServiceInterceptor$1.execute(DbServiceInterceptor.java:39) ~[hbec-platform-commons-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.platform.runtime.DbService.execute(DbService.java:1242) ~[hbec-platform-commons-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.platform.runtime.DbServiceInterceptor.intercept(DbServiceInterceptor.java:33) [hbec-platform-commons-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.service.impl.WarnFollowServiceImpl$$EnhancerByCGLIB$$41e28e09.follow(<generated>) [spring-core-4.0.2.RELEASE.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.controller.impl.FollowStockControllerImpl.follow(FollowStockControllerImpl.java:304) [hbec-app-stock-follow-1.0.2-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.common.bytecode.Wrapper94.invokeMethod(Wrapper94.java) [na:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.eagleeye.dubbo.EagleeyeFilter.invoke(EagleeyeFilter.java:155) [hbec-platform-runtime-app-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:60) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:112) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:108) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82) [dubbo-2.5.3.jar:2.5.3]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 Caused by: java.lang.RuntimeException: sky.platform.commons.exceptions.HbecDbServiceException: service=db,message=
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error may involve WarnFollowMapper.follow-Inline
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error occurred while setting parameters
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### SQL: insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort)         values (?, ?,  ?,                 ?,?, ?,                 (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = ?) )         on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= ?)
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.repository.impl.WarnFollowRepository.follow(WarnFollowRepository.java:238) ~[hbec-app-stock-follow-1.0.2-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.service.impl.WarnFollowServiceImpl.follow(WarnFollowServiceImpl.java:87) ~[hbec-app-stock-follow-1.0.2-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.service.impl.WarnFollowServiceImpl$$EnhancerByCGLIB$$41e28e09.CGLIB$follow$0(<generated>) [spring-core-4.0.2.RELEASE.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.service.impl.WarnFollowServiceImpl$$EnhancerByCGLIB$$41e28e09$$FastClassByCGLIB$$cf1f7d1b.invoke(<generated>) ~[spring-core-4.0.2.RELEASE.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228) ~[spring-core-4.0.2.RELEASE.jar:4.0.2.RELEASE]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.platform. 大专栏  deadlock-found-when-trying-to-get-lockruntime.DbServiceInterceptor$1.execute(DbServiceInterceptor.java:37) ~[hbec-platform-commons-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	... 34 common frames omitted
Jul 23 17:12:50 iZ2360o6lpyZ warn1 Caused by: sky.platform.commons.exceptions.HbecDbServiceException: service=db,message=
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error may involve WarnFollowMapper.follow-Inline
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error occurred while setting parameters
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### SQL: insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort)         values (?, ?,  ?,                 ?,?, ?,                 (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = ?) )         on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= ?)
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.platform.runtime.DbService.myInsert(DbService.java:2345) ~[hbec-platform-commons-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.app.stock.follow.repository.impl.WarnFollowRepository.follow(WarnFollowRepository.java:236) ~[hbec-app-stock-follow-1.0.2-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	... 39 common frames omitted
Jul 23 17:12:50 iZ2360o6lpyZ warn1 Caused by: org.apache.ibatis.exceptions.PersistenceException: 
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error may involve WarnFollowMapper.follow-Inline
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### The error occurred while setting parameters
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### SQL: insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort)         values (?, ?,  ?,                 ?,?, ?,                 (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = ?) )         on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= ?)
Jul 23 17:12:50 iZ2360o6lpyZ warn1 ### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:26) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:154) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:141) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sky.platform.runtime.DbService.myInsert(DbService.java:2331) ~[hbec-platform-commons-0.0.32-SNAPSHOT.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	... 40 common frames omitted
Jul 23 17:12:50 iZ2360o6lpyZ warn1 Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) ~[na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at java.lang.reflect.Constructor.newInstance(Constructor.java:526) ~[na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.Util.getInstance(Util.java:386) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1066) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4237) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4169) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2617) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2778) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2825) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2156) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1379) ~[mysql-connector-java-5.1.28.jar:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sun.reflect.GeneratedMethodAccessor199.invoke(Unknown Source) ~[na:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_55]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:62) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at com.sun.proxy.$Proxy28.execute(Unknown Source) ~[na:na]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:44) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:69) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:48) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:105) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:71) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:152) ~[mybatis-3.2.8.jar:3.2.8]
Jul 23 17:12:50 iZ2360o6lpyZ warn1 	... 42 common frames omitted
Jul 23 17:12:50 iZ2360o6lpyZ warn1 17-07-23 17:12:50.780 DEBUG[DubboServerHandler-10.253.17.105:20880-thread-192 follow.debug:139]MYBATIS <==    Updates: 2

查看数据库引擎状态

1
show engine innodb status
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
------------------------
LATEST DETECTED DEADLOCK
------------------------
2017-07-23 17:13:58 2afc664c2700
*** (1) TRANSACTION:
TRANSACTION 730441984, ACTIVE 0.003 sec inserting
mysql tables in use 3, locked 3
LOCK WAIT 8 lock struct(s), heap size 2936, 37 row lock(s), undo log entries 1
LOCK BLOCKING MySQL thread id: 12246957 block 12256080
MySQL thread id 12256080, OS thread handle 0x2afc48c40700, query id 3543571324 10.253.17.105 test_app Sending data
insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort)
        values (3245964, 4,  '601318',
                'SH','中国平安', null,
                (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = 3245964) )
        on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= 3245964)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1198 page no 842 n bits 696 index `unique_index` of table `wndb`.`test_follow` trx id 730441984 lock_mode X waiting
Record lock, heap no 624 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 8031878c; asc  1  ;;
 1: len 1; hex 84; asc  ;;
 2: len 6; hex 363031333138; asc 601318;;
 3: len 4; hex 800399cb; asc     ;;
*** (2) TRANSACTION:
TRANSACTION 730441985, ACTIVE 0.001 sec inserting
mysql tables in use 3, locked 3
8 lock struct(s), heap size 2936, 37 row lock(s), undo log entries 1
MySQL thread id 12246957, OS thread handle 0x2afc664c2700, query id 3543571329 10.253.17.105 test_app Sending data
insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort)
        values (3245964, 4,  '601318',
                'SH','中国平安', null,
                (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = 3245964) )
        on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= 3245964)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1198 page no 842 n bits 696 index `unique_index` of table `wndb`.`test_follow` trx id 730441985 lock mode S locks rec but not gap
Record lock, heap no 624 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 8031878c; asc  1  ;;
 1: len 1; hex 84; asc  ;;
 2: len 6; hex 363031333138; asc 601318;;
 3: len 4; hex 800399cb; asc     ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1198 page no 842 n bits 696 index `unique_index` of table `wndb`.`test_follow` trx id 730441985 lock_mode X waiting
Record lock, heap no 624 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 8031878c; asc  1  ;;
 1: len 1; hex 84; asc  ;;
 2: len 6; hex 363031333138; asc 601318;;
 3: len 4; hex 800399cb; asc     ;;
*** WE ROLL BACK TRANSACTION (2)

从中可以看到两个事务在等待X锁

1
2
3
4
5
6
7
8
9
10
11
WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1198 page no 842 n bits 696 index `unique_index` of table `wndb`.`test_follow` trx id 730441984 lock_mode X waiting
Record lock
(2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1198 page no 842 n bits 696 index `unique_index` of table `wndb`.`test_follow` trx id 730441985 lock mode S locks rec but not gap
Record lock, heap no 624 PHYSICAL RECORD
(2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1198 page no 842 n bits 696 index `unique_index` of table `wndb`.`test_follow` trx id 730441985 lock_mode X waiting
Record lock, heap no 624 PHYSICAL RECORD

重现

1.准备工作

  • 同时开启三个command prompt，远程连接mysql服务器：mysql -uroc -proc -h10.0.30.59 wndb
  • 关闭自动提交：set autocommit=0

2.模拟请求

Session A

1
2
3
begin;
insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort) values (3245964, 4, '600628', 'SH','新世界', null, (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = 3245964) ) on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= 3245964);

Session B

1
2
3
begin;
insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort) values (3245964, 4, '600628', 'SH','新世界', null, (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = 3245964) ) on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= 3245964);

Session C

1
2
3
begin;
insert into test_follow (user_id, security_type, stock_code, exchange, stock_name, sub_fund_type, sort) values (3245964, 4, '600628', 'SH','新世界', null, (select max(IFNULL(t1.sort,0)) + 1 from test_FOLLOW t1 where t1.user_id = 3245964) ) on duplicate key update sort= (select max(IFNULL(t2.sort,0)) + 1 from test_follow t2 where t2.user_id= 3245964);

commit Session A，session B与session C竞争X锁，直接报错:

技术图片

解决

首先这是个添加操作，APP端不应该对同一用户、同一只股票执行多次并发添加操作
，APP端需要解决单设备、多并发问题。后台针对同一用户、同一股票的添加操作，需要使用分布式锁控制并发。

以上是关于deadlock-found-when-trying-to-get-lock的主要内容，如果未能解决你的问题，请参考以下文章