1 Reply Latest reply on Mar 27, 2009 11:50 AM by ceciiil

    [JBoss-4.0.3][SQLServer] LockAcquisitionException blocks the

    ceciiil

      Hello,

      Context :
      We are having a problem on the productive environment. We have an Enterprise Application deplioyed on JBoss-4.0.3 with Hibernate 3.2.3 and SQLServer 2005. We use sqljdbc driver version 1.1. We know there has been version 1.2 and 2.0 but the benchmark on our app is not so goood when we upgrade to these versions.

      Problem
      SQLServer sometimes identifies deadlock situations. This error is returned to Hibernate which throws a org.hibernate.exception.LockAcquisitionException.

      From this point onwards, the system no longer works : every single hibernate request to the DB server ends up in error. We have dozens of following exception :

      PDM:1.4.7.6 - jboss - mssql - 7776828 [http-0.0.0.0-8080-10] ERROR com.lectra.pdm.applicationserver.pub.commands.CommandBuilder - CommandBuilder - execute : com.lectra.pdm.enterpriselayer.pub.cbr.CustomBusinessRuleException: Not traduct[[class com.lectra.pdm.enterpriselayer.server.persistencymanagement.exceptions.PersistencyException : org.hibernate.exception.SQLGrammarException: could not get or update next value]]
      INFO | jvm 1 | 2009/03/24 17:25:42 | PDM:1.4.7.6 - jboss - mssql - 7792578 [http-0.0.0.0-8080-9] INFO org.jboss.resource.connectionmanager.CachedConnectionManager - Closing a connection for you. Please close them yourself: org.jboss.resource.adapter.jdbc.WrappedConnection@879a32
      INFO | jvm 1 | 2009/03/24 17:25:42 | java.lang.Throwable: STACKTRACE
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.resource.connectionmanager.CachedConnectionManager.registerConnection(CachedConnectionManager.java:333)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:482)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:894)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:73)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:421)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1538)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.doQuery(Loader.java:661)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.loadEntity(Loader.java:1851)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.entity.BatchingEntityLoader.load(BatchingEntityLoader.java:82)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3038)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:195)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:103)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:846)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:557)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:196)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.cache.StandardQueryCache.get(StandardQueryCache.java:130)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.getResultFromQueryCache(Loader.java:2152)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2117)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.Loader.list(Loader.java:2087)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:811)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at com.lectra.pdm.enterpriselayer.server.persistencymanagement.PersistencyManager.findSessionBySessionId(PersistencyManager.java:671)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at com.lectra.pdm.enterpriselayer.server.sessionmanagement.SessionManager.isSessionValid(SessionManager.java:127)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at com.lectra.pdm.enterpriselayer.server.utils.SessionUtils.checkSession(SessionUtils.java:25)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at com.lectra.pdm.enterpriselayer.server.contentmanagement.ContentManager.readContent(ContentManager.java:299)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at com.lectra.pdm.enterpriselayer.server.contentmanagement.ejb.ContentManagementFacadeBean.readContent(ContentManagementFacadeBean.java:502)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at sun.reflect.GeneratedMethodAccessor1844.invoke(Unknown Source)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at java.lang.reflect.Method.invoke(Method.java:585)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:106)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.Container.invoke(Container.java:873)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:415)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:88)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at $Proxy176.readContent(Unknown Source)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at com.lectra.pdm.enterpriselayer.server.contentmanagement.servlet.ContentAccessServlet.doGet(ContentAccessServlet.java:712)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
      INFO | jvm 1 | 2009/03/24 17:25:42 | at java.lang.Thread.run(Thread.java:595)
      
      


      Solution :
      The solution we have found to fix this : stop and restart the jboss.jca:Service=ManagedConnectionPool. Obviously this is just not acceptable iun a productive environment.

      We have changed the SQLServer configuration to set Snapshot mode and Read_Commited mode. We still have this LockAcquisition exception that brings our ManagedConnectionPool down and stop our application from being used.

      Has anybody seen this problem ? Can you propose a solution ? What would you recommend ? Thnaks !

        • 1. Re: [JBoss-4.0.3][SQLServer] LockAcquisitionException blocks
          ceciiil

          2 reasons :

          1) SQL Server sends "transaction started" and "transaction rolled back/committed" messages to the driver "in band" with a query's execution results (update counts, result sets, errors). The driver can't "see" the messages until the results that precede them have been processed. So once a transaction has been started, if a statement's execution causes a commit or rollback, the driver will think the transaction is still active until the statement's results have been processed. More here http://blogs.msdn.com/jdbcteam/archive/2009/02/24/the-server-failed-to-resume-the-transaction-why.aspx. So the solution is to configure your datasource with a request to always check the connection :

          <check-valid-connection-sql>SELECT 1 </check-valid-connection-sql>
          

          Believe it or not, the above select works with SQLServer2005.


          2) When setting snapshot mode on SQLServer, if you use Hibernate (as we do) as ORM you need to set the hibernate.connection.isolation to snapshot mode value (4096) :
          hibernate.connection.isolation = 4096
          

          More here http://www.hibernate.org/382.html