DeadLock Lesson

1. Problem

09:32:56,921  WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper:143 - SQL Error: 1213, SQLState: 4000109:32:56,922 ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper:144 - Deadlock found when trying to get lock; try restarting transaction09:32:56,949  WARN org.apache.cxf.phase.PhaseInterceptorChain:452 - Application {http://impl.service.basbroker.integration.yystar.com/}BrokeragedbBetServiceService#{http://api.service.basbroker.integration.yystar.com/}isAbleToPlaceBet has thrown exception, unwinding noworg.apache.cxf.interceptor.Fault: could not execute statementat org.apache.cxf.service.invoker.AbstractInvoker.createFault(AbstractInvoker.java:162)at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.createFault(AbstractJAXWSMethodInvoker.java:213)at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:128)at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.invoke(AbstractJAXWSMethodInvoker.java:178)at org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:68)at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:75)at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)at java.util.concurrent.FutureTask.run(FutureTask.java:166)at org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37)at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:107)at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:272)at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:239)at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:248)at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:222)at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:153)at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:167)at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:286)at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:206)at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:262)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:208)at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:181)at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:680)at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)at java.lang.Thread.run(Thread.java:722)Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statementat org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:411)at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125)at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110)at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:136)at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.executeAndExtract(IdentityGenerator.java:96)at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:58)at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2966)at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3477)at org.hibernate.action.internal.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:81)at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:362)at org.hibernate.engine.spi.ActionQueue.addResolvedEntityInsertAction(ActionQueue.java:203)at org.hibernate.engine.spi.ActionQueue.addInsertAction(ActionQueue.java:183)at org.hibernate.engine.spi.ActionQueue.addAction(ActionQueue.java:167)at org.hibernate.event.internal.AbstractSaveEventListener.addInsertAction(AbstractSaveEventListener.java:321)at org.hibernate.event.internal.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:286)at org.hibernate.event.internal.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:192)at org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:125)at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:204)at org.hibernate.event.internal.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:55)at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:189)at org.hibernate.event.internal.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:49)at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:90)at org.hibernate.internal.SessionImpl.fireSave(SessionImpl.java:763)at org.hibernate.internal.SessionImpl.save(SessionImpl.java:755)at org.hibernate.internal.SessionImpl.save(SessionImpl.java:751)at com.yystar.integration.basbroker.dao.impl.BasSyncDao.saveHoldingTransaction(BasSyncDao.java:500)at sun.reflect.GeneratedMethodAccessor1545.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:601)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)at com.sun.proxy.$Proxy27.saveHoldingTransaction(Unknown Source)at com.yystar.integration.basbroker.service.impl.BrokeragedbBetService.isAbleToPlaceBet(BrokeragedbBetService.java:135)at sun.reflect.GeneratedMethodAccessor660.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:601)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:198)at com.sun.proxy.$Proxy29.isAbleToPlaceBet(Unknown Source)at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:601)at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180)at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)... 41 moreCaused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transactionat sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)at java.lang.reflect.Constructor.newInstance(Constructor.java:525)at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)at com.mysql.jdbc.Util.getInstance(Util.java:386)at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1064)at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597)at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529)at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990)at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625)at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2333)at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2318)at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:133)... 88 more

2. Possible Cause:

(1) We have a CS application and a web application and a service interact with the database, and the legacy CS application's transaction isolation level is 'serializable'!

 _hedgingTransaction = HedgingdbConnection.BeginTransaction(IsolationLevel.Serializable);

(2) Both our CS application and BS application have long running transactions, which are prone to cause dead locks.

(3) We have a few long running transactions with reversed order database operation, some update table A first then table B, some update table B first then table A. Example in our project: create new bet and settle bet both are long running transactions, and the data operations are in reversed order.

Reference

[1] http://stackoverflow.com/questions/21777205/hibernate-deadlock-found-when-trying-to-obtain-lock