4 Replies Latest reply on Jul 18, 2012 7:33 AM by jesper.pedersen

JBoss 7.1.1.Final - Local transactions - Memory Leak

srikrishnak Jul 16, 2012 10:49 PM

We 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;amp;instanceName=applicationInstance&amp;amp;loginTimeout=20&amp;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;amp;instanceName=reportingInstance&amp;amp;loginTimeout=20&amp;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

1. Re: JBoss 7.1.1.Final - Local transactions - Memory Leak

jaikiran Jul 17, 2012 12:19 AM (in response to srikrishnak)

What kind of application is this and what operations does it do that shows up this issue?
Actions
2. Re: JBoss 7.1.1.Final - Local transactions - Memory Leak

jesper.pedersen Jul 17, 2012 7:24 AM (in response to srikrishnak)

Could you try the latest nightly snapshot and see if the problem is the same ?
Actions
3. Re: JBoss 7.1.1.Final - Local transactions - Memory Leak

srikrishnak Jul 17, 2012 4:19 PM (in response to jesper.pedersen)

This is a Dynamic Web Project which is using hibernate, doing some DB reads, caching them using Infinispan and some writes which are routed through JMS. Turns out, by setting use-ccm="false" and removing debug="true" on <cached-connection-manager>, we are able to prevent the memory leak. I made this change based on what I read here https://community.jboss.org/wiki/DetectingAndClosingLeakedConnectionsInJBoss71 , but turns out this feature is not working very well.
Actions
4. Re: JBoss 7.1.1.Final - Local transactions - Memory Leak

jesper.pedersen Jul 18, 2012 7:33 AM (in response to srikrishnak)

Set error="true" and fix your leaks.
Actions

Go to original post