MutableConfig causes too much lock contention

Type: Bug
Status: Closed
Priority: 1 Critical
Resolution: Fixed
Component/s: Forge
Labels:

Assignee: kkannaiy
Reporter: nelrahma
Created: May 27, 2009
Votes: 0
Watchers: 1
Updated:
February 12, 2013
Resolved:
May 30, 2009

Attachments

wharley (14.00 k) text/plain cdv-1278.txt

Description

Having HibernateCache using the MutableConfig class causes too much contention when using Hibernate second level cache.

When a get occurs on the cache, it checks to see if eviction is enabled. this entails checking the TTI and TTL values. In MutableConfig a DSO Lock is acquired when reading these values. Since it is the same lock, all other threads doing a get is getting blocked as demonstrated in the stacktrace below.

Since it is the same lock, they all hash to the same ClientLockManagerImpl, so it blocks on the call to lock.

The effect of this contention is significant. In our ReadOnly case, we went from 28k app TPS to 18k app TPS by using MutableConfig.

“PerAppThread-14” - Thread t@126 java.lang.Thread.State: BLOCKED on com.tc.management.beans.tx.ClientTxMonitor@64171cdc owned by: PerAppThread-8 at com.tc.management.beans.tx.ClientTxMonitor.committedReadTransaction(ClientTxMonitor.java:137) at com.tc.object.tx.ClientTransactionManagerImpl.commitInternal(ClientTransactionManagerImpl.java:520) at com.tc.object.tx.ClientTransactionManagerImpl.commit(ClientTransactionManagerImpl.java:499) at com.tc.object.tx.ClientTransactionManagerImpl.commit(ClientTransactionManagerImpl.java:427) at com.tc.object.bytecode.ManagerImpl.monitorExit(ManagerImpl.java:551) at com.tc.object.bytecode.ManagerUtil.monitorExit(ManagerUtil.java:534) at java.util.concurrent.locks.ReentrantReadWriteLock$DsoLock.unlock(ReentrantReadWriteLock.java:74) at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java) at org.terracotta.modules.dmap.MutableConfig.getMaxTTISeconds(MutableConfig.java:77) at org.terracotta.modules.dmap.MutableConfig.isEvictionEnabled(MutableConfig.java:191) at org.terracotta.modules.dmap.impl.ClusteredDistributedMap.getNonExpiredEntry(ClusteredDistributedMap.java:173) at org.terracotta.modules.dmap.impl.ClusteredDistributedMap.getEntry(ClusteredDistributedMap.java:158) at org.terracotta.modules.hibernatecache.TerracottaHibernateCache.get(TerracottaHibernateCache.java:129) at org.hibernate.cache.NonstrictReadWriteCache.get(NonstrictReadWriteCache.java:69) at org.hibernate.cache.impl.bridge.EntityAccessStrategyAdapter.get(EntityAccessStrategyAdapter.java:55) at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:524) at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:397) at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165) at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:207) at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:126) at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905) at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:873) at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:590) at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:219) at org.hibernate.type.TypeFactory.assemble(TypeFactory.java:443) at org.hibernate.cache.entry.CacheEntry.assemble(CacheEntry.java:119) at org.hibernate.cache.entry.CacheEntry.assemble(CacheEntry.java:105) at org.hibernate.event.def.DefaultLoadEventListener.assembleCacheEntry(DefaultLoadEventListener.java:587) at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:542) at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:397) at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165) at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:207) at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:126) at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905) at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:873) at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:590) at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:219) at org.hibernate.collection.PersistentSet.initializeFromCache(PersistentSet.java:147) at org.hibernate.cache.entry.CollectionCacheEntry.assemble(CollectionCacheEntry.java:58) at org.hibernate.event.def.DefaultInitializeCollectionEventListener.initializeCollectionFromCache(DefaultInitializeCollectionEventListener.java:159) at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:71) at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1743) at org.hibernate.collection.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:476) at org.hibernate.engine.StatefulPersistenceContext.initializeNonLazyCollections(StatefulPersistenceContext.java:867) at org.hibernate.event.def.DefaultLoadEventListener.assembleCacheEntry(DefaultLoadEventListener.java:614) at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:542) at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:397) at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165) at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:207) at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:126) at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905) at org.hibernate.impl.SessionImpl.get(SessionImpl.java:842) at org.hibernate.impl.SessionImpl.get(SessionImpl.java:835) at org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:182) at sun.reflect.GeneratedMethodAccessor25.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:194) at $Proxy15.find(Unknown Source) at org.springframework.samples.petclinic.jpa.EntityManagerClinic.loadOwner(EntityManagerClinic.java:70) at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy17.loadOwner(Unknown Source) at org.terracotta.petclinic.perftest.PetClinicPerfTestActions.getOwnerAccordingToFetchStrategy(PetClinicPerfTestActions.java:120) at org.terracotta.petclinic.perftest.PetClinicPerfTestActions.getOwner(PetClinicPerfTestActions.java:38) at org.terracotta.petclinic.perftest.PetClinicPerfTestActions$FastClassByCGLIB$6a48c588.invoke() at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191) at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:628) at org.terracotta.petclinic.perftest.PetClinicPerfTestActions$$EnhancerByCGLIB$$aa5cf164.getOwner() at org.terracotta.petclinic.perftest.type.ReadOnlyTest.doTestBody(ReadOnlyTest.java:14) at org.terracotta.petclinic.perftest.AbstractPerfTest.doTestBody(AbstractPerfTest.java:341) at org.terracotta.petclinic.perftest.AbstractPerfTest.runTest(AbstractPerfTest.java:472) at org.terracotta.petclinic.perftest.AbstractPerfTest.access$000(AbstractPerfTest.java:32) at org.terracotta.petclinic.perftest.AbstractPerfTest$1.run(Ab

Comments

Saravanan Subbiah 2009-05-27

Nabib reverted it to Immuatable config for now in revision 15948

Alex Miller 2009-05-27

I don’t disagree with the possibility that MutableConfig is an issue (particularly if you’ve confirmed with ImmutableConfig as an alternative). But this particular stack trace doesn’t indicate MutableConfig - it just is the normal read locked get to look up the data and does not involve the config at all. It would be helpful if you could attach a better stack trace.

Fiona OShea 2009-05-27

Please update with latest status. thanks

Walter Harley 2009-05-27

The stack trace originally posted to the Jira was incorrect; Nabib has replaced it with the correct trace. The contention is on the monitor of the ClientLockManagerImpl instance, caused by lots of threads trying to read the lockId map in order to get the same lock, the lock on the MutableConfig.

We can address this by making the map-evictor code use a local (volatile transient) MutableConfig instance (actually could probably be an ImmutableConfig), which gets updated from the clustered one on every evictor cycle.

Nabib will change the cache back to use MutableConfig, so that the admin console is fixed; the perf test guys will use a local patch rather than trunk. I’ll make the perf change so that trunk works fast again, but in the interest of stability, probably won’t check it in till after the beta has been cut.

Nabib El-Rahman 2009-05-27

“RMI TCP Connection(15)-10.0.0.176” - Thread t@133 java.lang.Thread.State: RUNNABLE at sun.management.ThreadImpl.dumpThreads0(Native Method) at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:374) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.sun.jmx.mbeanserver.ConvertingMethod.invokeWithOpenReturn(ConvertingMethod.java:167) at com.sun.jmx.mbeanserver.MXBeanIntrospector.invokeM2(MXBeanIntrospector.java:96) at com.sun.jmx.mbeanserver.MXBeanIntrospector.invokeM2(MXBeanIntrospector.java:33) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208) at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:120) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:262) at javax.management.StandardMBean.invoke(StandardMBean.java:391) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836) at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761) at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1426) at javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:72) at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1264) at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1359) at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:788) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305) at sun.rmi.transport.Transport$1.run(Transport.java:159) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:155) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619)

Locked ownable synchronizers: - locked java.util.concurrent.locks.ReentrantLock$FairSync@167ab528

“RMI TCP Connection(14)-10.0.0.176” - Thread t@132 java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) at java.io.BufferedInputStream.read(BufferedInputStream.java:237) - locked java.io.BufferedInputStream@104eb890 at java.io.FilterInputStream.read(FilterInputStream.java:66) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:517) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619)

Locked ownable synchronizers: - locked java.util.concurrent.locks.ReentrantLock$FairSync@2036fe4d

“JMX server connection timeout 131” - Thread t@131 java.lang.Thread.State: TIMED_WAITING on [I@283781d9 at java.lang.Object.wait(Native Method) at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:150) at java.lang.Thread.run(Thread.java:619)