Random TimeoutException in Infinispan Hibernate L2 cache when put a load
erangac Mar 4, 2015 6:00 AMI am using Infinispan as a hibernate L2 cache. In a normal load system running without an issue. But when load put into the system the following exception was thrown from the cache cluster. Even though this not causing a functional impact reporting an ERROR seems a problem.
Infinispan version : 5.3
Error log
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.interceptors.EntryWrappingInterceptor - Wrapping entry 'MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16'? true
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.container.EntryFactoryImpl - Exists in context? null
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.container.EntryFactoryImpl - Retrieved from container null
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.container.EntryFactoryImpl - Creating new entry.
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.interceptors.distribution.NonTxDistributionInterceptor - Not doing a remote get for key MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16 since entry is not affected by rehash or is already in data container. We are cosmos-db2-16474, owners are [cosmos-db2-16474, cosmos-db1-39743, cosmos-db1-5230, cosmos-db2-2169]
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.interceptors.CallInterceptor - Executing command: PutKeyValueCommand{key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ], putIfAbsent=true, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=1, version=null}, successful=true}.
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.remoting.rpc.RpcManagerImpl - cosmos-db2-16474 invoking PutKeyValueCommand{key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ], putIfAbsent=true, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=1, version=null}, successful=true} to recipient list null with options RpcOptions{timeout=20000, unit=MILLISECONDS, fifoOrder=true, totalOrder=false, responseFilter=null, responseMode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, skipReplicationQueue=false}
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.remoting.transport.jgroups.JGroupsTransport - dests=null, command=SingleRpcCommand{cacheName='Order.eventTypesStatusMap', command=PutKeyValueCommand{key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ], putIfAbsent=true, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=1, version=null}, successful=true}}, mode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, timeout=20000
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher - Replication task sending SingleRpcCommand{cacheName='Order.eventTypesStatusMap', command=PutKeyValueCommand{key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ], putIfAbsent=true, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=1, version=null}, successful=true}} to addresses null with response mode GET_NONE
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.marshall.AdaptiveBufferSizePredictor - Next predicted buffer size for object type 'org.infinispan.commands.remote.SingleRpcCommand' will be 3584
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.marshall.VersionAwareMarshaller - Wrote version 510
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.marshall.AdaptiveBufferSizePredictor - Next predicted buffer size for object type 'org.infinispan.commands.remote.SingleRpcCommand' will be 512
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.marshall.VersionAwareMarshaller - Wrote version 510
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.marshall.jboss.AbstractJBossMarshaller - Stop marshaller
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.marshall.jboss.AbstractJBossMarshaller - Stop marshaller
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher - real_dests=[cosmos-db1-5230, cosmos-db2-2169, cosmos-db1-39743]
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.remoting.rpc.RpcManagerImpl - Response(s) to SingleRpcCommand{cacheName='Order.eventTypesStatusMap', command=PutKeyValueCommand{key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ], putIfAbsent=true, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=1, version=null}, successful=true}} is {}
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.interceptors.EntryWrappingInterceptor - About to commit entry ReadCommittedEntry(783fea76){key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true}
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.container.entries.ReadCommittedEntry - Updating entry (key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16 removed=false valid=true changed=true created=true loaded=false value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c]
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.eviction.ActivationManagerImpl - Don't remove entry from shared cache store after activation.
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.interceptors.EntryWrappingInterceptor - The return value is null
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.util.concurrent.locks.LockManagerImpl - Attempting to unlock MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.util.concurrent.locks.containers.ReentrantPerEntryLockContainer - Unlocking lock instance for key MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.statetransfer.StateTransferManagerImpl - CommandTopologyId=39, localTopologyId=39
2015-03-03 16:50:32 TRACE [tid=xyz-150303164717095-2094855324-0-1] [Incoming-1,cosmos-db2-16474] org.infinispan.remoting.InboundInvocationHandlerImpl - About to send back response null for command SingleRpcCommand{cacheName='Order.eventTypesStatusMap', command=PutKeyValueCommand{key=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=1337, array=0x0301fe0409000000..}, cachedHashCode=-2052462461}@6d327a16, value=MarshalledValue{instance=<serialized>, serialized=ByteArray{size=126, array=0x0301fe0409000000..}, cachedHashCode=623872843}@ced725c, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ], putIfAbsent=true, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=1, version=null}, successful=true}}
2015-03-03 16:50:32 ERROR [tid=xyz-150303164717095-2094855324-0-1] [Incoming-2,cosmos-db2-16474] org.infinispan.remoting.InboundInvocationHandlerImpl - Exception executing command
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [0 milliseconds] on key [Order#4842ea8b-0d64-4703-b801-730c49aace35] for requestor [Thread[Incoming-2,cosmos-db2-16474,5,main]]! Lock held by [Thread[Incoming-1,cosmos-db2-16474,5,main]]
at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:214)
at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:197)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:149)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:145)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitPutKeyValueCommand(AbstractLockingInterceptor.java:69)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:83)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:54)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:83)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
at org.infinispan.interceptors.MarshalledValueInterceptor.visitPutKeyValueCommand(MarshalledValueInterceptor.java:154)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:83)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:54)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:83)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216)
at org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:194)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:136)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:83)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:160)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:83)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
Hibernate L2 cache configuration
<?xml version="1.0" encoding="UTF-8"?>
<infinispan xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="urn:infinispan:config:5.1"
xsi:schemaLocation="urn:infinispan:config:5.1 http://www.infinispan.org/schemas/infinispan-config-5.1.xsd">
<global>
<globalJmxStatistics enabled="true" cacheManagerName="H2L" jmxDomain="org.infinispan"
allowDuplicateDomains="true"/>
<transport
transportClass="org.infinispan.remoting.transport.jgroups.JGroupsTransport"
clusterName="infinispan-hibernate-cluster"
distributedSyncTimeout="50000"
strictPeerToPeer="false">
<properties>
<property name="configurationFile" value="jgroups.xml"/>
</properties>
</transport>
</global>
<default>
</default>
<!-- entity/collection caching that uses replication -->
<namedCache name="replicated-cache-entity">
<clustering mode="replication">
<stateTransfer fetchInMemoryState="false" timeout="20000"/>
<sync replTimeout="20000"/>
</clustering>
<!-- In distributed mode, Infinispan will store every entry on a subset of the nodes in the cache cluster
(controlled by the parameter numOwners, which controls how many owners each entry will have).
Theoretically reducing number of copies should increase the performance. Better to do a test with
mode distribution as well. -->
<!--<clustering mode="distribution">-->
<!--<sync replTimeout="20000"/>-->
<!--<hash numOwners="2" rehashEnabled="true"/>-->
<!--</clustering>-->
<locking isolationLevel="READ_COMMITTED" concurrencyLevel="1000"
lockAcquisitionTimeout="15000" useLockStriping="false"/>
<!-- Eviction configuration. WakeupInterval defines how often the eviction thread runs, in milliseconds.
0 means the eviction thread will never run. A separate executor is used for eviction in each cache. -->
<!-- maxEntries should be fine tune depend on the entities used to caching. Right now caching the events there fore
using a higher number -->
<eviction maxEntries="1000" strategy="LRU"/>
<expiration maxIdle="100000" wakeUpInterval="5000"/>
<storeAsBinary enabled="true"/>
<!--<transaction useSynchronization="true"
transactionMode="TRANSACTIONAL" autoCommit="false"
lockingMode="OPTIMISTIC"/>-->
</namedCache>
</infinispan>
Appreciate your help.