ActiveMQ message dequeuing hangs

[skate056]

Hello all,

We have about 145517 messages on the queue but after dequeueing about 1510 messages the dequeueing  stops. ActiveMQ is using about 28% of memory and the web ui responds. But the messages are not getting dequeued.

After restarting ActiveMQ it resumes dequeueing but then again processes about ~1500 messages and then hangs again.

We are running 5.9.0. Any suggestions what the issue could be?

Thanks,
Saket

[ceposta]

Take thread dumps while you attach consumers to see what's going on.
Any way to recreate it?


On Fri, May 23, 2014 at 9:07 AM, skate056 <[hidden email]> wrote:

> Hello all,
>
> We have about 145517 messages on the queue but after dequeueing about 1510
> messages the dequeueing  stops. ActiveMQ is using about 28% of memory and
> the web ui responds. But the messages are not getting dequeued.
>
> After restarting ActiveMQ it resumes dequeueing but then again processes
> about ~1500 messages and then hangs again.
>
> We are running 5.9.0. Any suggestions what the issue could be?
>
> Thanks,
> Saket
>
>
>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/ActiveMQ-message-dequeuing-hangs-tp4681366.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>

--
*Christian Posta*
http://www.christianposta.com/blog
twitter: @christianposta

[skate056]

I looked at the thread dump but it does not point to something obvious. Attached are the thread dumps.

I am trying to simulate this on a pure vanilla ActiveMQ instance with some random data.

On Tue, May 27, 2014 at 5:08 PM, ceposta [via ActiveMQ] <[hidden email]> wrote:

Take thread dumps while you attach consumers to see what's going on.
Any way to recreate it?


On Fri, May 23, 2014 at 9:07 AM, skate056 <[hidden email]> wrote:

> Hello all,
>
> We have about 145517 messages on the queue but after dequeueing about 1510
> messages the dequeueing  stops. ActiveMQ is using about 28% of memory and
> the web ui responds. But the messages are not getting dequeued.
>
> After restarting ActiveMQ it resumes dequeueing but then again processes
> about ~1500 messages and then hangs again.
>
> We are running 5.9.0. Any suggestions what the issue could be?
>
> Thanks,
> Saket
>
>

>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/ActiveMQ-message-dequeuing-hangs-tp4681366.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>

--
*Christian Posta*
http://www.christianposta.com/blog
twitter: @christianposta

http://www.christianposta.com/blog

---

If you reply to this email, your message will be added to the discussion below:

http://activemq.2283324.n4.nabble.com/ActiveMQ-message-dequeuing-hangs-tp4681366p4681454.html

To unsubscribe from ActiveMQ message dequeuing hangs, click here.
NAML

[skate056]

Hello,

We were able to reproduce this issue with just ActiveMQ (minus our application). It seems that when the consumers throw a exceptions frequently, something goes wrong trying to rollback the transaction and the LevelDB. It seems that a LevelDB thread is locking it up.

Attached is a test which simulates the behavior. For us it failed after 50000 messages but the number may vary on the machine.

We suspect the following thread to be the culprit as it continuously seems to be blocked.

Thread 43139: (state = BLOCKED)

 - sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)

 - java.util.concurrent.locks.LockSupport.park(java.lang.Object) @bci=20, line=186 (Compiled frame [deoptimized])

 - java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt() @bci=7, line=834 (Compiled frame [deoptimized])

 - java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(int) @bci=89, line=994 (Compiled frame [deoptimized])

 - java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(int) @bci=47, line=1303 (Interpreted frame)

 - java.util.concurrent.CountDownLatch.await() @bci=11, line=236 (Interpreted frame)

 - org.apache.activemq.leveldb.LevelDBStore.rollback(org.apache.activemq.command.TransactionId) @bci=152, line=498 (Interpreted frame)

 - org.apache.activemq.transaction.LocalTransaction.rollback() @bci=111, line=94 (Interpreted frame)

 - org.apache.activemq.broker.TransactionBroker.rollbackTransaction(org.apache.activemq.broker.ConnectionContext, org.apache.activemq.command.TransactionId) @bci=15, line=258 (Interpreted frame)

 - org.apache.activemq.broker.BrokerFilter.rollbackTransaction(org.apache.activemq.broker.ConnectionContext, org.apache.activemq.command.TransactionId) @bci=12, line=142 (Interpreted frame)

 - org.apache.activemq.broker.MutableBrokerFilter.rollbackTransaction(org.apache.activemq.broker.ConnectionContext, org.apache.activemq.command.TransactionId) @bci=12, line=147 (Interpreted frame)

 - org.apache.activemq.broker.TransportConnection.processRollbackTransaction(org.apache.activemq.command.TransactionInfo) @bci=44, line=442 (Interpreted frame)

 - org.apache.activemq.command.TransactionInfo.visit(org.apache.activemq.state.CommandVisitor) @bci=146, line=104 (Compiled frame [deoptimized])

 - org.apache.activemq.broker.TransportConnection.service(org.apache.activemq.command.Command) @bci=52, line=292 (Compiled frame [deoptimized])

 - org.apache.activemq.broker.TransportConnection$1.onCommand(java.lang.Object) @bci=95, line=149 (Compiled frame [deoptimized])

 - org.apache.activemq.transport.MutexTransport.onCommand(java.lang.Object) @bci=58, line=50 (Compiled frame [deoptimized])

 - org.apache.activemq.transport.WireFormatNegotiator.onCommand(java.lang.Object) @bci=35, line=113 (Compiled frame [deoptimized])

 - org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(java.lang.Object) @bci=162, line=270 (Compiled frame [deoptimized])

 - org.apache.activemq.transport.TransportSupport.doConsume(java.lang.Object) @bci=27, line=83 (Compiled frame [deoptimized])

 - org.apache.activemq.transport.tcp.TcpTransport.doRun() @bci=13, line=214 (Compiled frame [deoptimized])

 - org.apache.activemq.transport.tcp.TcpTransport.run() @bci=70, line=196 (Compiled frame [deoptimized])

 - java.lang.Thread.run() @bci=17, line=724 (Interpreted frame)

Thanks.

Saket

On Thu, May 29, 2014 at 5:03 PM, Saket Jha <[hidden email]> wrote:

I looked at the thread dump but it does not point to something obvious. Attached are the thread dumps.

I am trying to simulate this on a pure vanilla ActiveMQ instance with some random data.

On Tue, May 27, 2014 at 5:08 PM, ceposta [via ActiveMQ] <[hidden email]> wrote:

Take thread dumps while you attach consumers to see what's going on.
Any way to recreate it?


On Fri, May 23, 2014 at 9:07 AM, skate056 <[hidden email]> wrote:

> Hello all,
>
> We have about 145517 messages on the queue but after dequeueing about 1510
> messages the dequeueing  stops. ActiveMQ is using about 28% of memory and
> the web ui responds. But the messages are not getting dequeued.
>
> After restarting ActiveMQ it resumes dequeueing but then again processes
> about ~1500 messages and then hangs again.
>
> We are running 5.9.0. Any suggestions what the issue could be?
>
> Thanks,
> Saket
>
>

>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/ActiveMQ-message-dequeuing-hangs-tp4681366.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>

--
*Christian Posta*
http://www.christianposta.com/blog
twitter: @christianposta

http://www.christianposta.com/blog

---

If you reply to this email, your message will be added to the discussion below:

http://activemq.2283324.n4.nabble.com/ActiveMQ-message-dequeuing-hangs-tp4681366p4681454.html

To unsubscribe from ActiveMQ message dequeuing hangs, click here.
NAML

[badavis]

I ran into the same issue.  The good thing is I figured out what was causing the issue.  I believe the issue is two issues.  There is a deadlock in the processing of async jobs that is blocking a job that can unblock the deadlock.

The two threads that are important are:

Thread 43139: (state = BLOCKED)
 - sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
 - java.util.concurrent.locks.LockSupport.park(java.lang.Object) @bci=20, line=186 (Compiled frame [deoptimized])
 - java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt() @bci=7, line=834 (Compiled frame [deoptimized])
 - java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(int) @bci=89, line=994 (Compiled frame [deoptimized])
 - java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(int) @bci=47, line=1303 (Interpreted frame)
 - java.util.concurrent.CountDownLatch.await() @bci=11, line=236 (Interpreted frame)
 - org.apache.activemq.leveldb.LevelDBStore.rollback(org.apache.activemq.command.TransactionId) @bci=152, line=498 (Interpreted frame)
 -> org.apache.activemq.transaction.LocalTransaction.rollback() @bci=111, line=94 (Interpreted frame)
 - org.apache.activemq.broker.TransactionBroker.rollbackTransaction(org.apache.activemq.broker.ConnectionContext, org.apache.activemq.command.TransactionId) @bci=15, line=258 (Interpreted frame)
 - org.apache.activemq.broker.BrokerFilter.rollbackTransaction(org.apache.activemq.broker.ConnectionContext, org.apache.activemq.command.TransactionId) @bci=12, line=142 (Interpreted frame)
 - org.apache.activemq.broker.MutableBrokerFilter.rollbackTransaction(org.apache.activemq.broker.ConnectionContext, org.apache.activemq.command.TransactionId) @bci=12, line=147 (Interpreted frame)
 - org.apache.activemq.broker.TransportConnection.processRollbackTransaction(org.apache.activemq.command.TransactionInfo) @bci=44, line=442 (Interpreted frame)
 - org.apache.activemq.command.TransactionInfo.visit(org.apache.activemq.state.CommandVisitor) @bci=146, line=104 (Compiled frame [deoptimized])
 - org.apache.activemq.broker.TransportConnection.service(org.apache.activemq.command.Command) @bci=52, line=292 (Compiled frame [deoptimized])
 - org.apache.activemq.broker.TransportConnection$1.onCommand(java.lang.Object) @bci=95, line=149 (Compiled frame [deoptimized])
 - org.apache.activemq.transport.MutexTransport.onCommand(java.lang.Object) @bci=58, line=50 (Compiled frame [deoptimized])
 - org.apache.activemq.transport.WireFormatNegotiator.onCommand(java.lang.Object) @bci=35, line=113 (Compiled frame [deoptimized])
 - org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(java.lang.Object) @bci=162, line=270 (Compiled frame [deoptimized])
 - org.apache.activemq.transport.TransportSupport.doConsume(java.lang.Object) @bci=27, line=83 (Compiled frame [deoptimized])
 - org.apache.activemq.transport.tcp.TcpTransport.doRun() @bci=13, line=214 (Compiled frame [deoptimized])
 - org.apache.activemq.transport.tcp.TcpTransport.run() @bci=70, line=196 (Compiled frame [deoptimized])
 - java.lang.Thread.run() @bci=17, line=724 (Interpreted frame)



Thread 38184: (state = BLOCKED)
 -> org.apache.activemq.leveldb.LevelDBStore.getTopicGCPositions() @bci=15, line=768 (Interpreted frame)
 - org.apache.activemq.leveldb.DBManager$$anonfun$pollGc$1.apply$mcV$sp() @bci=28, line=640 (Interpreted frame)
 - org.fusesource.hawtdispatch.package$$anon$4.run() @bci=10, line=357 (Compiled frame [deoptimized])
 - org.fusesource.hawtdispatch.internal.SerialDispatchQueue.run() @bci=317, line=100 (Compiled frame [deoptimized])
 - org.fusesource.hawtdispatch.internal.pool.SimpleThread.run() @bci=105, line=77 (Compiled frame [deoptimized])


I bolded and -> the lines that are important with the deadlock.  The rollback thread holds the lock of the message store and the getTopicGCPositions needs to get the lock of the message store (the identified lines in the stack trace).  That may not seem that important but the more important thing is where the getTopicGCPositions is running.  It is running in the hawtdispatcher.  If you could look at the SerialDispatchQueue you would see that it tries to run all the jobs in one run.  Well this is a problem if one of the front jobs is blocked until a job behind it runs.  That is where we are.  The job that the rollback is waiting on is scheduled to run behind the pollGc job.

My belief is their are two issues:

* the LevelDBStore class does not fully own its lock
* the hawtdispatcher does not distribute the jobs over the dispatcher's threads, but chooses to run many jobs in one thread when other threads are available.
 
Hope this helps.

You have a good one.

Brian

P.S. The only mitigation is a code change.  You cannot change the polling interval to lower the likely hood of it happening because it is hard coded to every 10 seconds.

[jameshome]

Based on your post Brian, I modified LevelDBStore to use a private lock instead of this, and it does indeed solve the issue.

I've attached a 5.9.2 patch to:

https://issues.apache.org/jira/browse/AMQ-5125

Thanks for your help,

James

[mattmadhavan]

Hello,
I am facing almost identical problem. I am using the latest AMQ 5.11.1 with KhaDB.

Any suggestions please?

Thanks
Matt

[mattmadhavan]

HI James,
I am trying to get my ActiveMQ configuration closer to yours. Can you please elaborate what you mean by:

 "I modified LevelDBStore to use a private lock instead of this" and how do I do it? I been stuck on this issue for couple of weeks now.

Thanks
Matt'M

[skate056]

Have you tried this on 5.10? I believe James had committed a fix for that.

Thanks
Saket

On Mon, 6 Apr 2015 at 22:23, mattmadhavan [via ActiveMQ] <[hidden email]> wrote:

HI James,
I am trying to get my ActiveMQ configuration closer to yours. Can you please elaborate what you mean by:

 "I modified LevelDBStore to use a private lock instead of this" and how do I do it? I been stuck on this issue for couple of weeks now.

Thanks
Matt'M

---

If you reply to this email, your message will be added to the discussion below:

http://activemq.2283324.n4.nabble.com/ActiveMQ-message-dequeuing-hangs-tp4681366p4694366.html

To unsubscribe from ActiveMQ message dequeuing hangs, click here.
NAML

[mattmadhavan]

HI Skate,
Thanks for the reply. I actually started with 5.10 when I ran into this problem. I switched to the latest ActiveMQ 5.11.1 still the same issue.

It actually hung once more just I while I am writing this reply. Very frustrating.

Any ideas please?

I appreciate your help in advance!

Thanks
Matt'M

[jameshome]

Hi Matt,

The previous issue (AMQ-5125) was specifically an issue when using LevelDB, so if you're using KahaDB it won't be exactly the same issue, despite the similarity of the symptoms.

Out of interest, have you tried using LevelDB? Do you get the same issue?

James

[mattmadhavan]

Hi James,
Yes I did yesterday and facing the same issue as I did with KahaDB. Problem is no errors, warnings nothing!

Not sure whats happening!

Any insight into this will be appreciated.

Thanks
Matt'M