Terracotta Discussion Forums (LEGACY READ-ONLY ARCHIVE)

During load tests we randomly encountered state of lots of threads being stuck like shown below.
Because these were automated tests running on night we didn't capture full thread dumps (below are just stack traces coming from the application server hung thread notifications). We'll perform some more tests and if we encounter the same state we'll gather full thread dumps then.

Below you can see typical stack traces observed for all those hung threads, they refer to caches that are configured as read-write and they're replicated via RMI in the cluster by the way (I think we can disregards the read-write + RMI replication consistency issues described for example here: http://lists.terracotta.org/pipermail/ehcache-list/2011-April/000354.html for now as these shouldn't be related, the reason why they're read-write is simply coming from the history when nonstrict-read-write cache elements were being put and then removed which didn't cause what we required)

at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:964)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1282)
at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:731)
at net.sf.ehcache.store.chm.SelectableConcurrentHashMap$Segment.get(SelectableConcurrentHashMap.java:690)
at net.sf.ehcache.store.chm.SelectableConcurrentHashMap.get(SelectableConcurrentHashMap.java:308)
at net.sf.ehcache.store.MemoryStore.get(MemoryStore.java:326)
at net.sf.ehcache.Cache.get(Cache.java:1634)
at org.hibernate.cache.ehcache.internal.regions.EhcacheTransactionalDataRegion.get(EhcacheTransactionalDataRegion.java:115)
at org.hibernate.cache.ehcache.internal.strategy.AbstractReadWriteEhcacheAccessStrategy.get(AbstractReadWriteEhcacheAccessStrategy.java:77)
at org.hibernate.cache.ehcache.internal.nonstop.NonstopAwareEntityRegionAccessStrategy.get(NonstopAwareEntityRegionAccessStrategy.java:133)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:546)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:419)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:204)
at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:260)
at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:148)
at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1078)
at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1005)
at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:651)
at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:266)
at org.hibernate.type.TypeHelper.assemble(TypeHelper.java:113)
at org.hibernate.cache.internal.StandardQueryCache.get(StandardQueryCache.java:163)
at org.hibernate.loader.Loader.getResultFromQueryCache(Loader.java:2443)
at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2351)
at org.hibernate.loader.Loader.list(Loader.java:2324)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:490)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:195)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1247)
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:264)
...

at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:945)
at net.sf.ehcache.concurrent.ReadWriteLockSync.lock(ReadWriteLockSync.java:50)
at org.hibernate.cache.ehcache.internal.regions.EhcacheTransactionalDataRegion.writeLock(EhcacheTransactionalDataRegion.java:210)
at org.hibernate.cache.ehcache.internal.strategy.AbstractReadWriteEhcacheAccessStrategy.putFromLoad(AbstractReadWriteEhcacheAccessStrategy.java:102)
at org.hibernate.cache.ehcache.internal.nonstop.NonstopAwareEntityRegionAccessStrategy.putFromLoad(NonstopAwareEntityRegionAccessStrategy.java:195)
at org.hibernate.engine.internal.TwoPhaseLoad.doInitializeEntity(TwoPhaseLoad.java:224)
at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:134)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:1103)
at org.hibernate.loader.Loader.processResultSet(Loader.java:960)
at org.hibernate.loader.Loader.doQuery(Loader.java:910)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341)
at org.hibernate.loader.Loader.doList(Loader.java:2516)
at org.hibernate.loader.Loader.doList(Loader.java:2502)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2332)
at org.hibernate.loader.Loader.list(Loader.java:2327)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:490)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:195)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1247)
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:264)
...

at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:945)
at net.sf.ehcache.store.chm.SelectableConcurrentHashMap$Segment.remove(SelectableConcurrentHashMap.java:548)
at net.sf.ehcache.store.chm.SelectableConcurrentHashMap.remove(SelectableConcurrentHashMap.java:377)
at net.sf.ehcache.store.MemoryStore.remove(MemoryStore.java:359)
at net.sf.ehcache.store.NotifyingMemoryStore.evict(NotifyingMemoryStore.java:75)
at net.sf.ehcache.store.MemoryStore.removeElementChosenByEvictionPolicy(MemoryStore.java:609)
at net.sf.ehcache.store.MemoryStore.access$600(MemoryStore.java:95)
at net.sf.ehcache.store.MemoryStore$Participant.evict(MemoryStore.java:1243)
at net.sf.ehcache.pool.impl.FromLargestCachePoolEvictor.freeSpace(FromLargestCachePoolEvictor.java:49)
at net.sf.ehcache.pool.impl.AtomicPoolAccessor.add(AtomicPoolAccessor.java:71)
at net.sf.ehcache.pool.impl.AbstractPoolAccessor.add(AbstractPoolAccessor.java:67)
at net.sf.ehcache.store.MemoryStore.put(MemoryStore.java:266)
at net.sf.ehcache.Cache.putInternal(Cache.java:1500)
at net.sf.ehcache.Cache.put(Cache.java:1426)
at net.sf.ehcache.Cache.put(Cache.java:1391)
at org.hibernate.cache.ehcache.internal.regions.EhcacheTransactionalDataRegion.put(EhcacheTransactionalDataRegion.java:141)
at org.hibernate.cache.ehcache.internal.strategy.AbstractReadWriteEhcacheAccessStrategy.putFromLoad(AbstractReadWriteEhcacheAccessStrategy.java:107)
at org.hibernate.cache.ehcache.internal.nonstop.NonstopAwareEntityRegionAccessStrategy.putFromLoad(NonstopAwareEntityRegionAccessStrategy.java:195)
at org.hibernate.engine.internal.TwoPhaseLoad.doInitializeEntity(TwoPhaseLoad.java:224)
at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:134)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:1103)
at org.hibernate.loader.Loader.processResultSet(Loader.java:960)
at org.hibernate.loader.Loader.doQuery(Loader.java:910)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341)
at org.hibernate.loader.Loader.doList(Loader.java:2516)
at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2361)
at org.hibernate.loader.Loader.list(Loader.java:2324)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:490)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:195)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1247)
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:264)
...

Hibernate 4.1.9, Ehcache 2.7.0, java version "1.7.0_17" (WebSphere Application Server 8.5.5.0 at Solaris 10 x86_64)

alexsnaps wrote:

Still can't help with this... Also, you see threads waiting to acquire lock, but do you see threads holding locks ? Or do these threads hang forever ?

We don't have full thread dump at the moment because it was running unattended through the night. We'll try to gather some if this issue occurs in one of the following runs.

And yes, those threads remained in that state until one my colleague killed the JVM process in the morning.

Note that at approximately the same time there was an exhaustion of DB one connection pool, though that datasource was a different one, used by different component against separate DB schema.

Adding 2 full thread dumps, check out the following threads, any ideas welcome:
Found one Java-level deadlock:
=============================
"WebContainer : 109":
waiting for ownable synchronizer 0xfffffd7d04e59a18, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
which is held by "WebContainer : 58"
"WebContainer : 58":
waiting for ownable synchronizer 0xfffffd7d04e5a058, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
which is held by "WebContainer : 59"
"WebContainer : 59":
waiting for ownable synchronizer 0xfffffd7d04e596f8, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
which is held by "WebContainer : 69"
"WebContainer : 69":
waiting for ownable synchronizer 0xfffffd7d04e5a058, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
which is held by "WebContainer : 59"

We'll probably try -XX:+UseMembar for the following test, however we're running out of time at that target environment and won't be able to perform much more tests.