6 Replies Latest reply on Dec 24, 2010 12:46 AM by getthiyagu

org.infinispan.util.concurrent.TimeoutException

cbo_ Jun 15, 2010 4:25 PM

I believe the exception below may be related to removing the queue between my app thread and the transport. I recently removed the asyncMarshalling (ie set it explicitly to false) on my replicated cache. The exception below seems to be created a deadlock.

2010-06-15 06:07:04,126 3167845 TRACE [org.jgroups.protocols.TCP] (Incoming-48,infinispan-cluster-EquityTradeServer1-test16,test16a_GCBC-53813:)received [dst: <null>, src: test16a_GCBC-53813 (3 headers), size=750 bytes], headers are RequestCorrelator: id=201, type=REQ, id=482, rsp_expecte

d=true, NAKACK: [MSG, seqno=611], TCP: [channel_name=infinispan-cluster-EquityTradeServer1-test16]

2010-06-15 06:07:04,125 3167844 TRACE [org.jgroups.protocols.FC] (Incoming-13,infinispan-cluster-EquityTradeServer1-test16,test16a_GCBC-53813:) s

ender test16a_GCBC-53813 minus 750 credits, 1887500 remaining

2010-06-15 06:07:04,184 3167903 TRACE [org.jgroups.protocols.TCP] (Incoming-48,infinispan-cluster-EquityTradeServer1-test16,test16a_GCBC-53813:)

received [dst: <null>, src: test16a_GCBC-53813 (3 headers), size=750 bytes], headers are RequestCorrelator: id=201, type=REQ, id=480, rsp_expecte

d=true, NAKACK: [MSG, seqno=609], TCP: [channel_name=infinispan-cluster-EquityTradeServer1-test16]

2010-06-15 06:07:04,184 3167903 TRACE [org.jgroups.protocols.TCP] (OOB-49,infinispan-cluster-EquityTradeServer1-test16,test16a_GCBC-53813:) recei

ved [dst: test16a_GCBC-53813, src: test16b_GCBC-48822 (2 headers), size=0 bytes, flags=OOB], headers are FD: heartbeat ack, TCP: [channel_name=in

finispan-cluster-EquityTradeServer1-test16]

2010-06-15 06:07:04,185 3167904 TRACE [org.jgroups.protocols.TCP] (Incoming-48,infinispan-cluster-EquityTradeServer1-test16,test16a_GCBC-53813:)

received [dst: <null>, src: test16a_GCBC-53813 (3 headers), size=750 bytes], headers are RequestCorrelator: id=201, type=REQ, id=481, rsp_expecte

d=true, NAKACK: [MSG, seqno=610], TCP: [channel_name=infinispan-cluster-EquityTradeServer1-test16]

2010-06-15 06:07:04,183 3167902 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (CommandProcessorThread.SGEN:) Execution error:

org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [20 seconds] on key [377553362] for requestor [Thread[CommandProces

sorThread.SGEN,5,main]]! Lock held by [Thread[CommandProcessorThread.SNHY,5,main]]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

at org.infinispan.CacheDelegate.put(CacheDelegate.java:414)

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

at com.cboe.infrastructureServices.cacheService.JCacheServiceInfinispanImpl.put(JCacheServiceInfinispanImpl.java:84)

at com.cboe.server.distributedCache.DistributedCacheImpl.put(DistributedCacheImpl.java:122)

at com.cboe.server.distributedCache.DistributedCacheImpl.put(DistributedCacheImpl.java:17)

at com.cboe.internalBusinessServices.productStateService.TradingProductSyncImpl.updateProductData(TradingProductSyncImpl.java:140)

at com.cboe.internalBusinessServices.productStateService.TradingProductSyncImpl.updateToSync(TradingProductSyncImpl.java:240)

at com.cboe.internalBusinessServices.productStateService.TradingProductImpl.changesCommitted(TradingProductImpl.java:3603)

at com.objectwave.transactionalSupport.TransactionLog.commit(TransactionLog.java:319)

at com.objectwave.transactionalSupport.Session.commit(Session.java:51)

at com.cboe.infrastructureServices.foundationFramework.transactionManagement.BOSession.commit(BOSession.java:99)

at com.cboe.infrastructureServices.foundationFramework.utilities.TransactionBaseImpl.commit(TransactionBaseImpl.java:122)

at com.cboe.infrastructureServices.foundationFramework.utilities.Transaction.commit(Transaction.java:22)

at com.cboe.internalBusinessServices.productStateService.ProductStateChangeByClassCommand.execute(ProductStateChangeByClassCommand.java:8

at com.cboe.server.commandProcessing.CommandProcessorImpl.processCommands(CommandProcessorImpl.java:272)

at com.cboe.server.commandProcessing.CommandProcessorComboQueueImpl.handleCommands(CommandProcessorComboQueueImpl.java:77)

at com.cboe.server.commandProcessing.CommandProcessorComboQueueImpl.run(CommandProcessorComboQueueImpl.java:275)

at java.lang.Thread.run(Thread.java:619)

Jgroups contents:

<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">

<TCP bind_port="7850"

loopback="true"

port_range="30"

recv_buf_size="20000000"

send_buf_size="640000"

discard_incompatible_packets="true"

max_bundle_size="64000"

max_bundle_timeout="30"

enable_bundling="true"

use_send_queues="true"

sock_conn_timeout="300"

enable_diagnostics="false"

thread_pool.enabled="true"

thread_pool.min_threads="2"

thread_pool.max_threads="30"

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="2"

oob_thread_pool.max_threads="30"

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"

<MPING receive_on_all_interfaces="true" break_on_coord_rsp="true"

mcast_addr="${jgroups.udp.mcast_addr:228.6.7.8}" mcast_port="${jgroups.udp.mcast_port:42610}" ip_ttl="${jgroups.udp.ip_ttl:16}"

num_initial_members="2" num_ping_requests="1"/>

<MERGE2 max_interval="30000"

min_interval="10000"/>

<FD_SOCK/>

<VERIFY_SUSPECT timeout="1500"/>

<pbcast.NAKACK

use_mcast_xmit="false" gc_lag="0"

retransmit_timeout="300,600,1200,2400,4800"

discard_delivered_msgs="false"/>

<pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000"

max_bytes="400000"/>

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

<FC max_credits="2000000"

min_threshold="0.10"/>

<pbcast.STREAMING_STATE_TRANSFER/>

<pbcast.FLUSH timeout="0"/>

</config>

1. Re: org.infinispan.util.concurrent.TimeoutException

manik Jun 16, 2010 6:28 AM (in response to cbo_)

If marshalling happens synchronously, then each call will take that much longer and hold on to locks that much longer as well. So your pool of locks may need to be further tuned. Could you paste your <locking ... > element in your Infinispan cfg file (if any) here?
Actions
2. Re: org.infinispan.util.concurrent.TimeoutException

cbo_ Jun 16, 2010 8:02 AM (in response to manik)

My named cache section(s) do not specify locking, but the default section does. Here is what it specifies:

<locking
            isolationLevel="REPEATABLE_READ"
            lockAcquisitionTimeout="20000"
            writeSkewCheck="false"
            concurrencyLevel="500"
            useLockStriping="true"
            />

I am reviewing these now......
Actions
3. Re: org.infinispan.util.concurrent.TimeoutException

cbo_ Jun 17, 2010 9:42 PM (in response to cbo_)

I have changed the locking to the following:

<locking
useLockStriping="false"
/>

Prior to this change we were subject to the TimeoutExcpetion. Now that the above change is made we are no longer getting the TimeoutExceptions, but throughput and response times are not good. Most transactions are taking >30ms. Most of the time has been tracked to:

org.jgroups.blocks.Request. There is a method called responsesComplete that is taking the majority of the time. It seems to be waiting on a time based on a value set by timeout. What is this and how can I remedy it?
Actions
4. Re: org.infinispan.util.concurrent.TimeoutException

manik Jun 30, 2010 6:17 PM (in response to cbo_)

This is basically the code that waits for a response. Is this running in sync or async clustering mode? And have you tried using a replication queue if you are using async mode?
Actions
5. Re: org.infinispan.util.concurrent.TimeoutException

mircea.markus Jul 1, 2010 7:55 AM (in response to manik)

This is related to: https://jira.jboss.org/browse/ISPN-502.
Actions
6. Re: org.infinispan.util.concurrent.TimeoutException

getthiyagu Dec 24, 2010 12:46 AM (in response to cbo_)

hi craig,

We are facing the same issue in our prject as well. Did you overcome that issue? If so can you please provide the step.

Thanks in advance
Actions

Go to original post