TransactionTable HashMap

[mraccola]

Our application is currently experiencing signs of a memory leak. We have analyzed the heap dumps and have traced the largest block of memory back to a HashMap in org.jboss.cache.TransactionTable.

I stepped through the code and found that on every put to the cache 2 transaction entries are written to the "txs" and "tx_map" but only 1 is removed, leaking one entry per put. The entry which is leaked is initiated from (TreeCache.put(Fqn, Object, Object) line: 3845). The entry which is properly cleaned up is from (TxInterceptor.handleNonTxMethod(MethodCall) line: 361).

Here is the code used to do the cache put

 Option option = new Option();
 option.setFailSilently(true);
 Fqn keyFqn = new Fqn(new Object[]{this.regionFqn, key});
 cacheRegion.getCache().put(keyFqn, ITEM, value, option);

Environment: WebSphere 6.1 + JBC 1.4.1.SP4

Here is a relevant portion of the heap dump:

440,293,704 (43%) [7,600] 948 array of EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ad66a9e68
 2,019,968 (0%) [72] 3 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ad4f95450
 2,019,832 (0%) [112] 8 org/jboss/cache/OptimisticTransactionEntry 0x2ad4f94a50
 64 (0%) [64] 2 org/jboss/cache/GlobalTransaction 0x2ad4f949e8
 608 (0%) [304] 6 class EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x20d3500
 1,722,808 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af73f8eb8
 1,435,344 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af0e735d8
 287,328 (0%) [112] 8 org/jboss/cache/OptimisticTransactionEntry 0x2af73f84b8
 64 (0%) [64] 2 org/jboss/cache/GlobalTransaction 0x2af73f8450
 608 (0%) [304] 6 class EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x20d3500
 1,701,592 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ae6e62bb8
 1,616,768 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ae4011d00
 1,581,112 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ac8576428
 1,535,568 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af4759d10
 1,511,600 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2afb2b8468
 1,482,928 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af4aa4ff8
 1,462,016 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af53ac168
 1,455,736 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2add5ee428
 1,263,912 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ab8b32dd0
 1,249,912 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ae51d9a60
 1,245,624 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af0ef8a20
 1,237,912 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2aee239508
 1,223,040 (0%) [72] 3 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ade5f4ea0
 1,218,040 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2aef3095c8
 1,199,520 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2afe8d0880
 1,169,392 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2b00dfd6d0
 1,165,664 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2af05c79f0
 1,151,128 (0%) [72] 4 EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap$Entry 0x2ac35487b8
There are 928 more children

[manik]

Hmm, I can't seem to recreate this. Running the code you provided in a loop and then inspecting the size of the 2 maps, I see they're both 0.

The cleanup is called in the afterCompletion() call in the Synchronization registered with the transaction manager. Do you see this being called in your logs?

Also, do you know if this happens all the time, or only on failing transactions that rollback or on remotely originating transactions? All stuff you would have simulated for your profiler session.

[mraccola]

Yes, I am using two cache instances, one as a Hibernate 2nd-level cache, one as a custom application cache. I can see in the Hibernate cache (which is called from Hibernate) that although the same exact path through JBC is taken the cleanup is done in the transaction syncronization. However, this is NOT happening for my custom cache.

I have attached a JUnit test to demonstrate what I am seeing. Note that in my test the assertions at the bottom of the test (Lines 70 and 71) fail because the size of the HashMap is > 0.

What am I doing wrong?

Test Case

package fleetcycle.model.framework.cache;

import java.io.InputStream;
import java.util.Properties;

import javax.naming.Context;
import javax.naming.InitialContext;
import javax.transaction.UserTransaction;

import junit.framework.TestCase;

import org.jboss.cache.Fqn;
import org.jboss.cache.PropertyConfigurator;
import org.jboss.cache.TreeCache;
import org.jboss.cache.config.Option;

public class Test_CacheLeak extends TestCase
{

 public void testLeak() throws Exception
 {
 final String ITEM = "item";
 TreeCache cache = new TreeCache();
 InputStream configStream = this.getClass().getResourceAsStream("/treecache-app.xml");
 PropertyConfigurator configs = new PropertyConfigurator();
 configs.configure(cache, configStream);
 cache.start();

 Fqn regionFqn = Fqn.fromString("/TestRegion");

 boolean fail = false;
 int iterationCnt = 100;

 Properties prop = new Properties();
 prop.put(Context.INITIAL_CONTEXT_FACTORY, "org.jboss.cache.transaction.DummyContextFactory");

 for (int i = 0; i < iterationCnt; i++)
 {
 UserTransaction tx = (UserTransaction) new InitialContext(prop).lookup("UserTransaction");
 try
 {
 tx.begin();
 Option option = new Option();
 option.setFailSilently(true);
 Fqn keyFqn = new Fqn(new Object[]{regionFqn, "testRoot/testNode" + i});
 cache.put(keyFqn, ITEM, "testVal", option);
 tx.commit();
 if (fail) throw new RuntimeException();
 System.out.println("Committing");
 } catch (Throwable ex)
 {
 System.out.println("Rolling back=" + ex.getMessage());
 ex.printStackTrace();
 try
 {
 tx.rollback();
 } catch (Throwable t)
 {}
 }
 }

 for (int i = 0; i < iterationCnt; i++)
 {
 Fqn keyFqn = new Fqn(new Object[]{regionFqn, "testRoot/testNode" + i});
 assertNotNull("Expected cache item not found", cache.get(keyFqn, ITEM));
 }

 int gtxCnt = cache.getTransactionTable().getNumGlobalTransactions();
 int txCnt = cache.getTransactionTable().getNumLocalTransactions();
 assertEquals("Global transaction count is > 0", 0, gtxCnt);
 assertEquals("Local transaction count is > 0", 0, txCnt);
 }

}

treecache-app.xml

<?xml version="1.0" encoding="UTF-8"?>
<server>
 <classpath codebase="./lib" archives="jboss-cache.jar, jgroups.jar" />
 <mbean code="org.jboss.cache.TreeCache" name="jboss.cache:service=TreeCache_FCXP_app">
 <depends>jboss:service=Naming</depends>
 <depends>jboss:service=TransactionManager</depends>

 <attribute name="ClusterName">FCXP_app</attribute>
 <attribute name="CacheMode">LOCAL</attribute>
 <attribute name="SyncReplTimeout">10000</attribute>
 <attribute name="LockAcquisitionTimeout">15000</attribute>
 <attribute name="FetchInMemoryState">false</attribute>
 <attribute name="NodeLockingScheme">OPTIMISTIC</attribute>
 <attribute name="TransactionManagerLookupClass">org.jboss.cache.DummyTransactionManagerLookup</attribute>
 <!-- Uncomment this line for WebSphere -->
 <!-- attribute name="UseInterceptorMbeans">false</attribute -->

 <attribute name="EvictionPolicyConfig">
 <config>
 <attribute name="wakeUpIntervalSeconds">5</attribute>
 <!-- Cache wide default -->
 <region name="/_default_" policyClass="org.jboss.cache.eviction.LRUPolicy">
 <attribute name="maxNodes">0</attribute>
 <attribute name="timeToIdleSeconds">10000</attribute>
 </region>
 </config>
 </attribute>
 </mbean>
</server>

[mraccola]

Please note if I comment the following line the test passes:

option.setFailSilently(true);

[manik]

Thanks for this and the JIRA. Just confirmed that this is on the 1.4.X branch as well. Will take a look!