ISPN000136 java.lang.Interrupted Exception during cache.put()

[darrellburgan]

Hello, we're in the verge of deploying Infinispan 5.0.0 as a caching solution for our custom Java data tier and in our testing we have run into a strange exception happening very intermittently when we attempt to put an object into a cache. Here is the exception being thrown:

2011-09-22 15:43:25,482 [TP-Processor3] ERROR org.infinispan.interceptors.InvocationContextInterceptor :: ISPN000136: Execution error

java.lang.InterruptedException

        at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireNanos(AbstractQueuedSynchronizer.java:1223)

        at java.util.concurrent.locks.ReentrantLock.tryLock(ReentrantLock.java:416)

        at org.infinispan.util.concurrent.locks.containers.AbstractStripedLockContainer.acquireLock(AbstractStripedLockContainer.java:91)

        at org.infinispan.util.concurrent.locks.LockManagerImpl.lockAndRecord(LockManagerImpl.java:82)

        at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:232)

        at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:157)

        at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:109)

        at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:293)

        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:119)

        at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:133)

        at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:60)

        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:119)

        at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:214)

        at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:162)

        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:119)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:104)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:64)

        at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:60)

        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)

        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:274)

        at org.infinispan.CacheImpl.put(CacheImpl.java:515)

        at org.infinispan.CacheSupport.put(CacheSupport.java:51)

        at com.peopleAnswers.datagrid.impl.InfinispanVirtualSecondaryCache.put(InfinispanVirtualSecondaryCache.java:141)

       (other stuff in our code omitted)

Here is the Infinispan config:

<?xml version="1.0" encoding="UTF-8"?>

<infinispan xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:infinispan:config:5.0 http://www.infinispan.org/schemas/infinispan-config-5.0.xsd" xmlns="urn:infinispan:config:5.0">

     <global>

          <transport transportClass="org.infinispan.remoting.transport.jgroups.JGroupsTransport">

               <properties><property name="configurationFile" value="infinispan/jgroups-development-multinode.xml" /></properties>

          </transport>

     </global>

          <default>

                    <locking useLockStriping="true" isolationLevel="READ_COMMITTED" concurrencyLevel="64" writeSkewCheck="false" />

                    <eviction maxEntries="-1" strategy="LIRS" />

                    <expiration lifespan="-1" maxIdle="-1" />

                    <clustering><stateRetrieval fetchInMemoryState="false" /></clustering>

          </default>

          <namedCache name="syncInvalidationCache">

                    <locking isolationLevel="READ_COMMITTED" />

                    <clustering mode="invalidation"><sync /></clustering>

          </namedCache>

</infinispan>

And here is the JGroups config:

<config xmlns="urn:org:jgroups" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:org:jgroups http://www.jgroups.org/schema/JGroups-2.12.xsd">

          <TCP bind_port="58770" loopback="true" recv_buf_size="${tcp.recv_buf_size:20M}" send_buf_size="${tcp.send_buf_size:640K}"

                    discard_incompatible_packets="true" max_bundle_size="64K" max_bundle_timeout="30" enable_bundling="true" use_send_queues="true"

                    sock_conn_timeout="300" timer_type="new" timer.min_threads="4" timer.max_threads="10" timer.keep_alive_time="3000"

        timer.queue_max_size="500" thread_pool.enabled="true" thread_pool.min_threads="1" thread_pool.max_threads="10"

                    thread_pool.keep_alive_time="5000" thread_pool.queue_enabled="false" thread_pool.queue_max_size="100"

                    thread_pool.rejection_policy="discard" oob_thread_pool.enabled="true" oob_thread_pool.min_threads="1" oob_thread_pool.max_threads="8"

                    oob_thread_pool.keep_alive_time="5000" oob_thread_pool.queue_enabled="false" oob_thread_pool.queue_max_size="100"

                    oob_thread_pool.rejection_policy="discard" />

          <!-- gossip routers run on localhost on different ports -->

    <TCPGOSSIP timeout="3000" initial_hosts="${jgroups.tunnel.gossip_router_hosts:localhost[58771],localhost[58772]}" num_initial_members="3" />

    <MERGE2 max_interval="30000" min_interval="10000" />

    <FD timeout="2000" max_tries="4" />

    <VERIFY_SUSPECT timeout="1500" />

    <pbcast.NAKACK use_mcast_xmit="false" gc_lag="100" retransmit_timeout="600,1200,2400,4800" />

    <UNICAST timeout="300,600,1200" />

    <pbcast.STABLE stability_delay="1000" desired_avg_gossip="20000" max_bytes="4m" />

    <pbcast.GMS print_local_addr="true" join_timeout="5000" />

    <UFC max_credits="2M" min_threshold="0.4"/>

    <MFC max_credits="2M" min_threshold="0.4"/>

    <FRAG2 frag_size="60000" />

</config>

My temporary solution is to retry the put() operation when this occurs, which covers it up to an extent, but I am concerned that when this starts facing a heavy load that this is going to become an overwhelming issue. Can anyone shed any light as to what this exception really means? What is the correct way to deal with it? Any advice would be very helpful.

Thanks!

Darrell Burgan

[galder.zamarreno]

It would appear a lock acquisition was interrupted. Can you try disabling lock striping? Lock striping can sometimes leads to deadlocks.

[darrellburgan]

Yeah I turned off lock striping and the problem seemed to resolve.

Just a suggestion: the name "lock striping" confused me at first. I thought that "lock striping" meant it would be more concurrent not less concurrent, since I've seen people refer to the java.util.concurrent.ConcurrentMap as using "striping" to help reduce lock contention. Obviously, instead it means the opposite, that there will be fewer possible locks available and thus more chance for lock contention. Maybe a different name might help, or maybe the default for this should be off not on? I dunno, just some suggestions.

So far our Infinispan deployment has hit some speed bumps as we learn its behavior in our production environment, but it has been pretty solid overall. I'm pretty confident now that we are going to be able to make this work well, albeit with a few more tweaks to how we use it.

Thanks for your help!

[galder.zamarreno]

Lock striping is disabled by default since Infinispan 5.0: https://issues.jboss.org/browse/ISPN-970

Lock striping advantages and disadvantages are explained in http://community.jboss.org/polls/1073?pollSuccess=true