Memory leak using Infinispan 5.1.8 with Hibernate 4.1.8

[dchuiko]

Hi everybody!

I have encountered a memory leak using Infinispan 5.1.8 for Hibernate's (4.1.8) second level cache on Jboss 7.1.2. The problem is in org.hibernate.cache.infinispan.access.PutFromLoadValidator#pendingPuts cache. For an unknown reason after some time of extensive cache usage it began to contain ImmortalCacheEntry instances. So they could not be purged in org.infinispan.container.DefaultDataContainer#purgeExpired. A breakpoint in ImmortalCacheEntry constructor leaded to the following stack trace:

at org.infinispan.container.entries.ImmortalCacheEntry.<init>(ImmortalCacheEntry.java:50)
at org.infinispan.container.InternalEntryFactoryImpl.update(InternalEntryFactoryImpl.java:122)
at org.infinispan.container.DefaultDataContainer.put(DefaultDataContainer.java:144)
at org.infinispan.container.entries.ReadCommittedEntry.commit(ReadCommittedEntry.java:198)
at org.infinispan.interceptors.locking.ClusteringDependentLogic$AllNodesLogic.commitEntry(ClusteringDependentLogic.java:115)
at org.infinispan.interceptors.EntryWrappingInterceptor.commitContextEntry(EntryWrappingInterceptor.java:208)
at org.infinispan.interceptors.EntryWrappingInterceptor.commitEntryIfNeeded(EntryWrappingInterceptor.java:287)
at org.infinispan.interceptors.EntryWrappingInterceptor.commitContextEntries(EntryWrappingInterceptor.java:187)
at org.infinispan.interceptors.EntryWrappingInterceptor.invokeNextAndApplyChanges(EntryWrappingInterceptor.java:213)
at org.infinispan.interceptors.EntryWrappingInterceptor.visitPutKeyValueCommand(EntryWrappingInterceptor.java:147)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:68)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:62)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:62)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
at org.infinispan.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1006)
at org.infinispan.CacheImpl.putIfAbsent(CacheImpl.java:716)
at org.infinispan.CacheImpl.putIfAbsent(CacheImpl.java:707)
at org.infinispan.CacheSupport.putIfAbsent(CacheSupport.java:78)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.registerPendingPut(PutFromLoadValidator.java:382)
at org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.get(TransactionalAccessDelegate.java:74)
at org.hibernate.cache.infinispan.collection.TransactionalAccess.get(TransactionalAccess.java:36)
at org.hibernate.engine.spi.BatchFetchQueue.isCached(BatchFetchQueue.java:335)
at org.hibernate.engine.spi.BatchFetchQueue.getCollectionBatch(BatchFetchQueue.java:312)
at org.hibernate.loader.collection.BatchingCollectionInitializer.initialize(BatchingCollectionInitializer.java:72)
at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:678)
at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:80)
at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:1804)
at org.hibernate.collection.internal.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:681)
at org.hibernate.Hibernate.initialize(Hibernate.java:77)

Under debugging it was found that ReadCommittedEntry (down to the stack) has maxIdle = -1 despite the fact that in configuration 60 seconds were set. After that pending-puts cache configuration was changed from

builder.clustering().cacheMode(CacheMode.LOCAL)
          .transaction().transactionMode(TransactionMode.NON_TRANSACTIONAL)
          .expiration().maxIdle(TimeUnit.SECONDS.toMillis(60))
          .storeAsBinary().enabled(false)
          .locking().isolationLevel(IsolationLevel.READ_COMMITTED)
          .jmxStatistics().disable();

to

builder.clustering().cacheMode(CacheMode.LOCAL)
          .transaction().transactionMode(TransactionMode.NON_TRANSACTIONAL)
          .expiration().maxIdle(TimeUnit.SECONDS.toMillis(60)).lifespan(TimeUnit.MINUTES.toMillis(6))
          .storeAsBinary().enabled(false)
          .locking().isolationLevel(IsolationLevel.READ_COMMITTED)
          .jmxStatistics().disable();

and that helped.

Thank you in advance for your help with this problem!

[galder.zamarreno]

Hmmm, what does the rest of the configuration look like? It could be a side effect of the default configuration...

There's definitely something odd there cos if maxIdle is anything other than 0, it should create a TransientCacheEntry or TransientMortalCacheEntry. Even when updating, it should pass in the right default maxIdle value. There's more odd things there, how come a putIfAbsent call can lead to a entry being updated?

I can't replicate a similar scenario on my side. If you can replicate it, it'd be interesting to see if defaultMaxIdleTime starts with value -1 from the first invocation?

[dchuiko]

We use default configuration from hibernate-infinispan with only globalJmxStatistics set to true.

After your comment tried to carry out additional investigation and here are results.

I began from org.infinispan.container.entries.ReadCommittedEntry#commit:198 where maxIdle field is -1. This field can be set only from setter, so in 99,99% of invocations are done from PutKeyValueCommand#perform:113 where maxIdleTimeMillis has right value = 60000. So I tried to find ways how ReadCommitedEntiry can be send to commit without maxIdleTime set. And this place is the same PutKeyValueCommand#perform but another if statement branch: line 92, where entryValue variable is PutFromLoadValidator$PendingPutMap instance. The stack at this point is the following:

"Thread-21 (HornetQ-client-global-threads-819406422)"@29,824 in group "HornetQ-client-global-threads-819406422": RUNNING
          perform():92, PutKeyValueCommand {org.infinispan.commands.write}
          handleDefault():83, CallInterceptor {org.infinispan.interceptors}
          visitPutKeyValueCommand():62, AbstractVisitor {org.infinispan.commands}
          acceptVisitor():77, PutKeyValueCommand {org.infinispan.commands.write}
          invokeNextInterceptor():116, CommandInterceptor {org.infinispan.interceptors.base}
          invokeNextAndApplyChanges():212, EntryWrappingInterceptor {org.infinispan.interceptors}
          visitPutKeyValueCommand():147, EntryWrappingInterceptor {org.infinispan.interceptors}
          acceptVisitor():77, PutKeyValueCommand {org.infinispan.commands.write}
          invokeNextInterceptor():116, CommandInterceptor {org.infinispan.interceptors.base}
          visitPutKeyValueCommand():68, NonTransactionalLockingInterceptor {org.infinispan.interceptors.locking}
          acceptVisitor():77, PutKeyValueCommand {org.infinispan.commands.write}
          invokeNextInterceptor():116, CommandInterceptor {org.infinispan.interceptors.base}
          handleDefault():130, CommandInterceptor {org.infinispan.interceptors.base}
          visitPutKeyValueCommand():62, AbstractVisitor {org.infinispan.commands}
          acceptVisitor():77, PutKeyValueCommand {org.infinispan.commands.write}
          invokeNextInterceptor():116, CommandInterceptor {org.infinispan.interceptors.base}
          handleAll():132, InvocationContextInterceptor {org.infinispan.interceptors}
          handleDefault():91, InvocationContextInterceptor {org.infinispan.interceptors}
          visitPutKeyValueCommand():62, AbstractVisitor {org.infinispan.commands}
          acceptVisitor():77, PutKeyValueCommand {org.infinispan.commands.write}
          invoke():345, InterceptorChain {org.infinispan.interceptors}
          executeCommandAndCommitIfNeeded():1006, CacheImpl {org.infinispan}
          putIfAbsent():716, CacheImpl {org.infinispan}
          putIfAbsent():707, CacheImpl {org.infinispan}
          putIfAbsent():78, CacheSupport {org.infinispan}
          registerPendingPut():388, PutFromLoadValidator {org.hibernate.cache.infinispan.access}
          get():74, TransactionalAccessDelegate {org.hibernate.cache.infinispan.access}
          get():36, TransactionalAccess {org.hibernate.cache.infinispan.collection}
          initializeCollectionFromCache():121, DefaultInitializeCollectionEventListener {org.hibernate.event.internal}
          onInitializeCollection():68, DefaultInitializeCollectionEventListener {org.hibernate.event.internal}
          initializeCollection():1804, SessionImpl {org.hibernate.internal}
          doWork():549, AbstractPersistentCollection$4 {org.hibernate.collection.internal}
          withTemporarySessionIfNeeded():234, AbstractPersistentCollection {org.hibernate.collection.internal}
          initialize():545, AbstractPersistentCollection {org.hibernate.collection.internal}
          read():124, AbstractPersistentCollection {org.hibernate.collection.internal}
          doWork():153, AbstractPersistentCollection$1 {org.hibernate.collection.internal}
          doWork():138, AbstractPersistentCollection$1 {org.hibernate.collection.internal}
          withTemporarySessionIfNeeded():234, AbstractPersistentCollection {org.hibernate.collection.internal}
          readSize():137, AbstractPersistentCollection {org.hibernate.collection.internal}
          size():114, PersistentList {org.hibernate.collection.internal}
          size():22, ProxyList {com.lognex.sklad.base.util}
          hasNext():351, AbstractList$Itr {java.util}

After that the instance procceded to commit in ReadCommitedEntry without maxIdleTime set.

[galder.zamarreno]

Well, if it reaches line 92, it means that putIfAbsent is not succesful because the entry was already present, so it won't make any changes to the container:

https://github.com/infinispan/infinispan/blob/5.1.8.Final/core/src/main/java/org/infinispan/commands/write/PutKeyValueCommand.java#L92

Can you check further if there's a situation where the entry contents are applied after succesful is false?

Also, can you try swapping Infinispan library for latest release which is 5.2.1.Final?

[davidfdr.davidfdr.gmail.com]

Hi

We has a setup with Jboss 7.1.0 final (with infinispan 5.1.6 (Brahma) and Hibernate 4.2.0. We are presencing memory leaks that may be related to this problem when using hibernate 2LC with infinispan. (standalone and default hibernate+infinispan configuration)

With hibernate statistics turned on, we are only seeing putCount number increasing and cache miss and hit are 0 (jmx mbeans).

Other symptom is that Hibertante session is not closing (Using SFSB + Extended persistent context).

We will try updating to Infinispan 5.2.1.Final and see if this problem persists.

Thank you in advance.