I'm running two Hotrod servers with one active client that reads/writes. The load is fairly low, maybe 20 writes/minute and 60 reads/minute. There happened to be two consecutive writes 1 second apart on the same key.  I'm pasting the log from Hotrod Client and Server as well as the cache configs. Can somebody please point me in the right direction?

There was another post about locking tiemouts here - can it be the same issure even under such low load?

Hotrod Client:

org.infinispan.client.hotrod.exceptions.HotRodClientException:Request for message id[3244] returned server error (status=0x86): org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [20 seconds] on key [ByteArrayKey{data=ByteArray{size=151, hashCode=766d4f30, array=[3, 4, 9, 0, 0, 0, 37, 99, 111, 109, ..]}}] for requestor [Thread[HotRodServerWorker-1-74,5,main]]! Lock held by [(another thread)]

        at org.infinispan.client.hotrod.impl.operations.HotRodOperation.checkForErrorsInResponseStatus(HotRodOperation.java:172)

        at org.infinispan.client.hotrod.impl.operations.HotRodOperation.readHeaderAndValidate(HotRodOperation.java:132)

        at org.infinispan.client.hotrod.impl.operations.AbstractKeyValueOperation.sendPutOperation(AbstractKeyValueOperation.java:70)

        at org.infinispan.client.hotrod.impl.operations.PutOperation.executeOperation(PutOperation.java:49)

        at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:62)

        at org.infinispan.client.hotrod.impl.RemoteCacheImpl.put(RemoteCacheImpl.java:203)

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

        ...........

Hotrod Server:

2012-03-01 01:13:30,500 DEBUG (HotRodServerWorker-1-74) [org.infinispan.util.concurrent.locks.LockManagerImpl] Failed to acquire lock ByteArrayKey{data=ByteArray{size=151, hashCode=766d4f30, array=[3, 4, 9, 0, 0, 0, 37, 99, 111, 109, ..]}}, owner is (another thread)

2012-03-01 01:13:30,500 DEBUG (HotRodServerWorker-1-74) [org.infinispan.util.concurrent.locks.LockManagerImpl] This transaction (Thread[HotRodServerWorker-1-74,5,main]) already owned locks []

2012-03-01 01:13:30,501 ERROR (HotRodServerWorker-1-74) [org.infinispan.interceptors.InvocationContextInterceptor] ISPN000136: Execution error

org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [20 seconds] on key [ByteArrayKey{data=ByteArray{size=151, hashCode=766d4f30, array=[3, 4, 9, 0, 0, 0, 37, 99, 111, 109, ..]}}] for requestor [Thread[HotRodServerWorker-1-74,5,main]]! Lock held by [(another thread)]

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

        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:294)

        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.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:114)

        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:518)

        at org.infinispan.server.core.AbstractProtocolDecoder.put(AbstractProtocolDecoder.scala:185)

        at org.infinispan.server.core.AbstractProtocolDecoder.decodeValue(AbstractProtocolDecoder.scala:141)

        at org.infinispan.server.core.AbstractProtocolDecoder.decode(AbstractProtocolDecoder.scala:71)

        at org.infinispan.server.core.AbstractProtocolDecoder.decode(AbstractProtocolDecoder.scala:45)

        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:471)

        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:444)

        at org.infinispan.server.core.AbstractProtocolDecoder.messageReceived(AbstractProtocolDecoder.scala:347)

        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:80)

        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:545)

        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:540)

        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274)

        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261)

        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:350)

        at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:281)

        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:201)

        at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)

        at org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46)

        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:662)

cache.xml

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

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

    <global>

        <transport clusterName="infinispan-cluster" >

            <properties>

                <property name="configurationFile" value="/config/ispn_server/jgroups-udp.xml"/>

            </properties>

        </transport>

    </global>

    <default>      

        <jmxStatistics enabled="true"/>

        <clustering mode="replication">

            <async />            

        </clustering>       

        <locking  isolationLevel="READ_COMMITTED"

                  useLockStriping="false"

                  concurrencyLevel="1000"

                  lockAcquisitionTimeout="10000" />

    </default>   

    <namedCache name="testCache">   

    </namedCache>

</infinispan>

jgroups.xml

<config xmlns="urn:org:jgroups"

        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

        xsi:schemaLocation="urn:org:jgroups file:schema/JGroups-2.8.xsd">

   <UDP

         bind_addr="${jgroups.tcp.address:server1.com}"

         bind_port="${jgroups.tcp.port:11767}"

         tos="8"

         ucast_recv_buf_size="20000000"

         ucast_send_buf_size="640000"

         mcast_recv_buf_size="25000000"

         mcast_send_buf_size="640000"

         loopback="false"

         discard_incompatible_packets="true"

         max_bundle_size="64000"

         max_bundle_timeout="30"

         ip_ttl="${jgroups.udp.ip_ttl:2}"

         enable_bundling="true"

         enable_diagnostics="false"

         thread_naming_pattern="pl"

         thread_pool.enabled="true"

         thread_pool.min_threads="2"

         thread_pool.max_threads="30"

         thread_pool.keep_alive_time="5000"

         thread_pool.queue_enabled="true"

         thread_pool.queue_max_size="100000"

         thread_pool.rejection_policy="Discard"

         oob_thread_pool.enabled="true"

         oob_thread_pool.min_threads="2"

         oob_thread_pool.max_threads="30"

         oob_thread_pool.keep_alive_time="5000"

         oob_thread_pool.queue_enabled="true"

         oob_thread_pool.queue_max_size="100"

         oob_thread_pool.rejection_policy="Discard"

         />

<TCPPING timeout="3000"

               initial_hosts="server1[11767],server2[11767]"

               port_range="5"

               num_initial_members="1"

               ergonomics="false"

        />

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

   <FD timeout="25000" max_tries="10"/>

   <pbcast.NAKACK use_stats_for_retransmission="false"

                  exponential_backoff="0"

                  use_mcast_xmit="true"

                  gc_lag="0"

                  retransmit_timeout="300,600,1200"

                  discard_delivered_msgs="true"/>

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

   <pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000" max_bytes="1000000"/>

   <pbcast.GMS disable_initial_coord="false" print_local_addr="false" join_timeout="3000" view_bundling="true"/>

   <UFC max_credits="1200000" min_threshold="0.20"/>

   <MFC max_credits="1200000" min_threshold="0.20"/>

   <FRAG2 frag_size="60000"  />

    <!--  <pbcast.FLUSH  /> -->

   <pbcast.STREAMING_STATE_TRANSFER max_pool="10" socket_buffer_size="160000"/>

</config>

Message was edited by: dmitry.s