[Logo] Terracotta Discussion Forums (LEGACY READ-ONLY ARCHIVE)
  [Search] Search   [Recent Topics] Recent Topics   [Members]  Member Listing   [Groups] Back to home page 
[Register] Register /  [Login] Login 
[Expert]
Deadlocked Ehcache app -BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked() etc.  XML
Forum Index -> Ehcache
Author Message
[Post New]12/18/2012 05:05:18
    Subject: Deadlocked Ehcache app -BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked() etc.
[Up]
k1eran

neo

Joined: 08/10/2010 15:57:53
Messages: 5
Offline
Hi,

We sometimes get deadlocked ehcache 2.5.0 applications. Partial thread-dump with blocked threads below show e.g.
BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked(TCObjectServerMapImpl.java:300)

I see in http://jira.terracotta.org/jira/browse/EHCTERR-14
"Performance problema with terracotta 3.6.1 and ehcache 2.5.1" by fernando Paris
similar looking issues that were resoved via the "concurrency parameter per cache" but am unclear from
section of http://terracotta.org/documentation/enterprise-ehcache/reference-guide#86549
which says :
"concurrency – Sets the number of segments for the map backing the underlying server store managed by the Terracotta Server Array. If concurrency is not explicitly set (or set to "0"), the system selects an optimized value."
if this is right approach for preventing my deadlocks shown below?
Is it a just a optimization and deadlocks themselves are separate root cause?

My ehcache.xml <terracotta> entry is the default i.e.
Code:
     <cache name="DEVICES"
             maxElementsInMemory="1000"
             maxElementsOnDisk="10000"
             eternal="false"
             timeToIdleSeconds="0"
             timeToLiveSeconds="0"
             memoryStoreEvictionPolicy="LFU">
            <cacheEventListenerFactory class="net.sf.ehcache.event.TerracottaCacheEventReplicationFactory" />
             <terracotta/>         
      </cache>


Today experimenting with
Code:
     <terracotta clustered="true" consistency="strong" synchronousWrites="true"/>

but not sure yet if that will help. I know above options impact performance but emphasis is on stablility not performance at the moment!

Code:
 
 Thread dump Java HotSpot(TM) 64-Bit Server VM (19.1-b02 mixed mode):
 
 "Dispatcher-4" prio=10 tid=0x00007fab4c009800 nid=0x3f0e waiting for monitor entry [0x00007faa578f5000]
    java.lang.Thread.State: BLOCKED (on object monitor)
         at com.tc.object.TCObjectServerMapImpl.getValueUnlocked(TCObjectServerMapImpl.java:300)
         - waiting to lock <0x0000000782440ef0> (a java.lang.Object)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.unlockedGet(ConcurrentDistributedServerMapDso.java:353)
         at com.terracotta.toolkit.collections.ConcurrentDistributedMapDsoArray.unlockedGet(ConcurrentDistributedMapDsoArray.java:176)
         at org.terracotta.collections.ConcurrentDistributedMap.unlockedGet(ConcurrentDistributedMap.java:224)
         at org.terracotta.cache.TerracottaDistributedCache.getNonExpiredEntry(TerracottaDistributedCache.java:235)
         at org.terracotta.cache.TerracottaDistributedCache.getNonExpiredEntryUnlocked(TerracottaDistributedCache.java:157)
         at org.terracotta.cache.TerracottaDistributedCache.unlockedGetTimestampedValue(TerracottaDistributedCache.java:654)
         at org.terracotta.modules.ehcache.store.ClusteredStoreBackendImpl.unlockedGetTimestampedValue(ClusteredStoreBackendImpl.java:183)
         at org.terracotta.modules.ehcache.store.backend.NonStrictBackend.get(NonStrictBackend.java:185)
         at org.terracotta.modules.ehcache.store.ClusteredStore.doGet(ClusteredStore.java:411)
         at org.terracotta.modules.ehcache.store.ClusteredStore.getQuiet(ClusteredStore.java:402)
         at org.terracotta.modules.ehcache.store.ClusteredSafeStore.getQuiet(ClusteredSafeStore.java:288)
         at net.sf.ehcache.Cache.searchInStoreWithoutStats(Cache.java:2101)
         at net.sf.ehcache.Cache.get(Cache.java:1630)
         at net.sf.ehcache.Cache.get(Cache.java:1597)
 
 
 "Dispatcher-1" prio=10 tid=0x00007fab20004800 nid=0x3eda waiting for monitor entry [0x00007fab36cf9000]
    java.lang.Thread.State: BLOCKED (on object monitor)
         at org.terracotta.cache.serialization.ObjectStreamClassSerializer$SerializableDataKey.__tc_getserializedOsc(ObjectStreamClassSerializer.java)
         - waiting to lock <0x00000007a7882aa8> (a com.tc.object.ObjectID)
         at org.terracotta.cache.serialization.ObjectStreamClassSerializer$SerializableDataKey.getSerializedOsc(ObjectStreamClassSerializer.java:293)
         at org.terracotta.cache.serialization.ObjectStreamClassSerializer.equals(ObjectStreamClassSerializer.java:319)
         at org.terracotta.cache.serialization.ObjectStreamClassSerializer.access$000(ObjectStreamClassSerializer.java:30)
         at org.terracotta.cache.serialization.ObjectStreamClassSerializer$ComparisonSerializableDataKey.equals(ObjectStreamClassSerializer.java:212)
         at com.terracotta.toolkit.collections.chm.ConcurrentHashMap$Segment.get(ConcurrentHashMap.java:296)
         at com.terracotta.toolkit.collections.chm.ConcurrentHashMap.get(ConcurrentHashMap.java:686)
         at com.terracotta.toolkit.collections.ConcurrentDistributedMapDso.unsafeGet(ConcurrentDistributedMapDso.java:179)
         at com.terracotta.toolkit.collections.ConcurrentDistributedMapDsoArray.unsafeGet(ConcurrentDistributedMapDsoArray.java:255)
         at org.terracotta.collections.ConcurrentDistributedMap.unsafeGet(ConcurrentDistributedMap.java:208)
         at org.terracotta.cache.serialization.ObjectStreamClassSerializer.getMappingFor(ObjectStreamClassSerializer.java:115)
         at org.terracotta.cache.serialization.DsoSerializationStrategy$OOS.writeClassDescriptor(DsoSerializationStrategy.java:165)
         at java.io.ObjectOutputStream.writeNonProxyDesc(ObjectOutputStream.java:1253)
         at java.io.ObjectOutputStream.writeClassDesc(ObjectOutputStream.java:1211)
         at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1395)
         at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
         at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1518)
         at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1483)
         at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1400)
         at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
         at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1518)
         at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1483)
         at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1400)
         at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
         at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:330)
         at net.sf.ehcache.AbstractElementData.write(AbstractElementData.java:53)
         at org.terracotta.modules.ehcache.store.ElementSerializationStrategy.serialize(ElementSerializationStrategy.java:33)
         at org.terracotta.modules.ehcache.store.ElementSerializationStrategy.serialize(ElementSerializationStrategy.java:15)
         at org.terracotta.modules.ehcache.event.ClusteredEventReplicator.getElementDataForDMI(ClusteredEventReplicator.java:164)
         at org.terracotta.modules.ehcache.event.ClusteredEventReplicator.notifyElementPut(ClusteredEventReplicator.java:109)
         at net.sf.ehcache.event.TerracottaCacheEventReplication.notifyElementPut(TerracottaCacheEventReplication.java:50)
         at net.sf.ehcache.event.RegisteredEventListeners.notifyListener(RegisteredEventListeners.java:294)
         at net.sf.ehcache.event.RegisteredEventListeners.invokeListener(RegisteredEventListeners.java:284)
         at net.sf.ehcache.event.RegisteredEventListeners.internalNotifyElementPut(RegisteredEventListeners.java:144)
         at net.sf.ehcache.event.RegisteredEventListeners.notifyElementPut(RegisteredEventListeners.java:122)
         at net.sf.ehcache.Cache.notifyPutInternalListeners(Cache.java:1521)
         at net.sf.ehcache.Cache.putInternal(Cache.java:1496)
         at net.sf.ehcache.Cache.put(Cache.java:1417)
         at net.sf.ehcache.Cache.put(Cache.java:1382)
 
         "EmsScheduler_Worker-1" prio=10 tid=0x00007fab64e9f000 nid=0x3d95 waiting for monitor entry [0x00007faa5e1d4000]
    java.lang.Thread.State: BLOCKED (on object monitor)
         at com.tc.object.TCObjectServerMapImpl.getValueUnlocked(TCObjectServerMapImpl.java:300)
         - waiting to lock <0x00000007823fc658> (a java.lang.Object)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.unlockedGet(ConcurrentDistributedServerMapDso.java:353)
         at com.terracotta.toolkit.collections.ConcurrentDistributedMapDsoArray.unlockedGet(ConcurrentDistributedMapDsoArray.java:176)
         at org.terracotta.collections.ConcurrentDistributedMap.unlockedGet(ConcurrentDistributedMap.java:224)
         at org.terracotta.cache.TerracottaDistributedCache.getNonExpiredEntry(TerracottaDistributedCache.java:235)
         at org.terracotta.cache.TerracottaDistributedCache.getNonExpiredEntryUnlocked(TerracottaDistributedCache.java:157)
         at org.terracotta.cache.TerracottaDistributedCache.unlockedGetTimestampedValue(TerracottaDistributedCache.java:654)
         at org.terracotta.modules.ehcache.store.ClusteredStoreBackendImpl.unlockedGetTimestampedValue(ClusteredStoreBackendImpl.java:183)
         at org.terracotta.modules.ehcache.store.backend.NonStrictBackend.get(NonStrictBackend.java:185)
         at org.terracotta.modules.ehcache.store.ClusteredStore.doGet(ClusteredStore.java:411)
         at org.terracotta.modules.ehcache.store.ClusteredStore.getQuiet(ClusteredStore.java:402)
         at org.terracotta.modules.ehcache.store.ClusteredSafeStore.getQuiet(ClusteredSafeStore.java:288)
         at net.sf.ehcache.Cache.searchInStoreWithoutStats(Cache.java:2101)
         at net.sf.ehcache.Cache.get(Cache.java:1630)
         at net.sf.ehcache.Cache.get(Cache.java:1597)

Best Regards,
Kieran
[Post New]12/18/2012 14:37:37
    Subject: Re:Deadlocked Ehcache app -BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked() etc.
[Up]
vfunshte

neo

Joined: 12/18/2012 14:34:46
Messages: 3
Offline
Could you post the full thread dump from the app by any chance? It will help to see what threads actually hold locks on the objects that others are blocked on. Also, server log and/or thread dump around the time of the deadlock would be helpful as well. Thanks.
[Post New]12/18/2012 16:32:43
    Subject: Re:Deadlocked Ehcache app -BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked() etc.
[Up]
k1eran

neo

Joined: 08/10/2010 15:57:53
Messages: 5
Offline
Here is the other partial stack-trace for reference to the first object that has a blocked thread.

Code:
 "Dispatcher-0" prio=10 tid=0x00007fab5c008800 nid=0x3ed4 in Object.wait() [0x00007faa5c9bb000]
    java.lang.Thread.State: TIMED_WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         at com.tc.object.RemoteServerMapManagerImpl.waitForResult(RemoteServerMapManagerImpl.java:157)
         at com.tc.object.RemoteServerMapManagerImpl.getMappingForKey(RemoteServerMapManagerImpl.java:99)
         - locked <0x0000000781ca2038> (a com.tc.object.RemoteServerMapManagerImpl)
         at com.tc.object.TCObjectServerMapImpl.getValueForKeyFromServer(TCObjectServerMapImpl.java:405)
         at com.tc.object.TCObjectServerMapImpl.getValueUnlocked(TCObjectServerMapImpl.java:304)
         - locked <0x0000000782440ef0> (a java.lang.Object)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.unlockedGet(ConcurrentDistributedServerMapDso.java:353)
         at com.terracotta.toolkit.collections.ConcurrentDistributedMapDsoArray.unlockedGet(ConcurrentDistributedMapDsoArray.java:176)
         at org.terracotta.collections.ConcurrentDistributedMap.unlockedGet(ConcurrentDistributedMap.java:224)
         at org.terracotta.cache.TerracottaDistributedCache.getNonExpiredEntry(TerracottaDistributedCache.java:235)
         at org.terracotta.cache.TerracottaDistributedCache.getNonExpiredEntryUnlocked(TerracottaDistributedCache.java:157)
         at org.terracotta.cache.TerracottaDistributedCache.unlockedGetTimestampedValue(TerracottaDistributedCache.java:654)
         at org.terracotta.modules.ehcache.store.ClusteredStoreBackendImpl.unlockedGetTimestampedValue(ClusteredStoreBackendImpl.java:183)
         at org.terracotta.modules.ehcache.store.backend.NonStrictBackend.get(NonStrictBackend.java:185)
         at org.terracotta.modules.ehcache.store.ClusteredStore.doGet(ClusteredStore.java:411)
         at org.terracotta.modules.ehcache.store.ClusteredStore.getQuiet(ClusteredStore.java:402)
         at org.terracotta.modules.ehcache.store.ClusteredSafeStore.getQuiet(ClusteredSafeStore.java:288)
         at net.sf.ehcache.Cache.searchInStoreWithoutStats(Cache.java:2101)
         at net.sf.ehcache.Cache.get(Cache.java:1630)
         at net.sf.ehcache.Cache.get(Cache.java:1597)


Also we see in TC server log GC warnings around this time we're and investigating if it happens above or after above problem.

Code:
 2012-12-17 12:21:13,869 [TC Memory Monitor] WARN com.tc.runtime.logging.LongGCLogger - Detected long GC>8,000ms. GC count:1. GC Time:44,572ms. Frequent long GC cycles cause severe performance degradation. Use Terracotta BigMemory to eliminate them.
[Post New]12/18/2012 16:43:09
    Subject: Re:Deadlocked Ehcache app -BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked() etc.
[Up]
vfunshte

neo

Joined: 12/18/2012 14:34:46
Messages: 3
Offline
Would it be possible to get the full client thread dump, as well as the server log?
[Post New]12/20/2012 02:11:12
    Subject: Re:Deadlocked Ehcache app -BLOCKED at com.tc.object.TCObjectServerMapImpl.getValueUnlocked() etc.
[Up]
ssubbiah

jedi

Joined: 05/24/2006 14:25:22
Messages: 117
Location: Saravanan Subbiah
Offline
Please jira ur request here http://jira.terracotta.org and attach the thread dumps / cluster dumps there for analysis.
Saravanan Subbiah
Terracotta Engineer
 
Forum Index -> Ehcache
Go to:   
Powered by JForum 2.1.7 © JForum Team