JBoss 7.1.1.Final - Local transactions - Memory Leak
srikrishnak Jul 16, 2012 10:49 PMWe are migrating from JBoss 6.0.0.Final to JBoss 7.1.1.Final and in load environment we have noticed that even though JBoss 7.1.1.Final shows good bump from response times perspective, it is losing memory continuously and when it reaches the max available, naturally response times are tanking and so is number of requests processed per minute in a soak test. We have used jmap + jhat combination to figure where is the memory leak and the top 10 candidates point towards com.arjuna.* package. We are not using jta (jta=false) and another issue we have noticed is, with jta, our response times are tanking. (Ex: if non-jta setup gives us 3 milli seconds, jta setup shows us around 300 milli seconds for our application). Here is some data:
10 minutes into the soak test:
132405 instances of class com.arjuna.ats.arjuna.coordinator.RecordList 88300 instances of class com.arjuna.ats.arjuna.common.Uid 44146 instances of class com.arjuna.ats.arjuna.coordinator.ActionHierarchy 44146 instances of class com.arjuna.ats.arjuna.coordinator.ActionInfo 44146 instances of class com.arjuna.ats.arjuna.coordinator.CheckedAction 44146 instances of class com.arjuna.ats.internal.arjuna.common.BasicMutex 44146 instances of class com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction 44146 instances of class com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple 44146 instances of class [Lcom.arjuna.ats.arjuna.coordinator.ActionInfo; 44135 instances of class com.arjuna.ats.internal.jta.xa.TxInfo 44135 instances of class com.arjuna.ats.internal.jta.xa.XID 44135 instances of class com.arjuna.ats.jta.xa.XidImple
50 minutes into the soak test: (after 40 minutes)
333036 instances of class com.arjuna.ats.arjuna.coordinator.RecordList 222074 instances of class com.arjuna.ats.arjuna.common.Uid 111033 instances of class com.arjuna.ats.arjuna.coordinator.ActionHierarchy 111033 instances of class com.arjuna.ats.arjuna.coordinator.ActionInfo 111033 instances of class com.arjuna.ats.arjuna.coordinator.CheckedAction 111033 instances of class com.arjuna.ats.internal.arjuna.common.BasicMutex 111033 instances of class com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction 111033 instances of class com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple 111033 instances of class [Lcom.arjuna.ats.arjuna.coordinator.ActionInfo; 111012 instances of class com.arjuna.ats.internal.jta.xa.TxInfo 111012 instances of class com.arjuna.ats.internal.jta.xa.XID 111012 instances of class com.arjuna.ats.jta.xa.XidImple
Our datasource setup is as follows:
<subsystem xmlns="urn:jboss:domain:datasources:1.0"> <datasouces> <datasource jta="false" jndi-name="java:jboss/datasources/ApplicationDS" pool-name="java:jboss/datasources/ApplicationDS" enabled="true" use-ccm="true"> <connection-url>jdbc:inetdae7a:REPLACE_WITH_IP_ADDRESS:REPLACE_WITH_PORT_NUMBER?databaseName=ApplicationDB&amp;instanceName=applicationInstance&amp;loginTimeout=20&amp;queryTimeout=300</connection-url> <driver-class>com.inet.tds.TdsDriver</driver-class> <driver>Merlia-1.0.jar</driver> <pool> <min-pool-size>25</min-pool-size> <max-pool-size>250</max-pool-size> </pool> <security> <user-name>REPLACE_WITH_USERNAME</user-name> <password>REPLACE_WITH_PASSWORD</password> </security> <validation> <validate-on-match>false</validate-on-match> <background-validation>false</background-validation> </validation> <statement> <share-prepared-statements>false</share-prepared-statements> </statement> </datasource> <datasource jta="false" jndi-name="java:jboss/datasources/ReportingDS" pool-name="java:jboss/datasources/ReportingDS" enabled="true" use-ccm="true"> <connection-url>jdbc:inetdae7a:REPLACE_WITH_IP_ADDRESS:REPLACE_WITH_PORT_NUMBER?databaseName=ReportingDB&amp;instanceName=reportingInstance&amp;loginTimeout=20&amp;queryTimeout=300</connection-url> <driver-class>com.inet.tds.TdsDriver</driver-class> <driver>Merlia-1.0.jar</driver> <pool> <min-pool-size>25</min-pool-size> <max-pool-size>250</max-pool-size> </pool> <security> <user-name>REPLACE_WITH_USERNAME</user-name> <password>REPLACE_WITH_PASSWORD</password> </security> <validation> <validate-on-match>false</validate-on-match> <background-validation>false</background-validation> </validation> <statement> <share-prepared-statements>false</share-prepared-statements> </statement> </datasource> <drivers> <driver name="Merlia-1.0.jar" module="com.inet.tds"> <driver-class>com.inet.tds.TdsDriver</driver-class> </driver> </drivers> </datasources> </subsystem>
Another question we have is, even after setting jta="false", Heap Dump shows instances of "com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction" where package name is suggesting "jta" and is confusing. We are thinking memory leak is at transaction level, in the base api (arjuna) as there is no indication or errors in log files pointing to our code. When we enable DEBUG on com.arjuna package we see the following debug statements logging at regular intervals:
18:16:08,027 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING 18:16:08,027 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning 18:16:08,027 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Mon, 16 Jul 2012 18:16:08 18:16:08,028 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass 18:16:08,028 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions 18:16:08,028 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 18:16:08,028 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass 18:16:08,029 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 18:16:08,029 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass 18:16:08,030 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 18:16:18,031 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Mon, 16 Jul 2012 18:16:18 18:16:18,031 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass 18:16:18,031 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 18:16:18,031 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass 18:16:18,031 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 18:16:18,032 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass 18:16:18,032 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed 18:16:18,032 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of HornetQXAResourceWrapper [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], csf=ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], delegate=DelegatingSession [session=ClientSessionImpl [name=f125010a-cf9b-11e1-a943-dc6a20524153, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=()]@236d7300], xaRecoveryConfigs=[XARecoveryConfig [hornetQConnectionFactory=HornetQConnectionFactory [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], clientID=null, dupsOKBatchSize=1048576, transactionBatchSize=1048576, readOnly=fals e], username=null, password=null]], instance=1281715623] 18:16:18,034 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt 18:16:18,035 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass. 18:16:18,035 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed 18:16:18,036 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 18:16:18,036 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE 18:16:18,036 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off
We have repeated the same soak test in our JBoss 6.0.0.Final environment and it shows dismal statistics for the class com.arjuna.ats.arjuna.coordinator.RecordList class as follows:
10 minutes into the test - com.arjuna.ats.arjuna.coordinator.RecordList - 1009 50 minutes into the test - com.arjuna.ats.arjuna.coordinator.RecordList - 244
This has become a blocking issue and may have to kill our migration without a good solution. Any pointers are greatly appreciated! Thanks!
-Srikrishna Kalavacharla