Re: [jgroups-dev] Issue with TCPConnectionMap in jgroups 2.12.2.Final

Bela Ban <[email protected]> Thu, 28 Feb 2013 11:46:07 +0100
Newsgroups	gmane.comp.java.javagroups.devel
Message-ID	<[email protected]>
On 2/27/13 11:22 PM, Sundararajan, Mukund wrote:
>
> Hi Bela,
>
> I am running into an issue that is very similar to what was reported 
> here -à https://issues.jboss.org/browse/JGRP-1157
>

Actually, a more recent issue is https://issues.jboss.org/browse/JGRP-1600.


> Basically during application startup, jgroups forms a cluster with 9 
> other nodes. What I am seeing is sometimes all our threads get stuck 
> in 
> org/jgroups/blocks/TCPConnectionMap$TCPConnection$Sender.addToQueue(TCPConnectionMap.java:619). 
> When this condition happens I have no other way out but to restart the 
> application.
>

Yes. I guess this happens when the producers (senders) use a connection 
entry (including the send-queue) which differs from the one the consumer 
(receiver thread) uses. The effect is that the consumer is waiting for 
work, while the producers are blocked, waiting for someone to empty the 
send-queue.

I'll look into how this can happen in the 3.3 time frame, but a quick 
workaround should be to set use_send_queues to false in TCP.

> I have thread dumps and have analyzed it thoroughly. What I see is 
> there are 9 Sender threads waiting on LinkedBlockingQueue.take(). 
> However the threads that are sending messages out are getting blocked 
> on LinkedBlockingQueue.put() for a Connection for which the Sender 
> thread has most probably terminated and hence there is no code waiting 
> on take().
>


Terminated, or reading off of a different send-queue ? Search for 
"Connection.Sender". I remember a case where sender threads could 
terminate, but that was fixed. Don't remember the JIRA though.


> I say this because the Condition object that the 9 Sender threads are 
> waiting on is different from the Condition object that the writers are 
> blocked on!
>


You can't rely on this, as we're using a LinkedBlockingQueue, and there 
are 2 condition objects: notEmpty and notFull. The Connection.Sender 
threads are waiting on the notEmpty condition, while the producers would 
be waiting on the notFull condition object.

Further comments down (look for [bela]).

> *The nine Sender threads are the following - *
>
> "Connection.Sender [25.221.5.230:59891 - 
> 25.221.12.6:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14668 
> idx=0x6e8 tid=21005 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f88f638
>
> Connection.Sender [25.221.5.230:9800 - 
> 25.221.13.101:35061],Enterprise-,ukwgc7unybcm02-41676(2)" id=14660 
> idx=0x928 tid=20997 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f7dfd80
>
> "Connection.Sender [25.221.5.230:43781 - 
> 25.221.4.6:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14670 
> idx=0x978 tid=21007 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f4cd3b0
>
> "Connection.Sender [25.221.5.230:52571 - 
> 25.221.42.7:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14674 
> idx=0x9c8 tid=21011 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f741e40
>
> "Connection.Sender [25.221.5.230:48129 - 
> 25.221.42.6:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14672 
> idx=0xa48 tid=21009 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f474138
>
> "Connection.Sender [25.221.5.230:41259 - 
> 25.221.12.166:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14664 
> idx=0xa6c tid=21001 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f772cd8
>
> "Connection.Sender [25.221.5.230:9800 - 
> 25.221.2.5:35354],Enterprise-,ukwgc7unybcm02-41676(2)" id=14644 
> idx=0xa98 tid=19682 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x90bb3790
>
> "Connection.Sender [25.221.5.230:59870 - 
> 25.221.13.230:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14662 
> idx=0xb24 tid=20999 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f6bca10
>
> "Connection.Sender [25.221.5.230:36122 - 
> 25.221.4.198:9800],Enterprise-,ukwgc7unybcm02-41676(2)" id=14666 
> idx=0xb44 tid=21003 prio=5 alive, parked, native_blocked
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x9f5b0618
>
> *All my application threads are stuck in Sender.addToQueue() all 
> waiting on the same Condition object 
> *AbstractQueuedSynchronizer$ConditionObject@0x58590740. If you notice 
> there is no Sender thread above that has a blocking take() call on 
> this condition object.**
>
> [STUCK] ExecuteThread: '0' for queue: 'weblogic.kernel.Default 
> (self-tuning)'" id=20 idx=0x8c tid=26789 prio=1 alive, parked, 
> native_blocked, daemon
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x58590740
>
> [STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default 
> (self-tuning)'" id=23 idx=0x98 tid=26792 prio=1 alive, parked, 
> native_blocked, daemon
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x58590740
>
> "[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default 
> (self-tuning)'" id=30 idx=0xac tid=26802 prio=1 alive, parked, 
> native_blocked, daemon
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x58590740
>
> …..and so on. All my application threads (30 of them) are stuck in the 
> same place.
>


[bela] Yes, got it. But doesn't show whether a Connection.Sender has 
died, or whether it uses a different connection entry.

> *Here is the complete stack trace.*
>
> [STUCK] ExecuteThread: '0' for queue: 'weblogic.kernel.Default 
> (self-tuning)'" id=20 idx=0x8c tid=26789 prio=1 alive, parked, 
> native_blocked, daemon
>
> -- Parking to wait for: 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject@0x58590740
>
> at jrockit/vm/Locks.park0(J)V(Native Method)
>
> at jrockit/vm/Locks.park(Locks.java:2230)[inlined]
>
> at jrockit/proxy/sun/misc/Unsafe.park(Unsafe.java:616)[inlined]
>
> at 
> java/util/concurrent/locks/LockSupport.park(LockSupport.java:156)[inlined]
>
> at 
> java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)[optimized]
>
> at 
> java/util/concurrent/LinkedBlockingQueue.put(LinkedBlockingQueue.java:306)[optimized]
>
> at 
> org/jgroups/blocks/TCPConnectionMap$TCPConnection$Sender.addToQueue(TCPConnectionMap.java:619)[inlined]
>
> at 
> org/jgroups/blocks/TCPConnectionMap$TCPConnection.send(TCPConnectionMap.java:446)[inlined]
>
> at 
> org/jgroups/blocks/TCPConnectionMap$TCPConnection.access$100(TCPConnectionMap.java:354)[inlined]
>
> at 
> org/jgroups/blocks/TCPConnectionMap.send(TCPConnectionMap.java:167)[inlined]
>
> at org/jgroups/protocols/TCP.send(TCP.java:56)[optimized]
>
> at org/jgroups/protocols/BasicTCP.sendUnicast(BasicTCP.java:95)[optimized]
>
> at org/jgroups/protocols/TP.sendToSingleMember(TP.java:1214)[optimized]
>
> at org/jgroups/protocols/TP.doSend(TP.java:1198)[inlined]
>
> at org/jgroups/protocols/TP.send(TP.java:1184)[optimized]
>
> at org/jgroups/protocols/TP.down(TP.java:1041)[optimized]
>
> at org/jgroups/protocols/Discovery.down(Discovery.java:499)[inlined]
>
> at org/jgroups/protocols/TCPPING.down(TCPPING.java:149)[optimized]
>
> at org/jgroups/protocols/MERGE2.down(MERGE2.java:185)
>
> at org/jgroups/protocols/FD_SOCK.down(FD_SOCK.java:340)
>
> at org/jgroups/protocols/FD.down(FD.java:310)[optimized]
>
> at 
> org/jgroups/protocols/VERIFY_SUSPECT.down(VERIFY_SUSPECT.java:72)[optimized]
>
> at org/jgroups/protocols/BARRIER.down(BARRIER.java:93)[optimized]
>
> at org/jgroups/protocols/pbcast/NAKACK.down(NAKACK.java:634)[optimized]
>
> at org/jgroups/protocols/UNICAST.send(UNICAST.java:450)[inlined]
>
> at org/jgroups/protocols/UNICAST.down(UNICAST.java:401)[optimized]
>
> at org/jgroups/protocols/pbcast/STABLE.down(STABLE.java:330)
>
> at org/jgroups/protocols/pbcast/GMS.down(GMS.java:977)
>
> at org/jgroups/protocols/UFC.handleDownMessage(UFC.java:123)
>
> at org/jgroups/protocols/FlowControl.down(FlowControl.java:341)
>
> at 
> org/jgroups/protocols/FlowControl.sendCreditRequest(FlowControl.java:498)
>
> at org/jgroups/protocols/MFC.handleDownMessage(MFC.java:112)
>
> at org/jgroups/protocols/FlowControl.down(FlowControl.java:341)
>
> at org/jgroups/protocols/FRAG2.down(FRAG2.java:155)
>
> at 
> org/jgroups/protocols/pbcast/STATE_TRANSFER.down(STATE_TRANSFER.java:214)
>
> at org/jgroups/stack/ProtocolStack.down(ProtocolStack.java:1081)
>
> at org/jgroups/JChannel.down(JChannel.java:1654)
>
> at org/jgroups/JChannel.send(JChannel.java:734)
>
> at com/ipc/ds/interzone/channel/IZChannel.sendMessage(IZChannel.java:138)
>
> at com/ipc/ds/interzone/channel/IZChannel.sendMessage(IZChannel.java:120)
>
> at 
> com/ipc/ds/interzone/notification/LocalLineStatusNotificationListener.notify(LocalLineStatusNotificationListener.java:207)
>
> at 
> com/ipc/ds/notification/adaptors/JNDIAdaptor.tell(Ljava/lang/String;Ljava/util/List;Lcom/ipc/ds/notification/Publishable;)V(Unknown 
> Source)
>
> at com/ipc/ds/notification/core/NotificationEvent.fire()V(Unknown Source)
>
> at com/ipc/ds/notification/core/NotificationJob.run()V(Unknown Source)
>
> at 
> com/ipc/ds/notification/ejb/LineStatusNotificationMDB.onMessage(Ljavax/jms/Message;)V(Unknown 
> Source)
>
> at 
> sun/reflect/GeneratedMethodAccessor552.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;(Unknown 
> Source)
>
> at 
> sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)[optimized]
>
> at java/lang/reflect/Method.invoke(Method.java:597)[optimized]
>
> at 
> com/bea/core/repackaged/springframework/aop/support/AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310)[inlined]
>
> at 
> com/bea/core/repackaged/springframework/aop/framework/ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)[inlined]
>
> at 
> com/bea/core/repackaged/springframework/aop/framework/ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)[optimized]
>
> at 
> com/bea/core/repackaged/springframework/aop/support/DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
>
> at 
> com/bea/core/repackaged/springframework/aop/support/DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
>
> at 
> com/bea/core/repackaged/springframework/aop/framework/ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)[optimized]
>
> at 
> com/bea/core/repackaged/springframework/aop/interceptor/ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
>
> at 
> com/bea/core/repackaged/springframework/aop/framework/ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)[optimized]
>
> at 
> com/bea/core/repackaged/springframework/aop/support/DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
>
> at 
> com/bea/core/repackaged/springframework/aop/support/DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
>
> at 
> com/bea/core/repackaged/springframework/aop/framework/ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)[optimized]
>
> at 
> com/bea/core/repackaged/springframework/aop/framework/JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)[optimized]
>
> at $Proxy195.onMessage(Ljavax/jms/Message;)V(Unknown Source)
>
> at weblogic/ejb/container/internal/MDListener.execute(MDListener.java:466)
>
> at 
> weblogic/ejb/container/internal/MDListener.transactionalOnMessage(MDListener.java:371)
>
> at 
> weblogic/ejb/container/internal/MDListener.onMessage(MDListener.java:327)
>
> at weblogic/jms/client/JMSSession.onMessage(JMSSession.java:4659)
>
> at weblogic/jms/client/JMSSession.execute(JMSSession.java:4345)[optimized]
>
> at weblogic/jms/client/JMSSession.executeMessage(JMSSession.java:3821)
>
> at weblogic/jms/client/JMSSession.access$000(JMSSession.java:115)
>
> at weblogic/jms/client/JMSSession$UseForRunnable.run(JMSSession.java:5170)
>
> at 
> weblogic/work/SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528)[optimized]
>
> at weblogic/work/ExecuteThread.execute(ExecuteThread.java:201)[optimized]
>
> at weblogic/work/ExecuteThread.run(ExecuteThread.java:173)
>
> at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
>
> -- end of trace
>
> Is there a way out? This happens during application startup only under 
> unknown circumstances. I would say 1 out of 10 times it happens.
>

[bela]
Turn use_send_queues off. This removes the Connection.Sender threads and 
has the sending member send the message on its own thread.


> Our application starts sending out messages as soon as the JChannel 
> gets connected. From netstat what I see is out of the 9 TCP 
> connections, about 7 of them were initiated by this node to other 
> nodes and 2 of them were initiated by other nodes. My bind port is 
> 9800. For some connections I see the connection is from an ephemeral 
> port on the remote side versus 9800. See example below. My server IP 
> us 25.221.5.230. This connection was initiated by the remote side.
>

[bela]
I recently changed concurrent connection setup: 
https://issues.jboss.org/browse/JGRP-1549. This might help, but is in 
3.3.0.Beta1 (released today).


>
> I am trying to find a way out. Would setting use_send_queues to false 
> help? At this point I have to stay with 2.12.2.Final since this code 
> is running in the field but if an upgrade is inevitable I can look 
> into it.
>

[bela]
2.12.x is unsupported, check https://community.jboss.org/wiki/Support 
for details.

Once https://issues.jboss.org/browse/JGRP-1600 has been fixed, I suggest 
try it out. If you have comments, you can also add them to that case.

-- 
Bela Ban, JGroups lead (http://www.jgroups.org)


------------------------------------------------------------------------------
Everyone hates slow websites. So do we.
Make your web apps faster with AppDynamics
Download AppDynamics Lite for free today:
http://p.sf.net/sfu/appdyn_d2d_feb
_______________________________________________
Javagroups-development mailing list