Terracotta Discussion Forums (LEGACY READ-ONLY ARCHIVE)

Hello,

We are implementing Terracotta Server Array 3.7.4 for distributed caching. I've found an odd problem with our NonStop cache configuration.

When setting a timeoutMillis of 3 seconds, we are getting an IllegalMonitorStateException. This seems to be happening on read operations which should be a non-blocking (not locking).

I'm seeing this exception on read operations within hibernate. You can see that in the CriteriaImpl.list part of the stack trace. Although, I'm puzzled with the reference to the EhcacheTransactionalDataRegion class in the stack trace. All of our hibernate caches are setup with a read/write strategy.

We had decided to set a timeout of 3 seconds for the cache to ensure the site doesn't get slow if there are network issues. I'd rather have cache return a null so that hibernate can pull the data from the database.

Here's the odd part. If I set the timeoutMillis to 30 seconds (the default), this error goes away. However, in that case I can see some intermittent slower requests. The statistics in developer console also report higher max get times also.

The IllegalMonitorStateException relates back to a thread wait() or notify() operation on a thread which you don't own the lock for. That seems very odd for a non-blocking read operation in a cache setup with an eventual consistency.

Any ideas? Why does lowering the NonStop cache timeout causing these problems?

tc-config.xml:
Code:

 <?xml version="1.0" encoding="UTF-8"?>
  <tc:tc-config xmlns:tc="http://www.terracotta.org/config"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://www.terracotta.org/schema/terracotta-6.xsd">
 
    <servers>
      <server host="172.28.32.40" name="prodcache1">
        <data>/opt/cache/logs/server-data</data>
        <logs>/opt/cache/logs/server-logs</logs>
      </server>
      <server host="172.28.32.47" name="prodcache2">
        <data>/opt/cache/logs/server-data</data>
        <logs>/opt/cache/logs/server-logs</logs>
      </server>
      <mirror-groups>
        <mirror-group group-name="prodgroup1">
          <members>
            <member>prodcache1</member>
            <member>prodcache2</member>
          </members>
        </mirror-group>
      </mirror-groups>
      <ha>
        <mode>networked-active-passive</mode>
          <networked-active-passive>
            <election-time>5</election-time>
          </networked-active-passive>
      </ha>
    </servers>
    
    <clients>
      <logs>/opt/cache/logs/client-logs</logs>
    </clients>
 
  </tc:tc-config>

cache config:
Code:

 	<defaultCache
 		maxEntriesLocalHeap="1000"
 		eternal="false"
 		timeToIdleSeconds="3600"
 		statistics="true"
 	>
 		<persistence strategy="distributed" synchronousWrites="false"/>
 		<terracotta clustered="true" consistency="eventual" synchronousWrites="false">
 			<nonstop immediateTimeout="false" timeoutMillis="3000">
 				<timeoutBehavior type="noop" />
 			</nonstop>
 		</terracotta>
 		<bootstrapCacheLoaderFactory class="net.sf.ehcache.terracotta.TerracottaBootstrapCacheLoaderFactory" 
 			properties="bootstrapAsynchronously=true,
 				interval=3600,
 				immediateShutdown=true,
 				snapshotOnShutDown=false,
 				doKeySnapshot=true,
 				useDedicatedThread=false"/>
 	</defaultCache>

Exception:
Code:

 Caused by: org.hibernate.cache.CacheException: net.sf.ehcache.CacheException: java.lang.IllegalMonitorStateException
 	at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.writeUnlock(EhcacheTransactionalDataRegion.java:219)
 	at net.sf.ehcache.hibernate.strategy.AbstractReadWriteEhcacheAccessStrategy.putFromLoad(AbstractReadWriteEhcacheAccessStrategy.java:99)
 	at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.putFromLoad(NonstopAwareEntityRegionAccessStrategy.java:180)
 	at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:179)
 	at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:877)
 	at org.hibernate.loader.Loader.doQuery(Loader.java:752)
 	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
 	at org.hibernate.loader.Loader.doList(Loader.java:2228)
 	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2125)
 	at org.hibernate.loader.Loader.list(Loader.java:2120)
 	at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:118)
 	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1596)
 	at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
 	at com.liferay.portal.dao.orm.hibernate.DynamicQueryImpl.list(DynamicQueryImpl.java:95)
 	at com.liferay.portal.dao.orm.hibernate.DynamicQueryImpl.list(DynamicQueryImpl.java:91)
 	at com.liferay.portlet.calendar.service.persistence.CalEventPersistenceImpl.findWithDynamicQuery(CalEventPersistenceImpl.java:2061)
 	... 211 more
 Caused by: net.sf.ehcache.CacheException: java.lang.IllegalMonitorStateException
 	at net.sf.ehcache.constructs.nonstop.NonstopExecutorServiceImpl.execute(NonstopExecutorServiceImpl.java:108)
 	at net.sf.ehcache.constructs.nonstop.store.ExecutorServiceStore.executeWithExecutor(ExecutorServiceStore.java:160)
 	at net.sf.ehcache.constructs.nonstop.store.ExecutorServiceStore.executeWithExecutor(ExecutorServiceStore.java:129)
 	at net.sf.ehcache.constructs.nonstop.store.ExecutorServiceStore.executeClusterOperation(ExecutorServiceStore.java:1185)
 	at net.sf.ehcache.constructs.nonstop.store.NonstopStoreImpl.executeClusterOperation(NonstopStoreImpl.java:704)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync.unlock(NonstopSync.java:115)
 	at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.writeUnlock(EhcacheTransactionalDataRegion.java:214)
 	... 226 more
 Caused by: java.lang.IllegalMonitorStateException
 	at com.tc.object.locks.ClientLockImpl.release(ClientLockImpl.java:664)
 	at com.tc.object.locks.ClientLockImpl.unlock(ClientLockImpl.java:115)
 	at com.tc.object.locks.ClientLockManagerImpl.unlock(ClientLockManagerImpl.java:181)
 	at com.tc.object.bytecode.ManagerImpl.unlock(ManagerImpl.java:951)
 	at org.terracotta.locking.TerracottaLock.unlock(TerracottaLock.java:128)
 	at org.terracotta.modules.ehcache.concurrency.TcSync.unlock(TcSync.java:75)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync$LockOperationType$2.performOperation(NonstopSync.java:220)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync$ExplicitLockingClusterOperationImpl.performClusterOperation(NonstopSync.java:141)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync$ExplicitLockingClusterOperationImpl.performClusterOperation(NonstopSync.java:124)
 	at net.sf.ehcache.constructs.nonstop.store.ClusterOperationCallableImpl.call(ClusterOperationCallableImpl.java:46)
 	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
 	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
 	at net.sf.ehcache.constructs.nonstop.NonstopThreadPool$WorkerThreadLocal$1.run(NonstopThreadPool.java:193)
 	at net.sf.ehcache.constructs.nonstop.NonstopThreadPool$Worker.run(NonstopThreadPool.java:243)

Anybody else seen this issue?

I have an update. Even after removing the timoutMillis setting (and defaulting to 30sec), this issue has come back. It seems to be on both transactional and readonly requests.

Here's a couple more examples:

Code:

 Caused by: org.hibernate.cache.CacheException: net.sf.ehcache.CacheException: java.lang.IllegalMonitorStateException
 	at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.writeUnlock(EhcacheTransactionalDataRegion.java:219)
 	at net.sf.ehcache.hibernate.strategy.AbstractReadWriteEhcacheAccessStrategy.putFromLoad(AbstractReadWriteEhcacheAccessStrategy.java:99)
 	at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.putFromLoad(NonstopAwareEntityRegionAccessStrategy.java:180)
 	at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:179)
 	at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:877)
 	at org.hibernate.loader.Loader.doQuery(Loader.java:752)
 	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
 	at org.hibernate.loader.Loader.doList(Loader.java:2228)
 	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2125)
 	at org.hibernate.loader.Loader.list(Loader.java:2120)
 	at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:118)
 	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1596)
 	at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
 	at com.liferay.portal.dao.orm.hibernate.DynamicQueryImpl.list(DynamicQueryImpl.java:95)
 	at com.liferay.portal.dao.orm.hibernate.DynamicQueryImpl.list(DynamicQueryImpl.java:91)
 	at com.liferay.portlet.calendar.service.persistence.CalEventPersistenceImpl.findWithDynamicQuery(CalEventPersistenceImpl.java:2061)
 	... 208 more
 Caused by: net.sf.ehcache.CacheException: java.lang.IllegalMonitorStateException
 	at net.sf.ehcache.constructs.nonstop.NonstopExecutorServiceImpl.execute(NonstopExecutorServiceImpl.java:108)
 	at net.sf.ehcache.constructs.nonstop.store.ExecutorServiceStore.executeWithExecutor(ExecutorServiceStore.java:160)
 	at net.sf.ehcache.constructs.nonstop.store.ExecutorServiceStore.executeWithExecutor(ExecutorServiceStore.java:129)
 	at net.sf.ehcache.constructs.nonstop.store.ExecutorServiceStore.executeClusterOperation(ExecutorServiceStore.java:1185)
 	at net.sf.ehcache.constructs.nonstop.store.NonstopStoreImpl.executeClusterOperation(NonstopStoreImpl.java:704)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync.unlock(NonstopSync.java:115)
 	at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.writeUnlock(EhcacheTransactionalDataRegion.java:214)
 	... 223 more
 Caused by: java.lang.IllegalMonitorStateException
 	at com.tc.object.locks.ClientLockImpl.release(ClientLockImpl.java:664)
 	at com.tc.object.locks.ClientLockImpl.unlock(ClientLockImpl.java:115)
 	at com.tc.object.locks.ClientLockManagerImpl.unlock(ClientLockManagerImpl.java:181)
 	at com.tc.object.bytecode.ManagerImpl.unlock(ManagerImpl.java:951)
 	at org.terracotta.locking.TerracottaLock.unlock(TerracottaLock.java:128)
 	at org.terracotta.modules.ehcache.concurrency.TcSync.unlock(TcSync.java:75)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync$LockOperationType$2.performOperation(NonstopSync.java:220)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync$ExplicitLockingClusterOperationImpl.performClusterOperation(NonstopSync.java:141)
 	at net.sf.ehcache.constructs.nonstop.concurrency.NonstopSync$ExplicitLockingClusterOperationImpl.performClusterOperation(NonstopSync.java:124)
 	at net.sf.ehcache.constructs.nonstop.store.ClusterOperationCallableImpl.call(ClusterOperationCallableImpl.java:46)
 	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
 	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
 	at net.sf.ehcache.constructs.nonstop.NonstopThreadPool$WorkerThreadLocal$1.run(NonstopThreadPool.java:193)
 	at net.sf.ehcache.constructs.nonstop.NonstopThreadPool$Worker.run(NonstopThreadPool.java:243)
 	... 1 more

Most of the errors just show this cause, and it doesn't say much:

Code:

 Caused by: com.liferay.portal.kernel.dao.orm.ORMException: net.sf.ehcache.CacheException: java.lang.IllegalMonitorStateException
 	at com.liferay.portal.dao.orm.hibernate.ExceptionTranslator.translate(ExceptionTranslator.java:41)
 	at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:89)
 	at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:74)
 	at com.liferay.portal.service.persistence.ResourcePersistenceImpl.fetchByC_P(ResourcePersistenceImpl.java:649)
 	... 126 more

I'm guessing that nobody is using this forum because I've gotten no responses.

I do have one more update if anyone is willing to help.

The issue seems to creep up a day later. It'll work fine for a day, then we'll start getting these errors at an alarming rate.

Code:

 Caused by: com.liferay.portal.kernel.dao.orm.ORMException: net.sf.ehcache.CacheException: java.lang.IllegalMonitorStateException
 	at com.liferay.portal.dao.orm.hibernate.ExceptionTranslator.translate(ExceptionTranslator.java:41)
 	at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:89)
 	at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:74)
 	at com.tbb.gym.service.persistence.WorkoutSessionFinderImpl.findActiveSessions(WorkoutSessionFinderImpl.java:165)
 	... 209 more

All,

First, I'd like to say that I'm disappointed that nobody was able to post any responses to this issue. It appears that the developers on this product do not monitor their own forum.

Second, I'd like to note the fix I found for this issue.

Here's what I found.

The nonstop cache timeout is used for both get, put, & lock operations. In the case of a put, it's simple because we'll return a null and hibernate will follow up by pulling the data from the database.

In the case of a put operation, it's also simple because the operation will timeout and your item will not be added to cache. That's not a big deal if you don't require a "solid" cache. If that was the case, you'd likely be using a strict cache anyway. The next call will just get the data from the database.

In the case of a lock operation, the lock will timeout and the object will not be locked. The handleNonstopCacheException method within the HibernateNonstopCacheExceptionHandler object will be called. This method checks for the timeoutBehavior setting and either throws the exception or swallows the exception with debug logging.

Here's the problem. After a lock operation times out, the putFromLoad method in the AbstractReadWriteEhcacheAccessStrategy object will then add the object to cache anyway (without the lock). Then in the finally block, it will attempt to unlock the object. In this scenario, you don't own the lock for the object that the code is trying to unlock. That causes the JVM to throw an java.lang.IllegalMonitorStateException exception. The code should verify it has the lock before trying to remove the lock.

Here's the change I made to resolve the bug.

I updated the writeUnlock method within the EhcacheTransactionalDataRegion object. I added a check to ensure the thread has the lock before trying to unlock the object.

Code:

 Sync sync = lockProvider.getSyncForKey(key);
 if (sync.isHeldByCurrentThread(LockType.WRITE)) {
 	sync.unlock(LockType.WRITE);
 }

I recommend that they fix this issue in the next release......if not, you can always fix the EhcacheTransactionalDataRegion object yourself and update the ehcache-core-2.6.5.jar.