The deadlock is between the session's _messageDeliveryLock and the
Dispatcher's _lock. The dispatcher thread's main loop attempts to
acquire _lock first and then _messageDeliveryLock. The main thread
acquires _messageDeliveryLock first thing on close(...) and then
subsequently many levels down the stack attempts to acquire _lock in
order to call Dispatcher.rejectPending(...).
The change causes this to occur more frequently because it moves the
shutdown of the dispatcher thread to a later point, thereby increasing
the probability a deadlock will occur, but I think the possibility was
always there.
I believe the reason the 0-8 code path is not affected is because it
calls AMQSession.confirmConsumerCanceled(...) in the
BasicCancelOkMethodHandler which is executed in another thread, so the
main thread doesn't try to acquire the Dispatcher's _lock.
--Rafael
Rajith Attapattu wrote:
Hi All,
Following is the thread dump which identifies the deadlock.
Note this happens within the 0-10 code path.
This seems to have been introduced in revision 632331 after the fix for
QPID-823 in AMQSession.
If I rollback this deadlock doesn't happen.
[junit] Running org.apache.qpid.client.MessageListenerMultiConsumerTest
Full thread dump Java HotSpot(TM) Client VM (1.5.0_09-b03 mixed mode,
sharing):
"Dispatcher-Channel-2" daemon prio=1 tid=0x0aec0ba0 nid=0x362f waiting for
monitor entry [0xb047f000..0xb047f130]
at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java
:2449)
- waiting to lock <0x88bab5a8> (a java.lang.Object)
- locked <0x88be5810> (a java.lang.Object)
"SocketConnectorIoProcessor-4.0" prio=1 tid=0x0ae4a2a0 nid=0x362c runnable
[0xb037c000..0xb037ceb0]
at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x88d905c0> (a sun.nio.ch.Util$1)
- locked <0x88d9f0d8> (a java.util.Collections$UnmodifiableSet)
- locked <0x88d9d568> (a sun.nio.ch.PollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run
(SocketIoProcessor.java:558)
at org.apache.mina.util.NamePreservingRunnable.run(
NamePreservingRunnable.java:43)
at java.lang.Thread.run(Thread.java:595)
"Thread-47" prio=1 tid=0x08d68e58 nid=0x361a runnable
[0xb0580000..0xb0580fb0]
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:194)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0x88d92810> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(FilterInputStream.java:90)
at org.apache.qpid.testutil.QpidTestCase$Piper.run(QpidTestCase.java
:103)
"process reaper" daemon prio=1 tid=0x08e54828 nid=0x3618 runnable
[0xb0601000..0xb0602030]
at java.lang.UNIXProcess.waitForProcessExit(Native Method)
at java.lang.UNIXProcess.access$900(UNIXProcess.java:20)
at java.lang.UNIXProcess$1$1.run(UNIXProcess.java:132)
"VmPipeIdleStatusChecker" daemon prio=1 tid=0x08db1438 nid=0x35e1 waiting on
condition [0xb0703000..0xb0703f30]
at java.lang.Thread.sleep(Native Method)
at
org.apache.mina.transport.vmpipe.support.VmPipeIdleStatusChecker$Worker.run(
VmPipeIdleStatusChecker.java:74)
"PooledByteBufferExpirer-0" daemon prio=1 tid=0x0887c408 nid=0x35dd waiting
on condition [0xb0f06000..0xb0f070b0]
at java.lang.Thread.sleep(Native Method)
at org.apache.mina.common.PooledByteBufferAllocator$Expirer.run(
PooledByteBufferAllocator.java:277)
"AnonymousIoService-2" daemon prio=1 tid=0x08872a08 nid=0x35dc in
Object.wait() [0xb0a3d000..0xb0a3e130]
at java.lang.Object.wait(Native Method)
- waiting on <0x89696af8> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock
)
at java.lang.Object.wait(Object.java:474)
at
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(
LinkedBlockingQueue.java:316)
- locked <0x89696af8> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock
)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:493)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:689)
at java.lang.Thread.run(Thread.java:595)
"AnonymousIoService-1" daemon prio=1 tid=0x08841b10 nid=0x35db in
Object.wait() [0xb0abe000..0xb0abedb0]
at java.lang.Object.wait(Native Method)
- waiting on <0x89696af8> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock
)
at java.lang.Object.wait(Object.java:474)
at
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(
LinkedBlockingQueue.java:316)
- locked <0x89696af8> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock
)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:493)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:689)
at java.lang.Thread.run(Thread.java:595)
"SocketAcceptor-0" prio=1 tid=0x08d47028 nid=0x35d7 runnable
[0xb0d83000..0xb0d83fb0]
at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x89696c58> (a sun.nio.ch.Util$1)
- locked <0x89696c68> (a java.util.Collections$UnmodifiableSet)
- locked <0x89696c08> (a sun.nio.ch.PollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
at org.apache.mina.transport.socket.nio.SocketAcceptor$Worker.run(
SocketAcceptor.java:266)
at org.apache.mina.util.NamePreservingRunnable.run(
NamePreservingRunnable.java:43)
at java.lang.Thread.run(Thread.java:595)
"Thread-5" daemon prio=1 tid=0x08cff508 nid=0x357b waiting for monitor entry
[0xb0e04000..0xb0e04db0]
at java.io.BufferedInputStream.read(BufferedInputStream.java:304)
- waiting to lock <0x89078838> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(FilterInputStream.java:111)
at java.io.FilterInputStream.read(FilterInputStream.java:90)
at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java
:92)
at java.lang.Thread.run(Thread.java:595)
"Thread-2" daemon prio=1 tid=0x08cfb398 nid=0x356d runnable
[0xb0e85000..0xb0e86030]
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:194)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0x89078838> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(FilterInputStream.java:111)
at java.io.FilterInputStream.read(FilterInputStream.java:90)
at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java
:92)
at java.lang.Thread.run(Thread.java:595)
"Low Memory Detector" daemon prio=1 tid=0x0880d5c8 nid=0x3567 runnable
[0x00000000..0x00000000]
"CompilerThread0" daemon prio=1 tid=0x0880c020 nid=0x3566 waiting on
condition [0x00000000..0xb22ef918]
"Signal Dispatcher" daemon prio=1 tid=0x0880b0d8 nid=0x3565 runnable
[0x00000000..0x00000000]
"Finalizer" daemon prio=1 tid=0x08804228 nid=0x3564 in Object.wait()
[0xb25f1000..0xb25f2030]
at java.lang.Object.wait(Native Method)
- waiting on <0x89075e68> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x89075e68> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=1 tid=0x08803528 nid=0x3563 in Object.wait()
[0xb2672000..0xb26730b0]
at java.lang.Object.wait(Native Method)
- waiting on <0x89075ee8> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x89075ee8> (a java.lang.ref.Reference$Lock)
"main" prio=1 tid=0x087c4670 nid=0x3560 waiting for monitor entry
[0xbf913000..0xbf9145a8]
at org.apache.qpid.client.AMQSession$Dispatcher.rejectPending(
AMQSession.java:2347)
- waiting to lock <0x88be5810> (a java.lang.Object)
at org.apache.qpid.client.AMQSession.confirmConsumerCancelled(
AMQSession.java:603)
at org.apache.qpid.client.BasicMessageConsumer_0_10.sendCancel
(BasicMessageConsumer_0_10.java:209)
at org.apache.qpid.client.BasicMessageConsumer.close(
BasicMessageConsumer.java:520)
- locked <0x88d9dab8> (a java.lang.Object)
at org.apache.qpid.client.BasicMessageConsumer.close(
BasicMessageConsumer.java:487)
at org.apache.qpid.client.BasicMessageConsumer_0_10.close
(BasicMessageConsumer_0_10.java:487)
at org.apache.qpid.client.AMQSession.closeConsumers(AMQSession.java
:1791)
at org.apache.qpid.client.AMQSession.closeProducersAndConsumers(
AMQSession.java:1841)
at org.apache.qpid.client.AMQSession.close(AMQSession.java:473)
- locked <0x88d9dab8> (a java.lang.Object)
- locked <0x88bab5a8> (a java.lang.Object)
at org.apache.qpid.client.AMQConnection.closeAllSessions(
AMQConnection.java:754)
at org.apache.qpid.client.AMQConnection.close(AMQConnection.java
:673)
- locked <0x88d9dab8> (a java.lang.Object)
at org.apache.qpid.client.AMQConnection.close(AMQConnection.java
:659)
at org.apache.qpid.client.MessageListenerMultiConsumerTest.tearDown(
MessageListenerMultiConsumerTest.java:106)
at junit.framework.TestCase.runBare(TestCase.java:130)
at org.apache.qpid.testutil.QpidTestCase.runBare(QpidTestCase.java
:71)
at junit.framework.TestResult$1.protect(TestResult.java:106)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.framework.TestResult.run(TestResult.java:109)
at junit.framework.TestCase.run(TestCase.java:118)
at junit.framework.TestSuite.runTest(TestSuite.java:208)
at junit.framework.TestSuite.run(TestSuite.java:203)
at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(
JUnitTestRunner.java:421)
at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeInVM(
JUnitTask.java:1245)
at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(
JUnitTask.java:814)
at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeOrQueue(
JUnitTask.java:1657)
at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(
JUnitTask.java:764)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.Target.execute(Target.java:357)
at org.apache.tools.ant.Target.performTasks(Target.java:385)
at org.apache.tools.ant.Project.executeSortedTargets(Project.java
:1329)
at org.apache.tools.ant.helper.SingleCheckExecutor.executeTargets(
SingleCheckExecutor.java:38)
at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
at org.apache.tools.ant.taskdefs.Ant.execute(Ant.java:416)
at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:289)
at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:208)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java
:62)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.taskdefs.MacroInstance.execute(
MacroInstance.java:391)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.Target.execute(Target.java:357)
at org.apache.tools.ant.Target.performTasks(Target.java:385)
at org.apache.tools.ant.Project.executeSortedTargets(Project.java
:1329)
at org.apache.tools.ant.Project.executeTarget(Project.java:1298)
at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(
DefaultExecutor.java:41)
at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
at org.apache.tools.ant.Main.runBuild(Main.java:698)
at org.apache.tools.ant.Main.startAnt(Main.java:199)
at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)
"VM Thread" prio=1 tid=0x08800948 nid=0x3562 runnable
"VM Periodic Task Thread" prio=1 tid=0x0880eab0 nid=0x3568 waiting on
condition
Found one Java-level deadlock:
=============================
"Dispatcher-Channel-2":
waiting to lock monitor 0x088052bc (object 0x88bab5a8, a java.lang.Object
),
which is held by "main"
"main":
waiting to lock monitor 0x0880533c (object 0x88be5810, a java.lang.Object
),
which is held by "Dispatcher-Channel-2"
Java stack information for the threads listed above:
===================================================
"Dispatcher-Channel-2":
at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java
:2449)
- waiting to lock <0x88bab5a8> (a java.lang.Object)
- locked <0x88be5810> (a java.lang.Object)
"main":
at org.apache.qpid.client.AMQSession$Dispatcher.rejectPending(
AMQSession.java:2347)
- waiting to lock <0x88be5810> (a java.lang.Object)
at org.apache.qpid.client.AMQSession.confirmConsumerCancelled(
AMQSession.java:603)
at org.apache.qpid.client.BasicMessageConsumer_0_10.sendCancel
(BasicMessageConsumer_0_10.java:209)
at org.apache.qpid.client.BasicMessageConsumer.close(
BasicMessageConsumer.java:520)
- locked <0x88d9dab8> (a java.lang.Object)
at org.apache.qpid.client.BasicMessageConsumer.close(
BasicMessageConsumer.java:487)
at org.apache.qpid.client.BasicMessageConsumer_0_10.close
(BasicMessageConsumer_0_10.java:487)
at org.apache.qpid.client.AMQSession.closeConsumers(AMQSession.java
:1791)
at org.apache.qpid.client.AMQSession.closeProducersAndConsumers(
AMQSession.java:1841)
at org.apache.qpid.client.AMQSession.close(AMQSession.java:473)
- locked <0x88d9dab8> (a java.lang.Object)
- locked <0x88bab5a8> (a java.lang.Object)
at org.apache.qpid.client.AMQConnection.closeAllSessions(
AMQConnection.java:754)
at org.apache.qpid.client.AMQConnection.close(AMQConnection.java
:673)
- locked <0x88d9dab8> (a java.lang.Object)
at org.apache.qpid.client.AMQConnection.close(AMQConnection.java
:659)
at org.apache.qpid.client.MessageListenerMultiConsumerTest.tearDown(
MessageListenerMultiConsumerTest.java:106)
at junit.framework.TestCase.runBare(TestCase.java:130)
at org.apache.qpid.testutil.QpidTestCase.runBare(QpidTestCase.java
:71)
at junit.framework.TestResult$1.protect(TestResult.java:106)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.framework.TestResult.run(TestResult.java:109)
at junit.framework.TestCase.run(TestCase.java:118)
at junit.framework.TestSuite.runTest(TestSuite.java:208)
at junit.framework.TestSuite.run(TestSuite.java:203)
at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(
JUnitTestRunner.java:421)
at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeInVM(
JUnitTask.java:1245)
at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(
JUnitTask.java:814)
at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeOrQueue(
JUnitTask.java:1657)
at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(
JUnitTask.java:764)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.Target.execute(Target.java:357)
at org.apache.tools.ant.Target.performTasks(Target.java:385)
at org.apache.tools.ant.Project.executeSortedTargets(Project.java
:1329)
at org.apache.tools.ant.helper.SingleCheckExecutor.executeTargets(
SingleCheckExecutor.java:38)
at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
at org.apache.tools.ant.taskdefs.Ant.execute(Ant.java:416)
at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:289)
at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:208)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java
:62)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.taskdefs.MacroInstance.execute(
MacroInstance.java:391)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java
:288)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(
DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.tools.ant.dispatch.DispatchUtils.execute(
DispatchUtils.java:105)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.Target.execute(Target.java:357)
at org.apache.tools.ant.Target.performTasks(Target.java:385)
at org.apache.tools.ant.Project.executeSortedTargets(Project.java
:1329)
at org.apache.tools.ant.Project.executeTarget(Project.java:1298)
at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(
DefaultExecutor.java:41)
at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
at org.apache.tools.ant.Main.runBuild(Main.java:698)
at org.apache.tools.ant.Main.startAnt(Main.java:199)
at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)
Found 1 deadlock.
