You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Eric (JIRA)" <ji...@apache.org> on 2010/07/13 10:34:53 UTC
[jira] Commented: (AMQ-2693) potential hang with failover,
transactions and slow thread creation with outstanding commit - close
blocks pending dispatch FailoverConsumerOutstandingCommitTest intermittent
failure
[ https://issues.apache.org/activemq/browse/AMQ-2693?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=60616#action_60616 ]
Eric commented on AMQ-2693:
---------------------------
Problem seems to be localized here
When it works Ok :
09:11:02,704 [ActiveMQ Task ] DEBUG AbstractRegion - localhost removing consumer: ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:2:1 for destination: queue://FailoverWithOutstandingCommit
2010-07-13 09:11:02,705 [127.0.0.1:61616] WARN FailoverTransport - Transport failed to tcp://localhost:61616 , attempting to automatically reconnect due to: java.io.EOFException
2010-07-13 09:11:02,705 [ActiveMQ Task ] DEBUG Queue - remove sub: QueueSubscription: consumer=ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:2:1, destinations=1, dispatched=1, delivered=0, pending=0, lastDeliveredSeqId: 0, dequeues: 0, dispatched: 1, inflight: 1
2010-07-13 09:11:02,705 [127.0.0.1:61616] DEBUG FailoverTransport - Transport failed with the following exception:
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:375)
at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:269)
at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:211)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
at java.lang.Thread.run(Thread.java:619)
2010-07-13 09:11:02,705 [127.0.0.1:61616] DEBUG ActiveMQConnection - transport interrupted, dispatchers: 1
2010-07-13 09:11:02,706 [iveMQ Scheduler] DEBUG ActiveMQMessageConsumer - ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:2:1 clearing dispatched list (0) on transport interrupt
2010-07-13 09:11:02,706 [ActiveMQ Task ] DEBUG FailoverTransport - urlList connectionList:[tcp://localhost:61616]
2010-07-13 09:11:02,706 [ActiveMQ Task ] DEBUG Queue - FailoverWithOutstandingCommit toPageIn: 0, Inflight: 0, pagedInMessages.size 1, enqueueSize: 1
2010-07-13 09:11:02,706 [ActiveMQ Task ] DEBUG FailoverTransport - Attempting connect to: tcp://localhost:61616
2010-07-13 09:11:02,707 [ActiveMQ Task ] DEBUG AbstractRegion - localhost removing consumer: ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:-1:1 for destination: topic://ActiveMQ.Advisory.TempQueue,topic://ActiveMQ.Advisory.TempTopic
.....
When it blocks
2010-07-13 09:00:35,721 [ActiveMQ Task ] DEBUG AbstractRegion - localhost removing consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:-1:1 for destination: topic://ActiveMQ.Advisory.TempQueue,topic://ActiveMQ.Advisory.TempTopic
...
2010-07-13 09:00:35,722 [ActiveMQ Task ] DEBUG AbstractRegion - localhost removing consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 for destination: queue://FailoverWithOutstandingCommit
2010-07-13 09:00:35,722 [ActiveMQ Task ] DEBUG Queue - remove sub: QueueSubscription: consumer=ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1, destinations=1, dispatched=11, delivered=1, pending=0, lastDeliveredSeqId: 0, dequeues: 0, dispatched: 11, inflight: 11
2010-07-13 09:00:35,723 [127.0.0.1:61616] WARN FailoverTransport - Transport failed to tcp://localhost:61616 , attempting to automatically reconnect due to: java.io.EOFException
2010-07-13 09:00:35,724 [127.0.0.1:61616] DEBUG FailoverTransport - Transport failed with the following exception:
2010-07-13 09:00:35,724 [127.0.0.1:61616] DEBUG FailoverTransport - Transport failed with the following exception:
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:375)
at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:269)
at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:211)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
at java.lang.Thread.run(Thread.java:619)
2010-07-13 09:00:35,724 [BrokerService ] DEBUG Queue - FailoverWithOutstandingCommit toPageIn: 0, Inflight: 0, pagedInMessages.size 20, enqueueSize: 20
2010-07-13 09:00:35,725 [127.0.0.1:61616] DEBUG ActiveMQConnection - transport interrupted, dispatchers: 1
...
2010-07-13 09:01:05,907 [127.0.0.1:61616] WARN ActiveMQConnection - dispatch paused, waiting for outstanding dispatch interruption processing (1) to complete..
....
It's the way messageConsumers (and corresponding sessions) are cleared that impacts the "transportInterruptionProcessingComplete" countdown latch value
Eric-AWL
> potential hang with failover, transactions and slow thread creation with outstanding commit - close blocks pending dispatch FailoverConsumerOutstandingCommitTest intermittent failure
> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2693
> URL: https://issues.apache.org/activemq/browse/AMQ-2693
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.3.0, 5.3.1
> Environment: loaded machine where thread creation is slow
> Reporter: Gary Tully
> Assignee: Gary Tully
> Fix For: 5.4.0
>
>
> potential dead lock pending dispatch that is blocked by an outstanding commit after failover.
> Log indicates:{code}
> WARN ActiveMQConnection - dispatch paused, waiting for outstanding dispatch interruption processing (x) to complete..
> {code}
> Thread Dump:{code}
> Full thread dump Java HotSpot(TM) Server VM (14.0-b16 mixed mode):
> ...
> "ActiveMQ Transport: tcp:///127.0.0.1:49284" daemon prio=3 tid=0x0068f800 nid=0x32 runnable [0x56ffe000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
> at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
> at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
> at java.io.DataOutputStream.flush(DataOutputStream.java:106)
> at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:168)
> at org.apache.activemq.transport.InactivityMonitor.oneway(InactivityMonitor.java:243)
> - locked <0x5c2daab0> (a java.util.concurrent.atomic.AtomicBoolean)
> at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:83)
> at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
> at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:40)
> - locked <0x5c2da520> (a java.lang.Object)
> at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1205)
> at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:790)
> at org.apache.activemq.broker.TransportConnection.dispatchSync(TransportConnection.java:750)
> at org.apache.activemq.broker.region.PrefetchSubscription.dispatch(PrefetchSubscription.java:647)
> at org.apache.activemq.broker.region.PrefetchSubscription.dispatchPending(PrefetchSubscription.java:592)
> - locked <0x5c2db3a0> (a java.lang.Object)
> - locked <0x5c2db3a8> (a java.lang.Object)
> at org.apache.activemq.broker.region.PrefetchSubscription.add(PrefetchSubscription.java:158)
> at org.apache.activemq.broker.region.Queue.doActualDispatch(Queue.java:1548)
> at org.apache.activemq.broker.region.Queue.doDispatch(Queue.java:1500)
> - locked <0x5c2db500> (a java.util.ArrayList)
> - locked <0x5c2db518> (a java.lang.Object)
> at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1585)
> at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1219)
> - locked <0x5c2db520> (a org.apache.activemq.broker.region.Queue$3)
> at org.apache.activemq.broker.region.Queue.wakeup(Queue.java:1406)
> at org.apache.activemq.broker.region.Queue.addSubscription(Queue.java:377)
> at org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:279)
> - locked <0x5c2db590> (a java.lang.Object)
> at org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:380)
> at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86)
> at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86)
> at org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:89)
> at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86)
> at org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:93)
> at org.apache.activemq.broker.TransportConnection.processAddConsumer(TransportConnection.java:533)
> at org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:349)
> at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:300)
> at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:178)
> at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
> at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
> at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:216)
> - locked <0x5c2dab30> (a org.apache.activemq.transport.InactivityMonitor$1)
> at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
> at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:204)
> at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
> at java.lang.Thread.run(Thread.java:619)
> "ActiveMQ Transport: tcp://localhost/127.0.0.1:61616" prio=3 tid=0x007c9000 nid=0x2e waiting on condition [0x569fe000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x5c2b1950> (a java.util.concurrent.CountDownLatch$Sync)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:947)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1239)
> at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:253)
> at org.apache.activemq.ActiveMQConnection.waitForTransportInterruptionProcessing(ActiveMQConnection.java:2248)
> at org.apache.activemq.ActiveMQConnection$2.processMessageDispatch(ActiveMQConnection.java:1679)
> at org.apache.activemq.command.MessageDispatch.visit(MessageDispatch.java:108)
> at org.apache.activemq.ActiveMQConnection.onCommand(ActiveMQConnection.java:1676)
> at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
> at org.apache.activemq.transport.failover.FailoverTransport$3.onCommand(FailoverTransport.java:168)
> at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
> at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:216)
> - locked <0x5c2db138> (a org.apache.activemq.transport.InactivityMonitor$1)
> at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
> at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:204)
> at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
> at java.lang.Thread.run(Thread.java:619)
> "ActiveMQ Session Task" prio=3 tid=0x0076f000 nid=0x25 waiting on condition [0x55ffe000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x5c2e3cd0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
> at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:317)
> at org.apache.activemq.transport.FutureResponse.getResult(FutureResponse.java:40)
> at org.apache.activemq.transport.ResponseCorrelator.request(ResponseCorrelator.java:87)
> at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1262)
> at org.apache.activemq.TransactionContext.syncSendPacketWithInterruptionHandling(TransactionContext.java:666)
> at org.apache.activemq.TransactionContext.commit(TransactionContext.java:299)
> at org.apache.activemq.ActiveMQSession.commit(ActiveMQSession.java:558)
> at org.apache.activemq.transport.failover.FailoverConsumerOutstandingCommitTest$2.onMessage(FailoverConsumerOutstandingCommitTest.java:155)
> at org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1204)
> - locked <0x5c2c6088> (a java.lang.Object)
> at org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)
> at org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)
> at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
> at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
> 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:619)
> "ActiveMQ Scheduler" daemon prio=3 tid=0x006e4c00 nid=0xf waiting for monitor entry [0x573ff000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at org.apache.activemq.ActiveMQMessageConsumer.clearMessagesInProgress(ActiveMQMessageConsumer.java:661)
> - waiting to lock <0x5c2c6088> (a java.lang.Object)
> at org.apache.activemq.ActiveMQSession$2.run(ActiveMQSession.java:654)
> at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.java:33)
> at java.util.TimerThread.mainLoop(Timer.java:512)
> at java.util.TimerThread.run(Timer.java:462)
> "main" prio=3 tid=0x00030800 nid=0x2 waiting for monitor entry [0x7eb7d000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at org.apache.activemq.MessageDispatchChannel.stop(MessageDispatchChannel.java:115)
> - waiting to lock <0x5c2c6088> (a java.lang.Object)
> at org.apache.activemq.ActiveMQMessageConsumer.stop(ActiveMQMessageConsumer.java:1312)
> at org.apache.activemq.ActiveMQSession.stop(ActiveMQSession.java:1643)
> at org.apache.activemq.ActiveMQConnection.stop(ActiveMQConnection.java:544)
> - locked <0x5c2ae5d8> (a java.util.concurrent.CopyOnWriteArrayList)
> at org.apache.activemq.ActiveMQConnection.close(ActiveMQConnection.java:597)
> at org.apache.activemq.transport.failover.FailoverConsumerOutstandingCommitTest.doTestFailoverConsumerDups(FailoverConsumerOutstandingCommitTest.java:185)
> at org.apache.activemq.transport.failover.FailoverConsumerOutstandingCommitTest.testFailoverConsumerDups(FailoverConsumerOutstandingCommitTest.java:104)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
> at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:73)
> at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:46)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41)
> at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173)
> at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:220)
> at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
> at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
> at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:165)
> at org.apache.maven.surefire.Surefire.run(Surefire.java:107)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:289)
> at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1005)
> {code}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.