5 Replies Latest reply on Dec 3, 2013 1:11 PM by Jesper Pedersen

    Changing state of trackByTx during a global transaction.

    Jeremy Whiting Expert

      Hi,

      I have a query about when the state of TxConnectionListener.trackByTx should be true and false.

       

      My JEE application uses EJB3 and JPA API with Hibernate behind the scenes. The default for JBoss EAP. So, typically during a tx the ORM framework will be putting reads and writes into an action queue. Sometimes these are flushed to the datastore, other times they remain in the queue and are flushed at the end of the transaction and flushed by a TransactionSynchronization. The application uses the default configuration for trackByTx which is true. Also nothing is configured for interleaving. Which is false by default. Plus I use postgres and the pgjdbc driver.

       

      Some tracing has shown the connection listener at the beginning of the transaction has the state set to true. Then later on when the same associated connection listener is used again the state is false.

      My question is when the connection listener is leased to the persistence layer should the state of the trackByTx field be set to true during the lifetime of a transaction ?

       

      To help diagnose the context are attached are some logs that show the state of trackByTx changes when the connection listener is in use. Along with dumped state using Byteman. I used a bmt script to create a message and dump the stack if the state is false when TxConnectionListener.enlist is called.

       

      Here is an extract from the log file.

       

      12:46:50,181 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http-f19lite/192.168.0.3:8080-19) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@528106c0[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@14e25191 connection handles=0 lastUse=1385556409340 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2e0ba62b pool internal context=SemaphoreArrayListManagedConnectionPool@2d517aa8[pool=acmeOrderDS] xaResource=XAResourceWrapperImpl@317ee1b1[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@14e25191 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.2.5 jndiName=java:/jdbc/acmeOrderDS] txSync=null]

      12:46:50,181 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http-f19lite/192.168.0.3:8080-19) Got connection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@528106c0[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@14e25191 connection handles=0 lastUse=1385556409340 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2e0ba62b pool internal context=SemaphoreArrayListManagedConnectionPool@2d517aa8[pool=acmeOrderDS] xaResource=XAResourceWrapperImpl@317ee1b1[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@14e25191 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.2.5 jndiName=java:/jdbc/acmeOrderDS] txSync=null]

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) *** the trackByTx state is false during enlist. ***org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:-1)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:467)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:70)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:214)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:157)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:56)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:161)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:182)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:159)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1859)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1836)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1816)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.doQuery(Loader.java:900)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:312)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.Loader.loadEntity(Loader.java:2121)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:82)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:72)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:65)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.loader.entity.LegacyBatchingEntityLoaderBuilder$LegacyBatchingEntityLoader.load(LegacyBatchingEntityLoaderBuilder.java:121)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3941)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:460)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:429)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:206)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:262)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:150)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1098)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.internal.SessionImpl.access$2000(SessionImpl.java:175)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2482)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.internal.SessionImpl.get(SessionImpl.java:994)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:807)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:781)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.jpa.container.AbstractEntityManager.find(AbstractEntityManager.java:193)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.ejb.orders.session.CustomerSession.getCustomer(CustomerSession.java:46)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.ejb.orders.session.CustomerSession.getInventories(CustomerSession.java:89)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) sun.reflect.GeneratedMethodAccessor69.invoke (Unknown Source)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) java.lang.reflect.Method.invoke(Method.java:606)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:259)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:398)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:242)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.ejb.orders.session.CustomerSessionLocal$$$view14.getInventories (Unknown Source)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.servlet.helper.AcmeAction.getHoldings(AcmeAction.java:277)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.servlet.helper.AcmeServletAction.doHome(AcmeServletAction.java:281)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.servlet.AcmeAppServlet.performTask(AcmeAppServlet.java:209)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) com.acme.acme.servlet.AcmeAppServlet.doGet(AcmeAppServlet.java:78)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) javax.servlet.http.HttpServlet.service(HttpServlet.java:734)

      12:46:50,182 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) javax.servlet.http.HttpServlet.service(HttpServlet.java:847)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:920)

      12:46:50,183 INFO  [stdout] (http-f19lite/192.168.0.3:8080-19) java.lang.Thread.run(Thread.java:744)

       

       

      Regards,

      Jeremy

       

      Message was edited by: Jeremy Whiting - add zip compatible archive of server logs.