2 Replies Latest reply on Jul 17, 2007 12:47 PM by syedtaj

QueueDepth dropping to 0, Message Cache involved, NACK messa

syedtaj Jul 15, 2007 9:18 PM

Hi,

We are having a production issue at the moment while submitting messages into a queue. Using Jboss 4.0.4GA

When a message is submitted in the queue, it is consumed successfully. We have about 40 consumers. However when the messages grow in number, we start facing a lot of problem.

The queue depth of the queue drops to 0. Imaging that we have about 3000 messages in the queue. 40 consumers looking in the same queue, as soon as the consumers are up, the messages in the queue (watch from jmx-console) drop to 0, even though the messages are still present in the table. The consumers process the first batch of messages and since the queue is 0, they wait and only pick up any new message that come in.

The code of the consumer is pretty simple, picks up a message, that would delete it from the queue, process it and return it back.

On tracing the logs, i found the following messages. I hope someone can throw light on the messages.

2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) Begin handleMsg, msgType: 17
2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.TracingInterceptor] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) CALLED : transact
2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.TracingInterceptor] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) ARG : org.jboss.mq.TransactionRequest@ced1c1
2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845251473901932 40564 org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQ
ueue}
2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845252759362864 40564 org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQ
ueue}
2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305688096079 40564 org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQ
ueue}
2007-07-15 20:34:10,968 34037115 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305690466087 40564 org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQ
ueue}
....................

followed by

2007-07-15 20:34:10,976 34037123 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) Restoring message: 4911 msg=4523 hard STORED PERSISTENT queue=QUEUE.dispatchToNodeQueue priority=4 lateClone=false hashCode=16957640
2007-07-15 20:34:10,976 34037123 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) Updating message 4911 msg=4523 hard STORED PERSISTENT queue=QUEUE.dispatchToNodeQueue priority=4 lateClone=false hashCode=16957640 transaction=null
2007-07-15 20:34:10,980 34037127 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) Updated message 4911 msg=4523 hard STORED PERSISTENT queue=QUEUE.dispatchToNodeQueue priority=4 lateClone=false hashCode=16957640 transaction=null
2007-07-15 20:34:10,982 34037129 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) internalAddMessage 4911 msg=4523 hard STORED PERSISTENT queue=QUEUE.dispatchToNodeQueue priority=4 lateClone=false hashCode=16957640 org.jboss.mq.server.Persistent
Queue@12da4a6{id=QUEUE.dispatchToNodeQueue}
2007-07-15 20:34:10,982 34037129 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) queueMessageForSending Subscription[subId=-2147483648connection=ConnectionToken:ID:6970/48f674041eb704d4535a29e854646d8f destination=QUEUE.dispatchToNodeQueue mess
ageSelector=null Local Create] 4911 msg=4523 hard STORED PERSISTENT queue=QUEUE.dispatchToNodeQueue priority=4 lateClone=false hashCode=16957640 org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQueue}

and so on.

At this point, the queue depth rises but drops steadily again.

However this does not happen all the time, I believe it is triggrered by a message Begin handleMsg, msgType: 17 . I am unable to understand what is invoking the same.

Hope some one can throw light on the same.

I have caught something else as well, the message cache softens all the messages even if enough memory is available and these messages are lost and are not loaded again.

2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.22467656
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Need to soften 242 messages
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.22526875
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Need to soften 242 messages
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.22586171
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Need to soften 241 messages
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.22621797
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Need to soften 241 messages
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.2265625
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Need to soften 240 messages
2007-07-15 14:18:17,740 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.22694063
2007-07-15 14:18:17,741 TRACE [org.jboss.mq.server.MessageCache] Need to soften 240 messages

And after the above gets over - the queue depth is 0.

One more observation:-

2007-07-15 11:43:03,179 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 13
2007-07-15 11:43:03,179 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
2007-07-15 11:43:03,179 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
2007-07-15 11:43:03,179 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 60000
2007-07-15 11:43:03,179 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on ConnectionToken:ID:12/407a40114e31809c640bd2cb2f6f5021 subId=-2147483648
2007-07-15 11:43:03,179 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
Principal: guest
Principal: Roles(members:j2ee,guest,john)
;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [guest]
2007-07-15 11:43:03,180 TRACE [org.jboss.mq.server.BasicQueue] receive Subscription[subId=-2147483648connection=ConnectionToken:ID:12/407a40114e31809c640bd2cb2f6f5021 destination=QUEUE.dispatchToNodeQueue messageSelector=null Local Create] wait=true org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQueue}
2007-07-15 11:43:03,180 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
2007-07-15 11:43:03,180 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.ReceiveMsg33018671[msgType: m_receive, msgID: 30, error: null]
2007-07-15 11:43:03,180 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.ReceiveMsg33018671[msgType: m_receive, msgID: 30, error: null]
2007-07-15 11:43:03,180 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 13

I wonder what msgType:13 stands for. When the above happens the messages drop.

I am at lost what to do. The production system cannot be brought down or experimented upon. Also we are unable to reproduce the same at a lesser load.

If anyone could provide some suggestions or throw light upon the above events it would be a great help.

Thanks.

Taj

1. Re: QueueDepth dropping to 0, Message Cache involved, NACK m

adrian.brock Jul 16, 2007 8:14 AM (in response to syedtaj)

"syedtaj" wrote:

2007-07-15 20:34:10,968 34037115 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305690466087 40564 org.jboss.mq.server.PersistentQueue@12da4a6{id=QUEUE.dispatchToNodeQ
ueue}

A NACK is a negative acknowledgement. i.e. the client did not accept the message.
You can see it putting the message back in the queue for somebody else to process.

2007-07-15 20:34:10,976 34037123 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool@a425da client=10.0.10.76:1057)#44:) Restoring message: 4911 msg=4523 hard STORED PERSISTENT queue=QUEUE.dispatchToNodeQueue priority=4 lateClone=false hashCode=16957640

At this point, the queue depth rises but drops steadily again.

That's the expected behaviour if you think about.
One client NACKs the message then another one receives it.

Why the client is not acknowledging the messages it is receiving
is something for you to determine.
The rest of your post is irrelevant to that question.

*GUESS 1": It's always rolling back because some process cannot complete.

*GUESS 2": You forgot to commit the session, so only when the session
is closed are the messages from the incomplete transaction NACKed.
Actions
2. Re: QueueDepth dropping to 0, Message Cache involved, NACK m

syedtaj Jul 17, 2007 12:47 PM (in response to syedtaj)

Thanks Adrian,

Appreciate the reply.

We checked the Consumers who were nacking the messages back and found that they had an old set of code base on them and were giving some exceptions relating to invalid version. On fixing them the problem disappeared. Thanks again, your reply gave an additional information on how nacking actually works.

Regards,
Taj
Actions

Go to original post