You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by eugene <eu...@gmail.com> on 2012/08/01 12:47:20 UTC
Deadlock
Hello,
We are having a DeadLock issue and it seems that this is the same bug as
here:
https://issues.apache.org/jira/browse/QPID-3216
So here what the logs say:
[2012-08-01 23:24:00.355] INFO sample_service.SampleService
org.apache.qpid.client.BasicMessageConsumer Closing
consumer:7[2130838978]
[2012-08-01 23:24:00.355] ERROR Thread-71 System.err
Exception in thread "Thread-71" java.lang.RuntimeException:
java.lang.InterruptedException
[2012-08-01 23:24:00.355] ERROR Thread-71 System.err
at org.apache.qpid.client.AMQSession.syncDispatchQueue(AMQSession.java:2215)
[2012-08-01 23:24:00.355] ERROR Thread-71 System.err
at
org.apache.qpid.client.BasicMessageConsumer_0_10.getMessageFromQueue(BasicMessageConsumer_0_10.java:436)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at
org.apache.qpid.client.BasicMessageConsumer.receive(BasicMessageConsumer.java:407)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at com.moodys.msp.lb.ServiceRequestPoller.run(ServiceRequestPoller.java:43)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at java.lang.Thread.run(Thread.java:680)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
Caused by: java.lang.InterruptedException
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:979)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
at org.apache.qpid.client.AMQSession.syncDispatchQueue(AMQSession.java:2211)
[2012-08-01 23:24:00.356] ERROR Thread-71 System.err
... 4 more
Also here is the JConsole output for the deadlock:
Name: Dispatcher-Channel-0
State: BLOCKED on java.lang.Object@c58f769 owned by: main
Total blocked: 2 Total waited: 1
Stack trace:
org.apache.qpid.client.BasicMessageConsumer.close(BasicMessageConsumer.java:571)
org.apache.qpid.client.BasicMessageConsumer.close(BasicMessageConsumer.java:535)
com.eugene.package.CallResponseListener.tryCloseMessageConsumer(CallResponseListener.java:55)
com.eugene.package.CallResponseListener.onMessage(CallResponseListener.java:50)
org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:725)
org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:699)
org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:205)
org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:47)
org.apache.qpid.client.AMQSession$Dispatcher.notifyConsumer(AMQSession.java:3388)
org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:3332)
- locked java.lang.Object@22fe135d
- locked java.lang.Object@1a0283e
org.apache.qpid.client.AMQSession$Dispatcher.access$900(AMQSession.java:3113)
org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3106)
org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:55)
org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3260)
java.lang.Thread.run(Thread.java:680)
And on the other side:
Name: main
State: BLOCKED on java.lang.Object@22fe135d owned by: Dispatcher-Channel-0
Total blocked: 148 Total waited: 133
Stack trace:
org.apache.qpid.client.AMQSession.close(AMQSession.java:731)
- locked java.lang.Object@c58f769
org.apache.qpid.client.AMQSession.close(AMQSession.java:708)
org.apache.qpid.client.AMQSession.close(AMQSession.java:567)
come.eugene.package.MSPConnectionImpl.close(MSPConnectionImpl.java:54)
com.eugene.package.ToDelete.doRoundRobinTest(ToDelete.java:62)
com.eugene.package.ToDelete.main(ToDelete.java:25)
Any luck of that bug being closed?
Thank You,
Eugene.
--
View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518.html
Sent from the Apache Qpid developers mailing list archive at Nabble.com.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org
Re: Deadlock
Posted by Oleksandr Rudyy <or...@gmail.com>.
Hi Eugene,
I do apologize for making you waiting with the answer. I was quite
busy with my current tasks and did not have time to look through the
client in order to recollect the deadlock conditions.
Regarding the deadlock scenario you have described, I believe that you
are right. I cannot see in Qpid code the conditions which might lead
into such deadlock by closing of consumer inside of MessageListener
on 0.10 path. However, such deadlock can occur in a bit different
way and it is even reported in QPID-4086.
If your application is not using failover it seems it is safe. At
least, I cannot see the deadlock conditions in the current code not
related to failover.
In case of failover, potentially the dedlock can occur in the
following scenario when consumer is closed inside of MessageListener
(unless I missed something) :
1) Message is dispatched into MessageListener#onMessage(Message) but
MessageListener is trying to invoke the consumer close method. At this
moment in time, the dispatcher thread acquired the dispatcher lock
(AMQSession.Dispatcher._lock) and delivery lock
(AMQSession._deliveryLock) and is about to acquire the failover mutex
from BasicMessageConsumer#close()
2) At this time, the tcp connection is lost and failover is triggered
to restore the connectivity. On failover, the failover thread (which
is a receiver thread) acquires the failover mutex before the
dispatcher thread. Than it restores the connectivity and invokes
AMQConnection#.failoverPrep() to clean the data on connection (pls,
have a look into code in
AMQConnectionDelegate_0_10#closed(Connection))
3) AMQConnection#.failoverPrep() invokes 0.10 delegate which iterates
through the sessions and invokes failoverPrep() on each session, which
in turn calls syncDispatchQueue() method to clean the dispatcher
queue. syncDispatchQueue() sends the poisoned message into the
pre-fetched message queue and waits forever for message being consumed
in the dispatcher thread.
4) However, the dispatcher thread cannot process any message as it is
blocked in BasicMessageConsumer#close(). Thus, we have a dead lock.
Kind Regards,
Alex
On 2 August 2012 12:11, eugene <eu...@gmail.com> wrote:
> Well this is a bug in the libraries, I've been looking at the code and here
> is (probably obvious for you :) ) problem:
>
> 1. Thread 1 acquires the FailoverMutex
> 2. Thread 2 acquires the MessageDeliveryLock
> 3. Thread 1 tries to acquire the MessageDeliveryLock
> 4. Thread 2 tries to acquire the FailoverMutex
>
> Thus the deadlock.
>
> Alex, I do not think that it has anything to do with closing Consumers from
> Listeners, it's just a side effect.
>
> Thank You,
> Eugene.
>
>
>
> --
> View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518p7581564.html
> Sent from the Apache Qpid developers mailing list archive at Nabble.com.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
> For additional commands, e-mail: dev-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org
Re: Deadlock
Posted by eugene <eu...@gmail.com>.
Well this is a bug in the libraries, I've been looking at the code and here
is (probably obvious for you :) ) problem:
1. Thread 1 acquires the FailoverMutex
2. Thread 2 acquires the MessageDeliveryLock
3. Thread 1 tries to acquire the MessageDeliveryLock
4. Thread 2 tries to acquire the FailoverMutex
Thus the deadlock.
Alex, I do not think that it has anything to do with closing Consumers from
Listeners, it's just a side effect.
Thank You,
Eugene.
--
View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518p7581564.html
Sent from the Apache Qpid developers mailing list archive at Nabble.com.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org
Re: Deadlock
Posted by eugene <eu...@gmail.com>.
Hello Alex,
It is going to be rather difficult to get a sample code that might reproduce
the issue, since we have a pretty big codebase already..
However is that like a known issue that closing consumers from listeners is
going to provoke deadlocks?
This is rather an undocumented "feature" :)
Thank You,
Eugene.
--
View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518p7581550.html
Sent from the Apache Qpid developers mailing list archive at Nabble.com.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org
Re: Deadlock
Posted by Oleksandr Rudyy <or...@gmail.com>.
Hi Eugen,
I am sorry for the late response.
There is a good chance that the issue was fixed in QPID-3911 for 0.16
qpid client.
However, I am afraid that you might run into other deadlocks by
closing the consumer from MessageListener. I would avoid doing so.
Do you have any test reproducing the issue?
Kind Regards,
Alex
On 1 August 2012 13:10, eugene <eu...@gmail.com> wrote:
> Yup, its 0.10
>
>
>
> --
> View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518p7581526.html
> Sent from the Apache Qpid developers mailing list archive at Nabble.com.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
> For additional commands, e-mail: dev-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org
Re: Deadlock
Posted by eugene <eu...@gmail.com>.
Yup, its 0.10
--
View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518p7581526.html
Sent from the Apache Qpid developers mailing list archive at Nabble.com.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org
Re: Deadlock
Posted by Oleksandr Rudyy <or...@gmail.com>.
Hi Eugene,
What is the version of the client you are using?
Is it 0.10 client?
Kind Regards,
Alex
On 1 August 2012 11:47, eugene <eu...@gmail.com> wrote:
> Hello,
>
> We are having a DeadLock issue and it seems that this is the same bug as
> here:
>
> https://issues.apache.org/jira/browse/QPID-3216
>
> So here what the logs say:
>
> [2012-08-01 23:24:00.355] INFO sample_service.SampleService
> org.apache.qpid.client.BasicMessageConsumer Closing
> consumer:7[2130838978]
> [2012-08-01 23:24:00.355] ERROR Thread-71 System.err
> Exception in thread "Thread-71" java.lang.RuntimeException:
> java.lang.InterruptedException
> [2012-08-01 23:24:00.355] ERROR Thread-71 System.err
> at org.apache.qpid.client.AMQSession.syncDispatchQueue(AMQSession.java:2215)
> [2012-08-01 23:24:00.355] ERROR Thread-71 System.err
> at
> org.apache.qpid.client.BasicMessageConsumer_0_10.getMessageFromQueue(BasicMessageConsumer_0_10.java:436)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at
> org.apache.qpid.client.BasicMessageConsumer.receive(BasicMessageConsumer.java:407)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at com.moodys.msp.lb.ServiceRequestPoller.run(ServiceRequestPoller.java:43)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at java.lang.Thread.run(Thread.java:680)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> Caused by: java.lang.InterruptedException
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:979)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> at org.apache.qpid.client.AMQSession.syncDispatchQueue(AMQSession.java:2211)
> [2012-08-01 23:24:00.356] ERROR Thread-71 System.err
> ... 4 more
>
> Also here is the JConsole output for the deadlock:
>
> Name: Dispatcher-Channel-0
> State: BLOCKED on java.lang.Object@c58f769 owned by: main
> Total blocked: 2 Total waited: 1
>
> Stack trace:
>
> org.apache.qpid.client.BasicMessageConsumer.close(BasicMessageConsumer.java:571)
> org.apache.qpid.client.BasicMessageConsumer.close(BasicMessageConsumer.java:535)
> com.eugene.package.CallResponseListener.tryCloseMessageConsumer(CallResponseListener.java:55)
> com.eugene.package.CallResponseListener.onMessage(CallResponseListener.java:50)
> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:725)
> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:699)
> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:205)
> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:47)
> org.apache.qpid.client.AMQSession$Dispatcher.notifyConsumer(AMQSession.java:3388)
> org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:3332)
> - locked java.lang.Object@22fe135d
> - locked java.lang.Object@1a0283e
> org.apache.qpid.client.AMQSession$Dispatcher.access$900(AMQSession.java:3113)
> org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3106)
> org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:55)
> org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3260)
> java.lang.Thread.run(Thread.java:680)
>
>
> And on the other side:
>
>
> Name: main
> State: BLOCKED on java.lang.Object@22fe135d owned by: Dispatcher-Channel-0
> Total blocked: 148 Total waited: 133
>
> Stack trace:
> org.apache.qpid.client.AMQSession.close(AMQSession.java:731)
> - locked java.lang.Object@c58f769
> org.apache.qpid.client.AMQSession.close(AMQSession.java:708)
> org.apache.qpid.client.AMQSession.close(AMQSession.java:567)
> come.eugene.package.MSPConnectionImpl.close(MSPConnectionImpl.java:54)
> com.eugene.package.ToDelete.doRoundRobinTest(ToDelete.java:62)
> com.eugene.package.ToDelete.main(ToDelete.java:25)
>
> Any luck of that bug being closed?
>
> Thank You,
> Eugene.
>
>
>
>
> --
> View this message in context: http://apache-qpid-developers.2158895.n2.nabble.com/Deadlock-tp7581518.html
> Sent from the Apache Qpid developers mailing list archive at Nabble.com.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
> For additional commands, e-mail: dev-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org