1 Reply Latest reply on Mar 4, 2015 7:20 AM by Radim Vansa

    Random TimeoutException in Infinispan Hibernate L2 cache when put a load

    Eranga Samararathna Newbie

      I 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.