[jboss-user] [Messaging, JMS & JBossMQ] - QueueDepth dropping to 0, Message Cache involved, NACK messa
syedtaj
do-not-reply at jboss.com
Sun Jul 15 21:18:46 EDT 2007
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.
anonymous wrote :
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] (UIL2(SocketManager.MsgPool at 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 at 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 at a425da client=10.0.10.76:1057)#44:) ARG : org.jboss.mq.TransactionRequest at ced1c1
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool at a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845251473901932 40564 org.jboss.mq.server.PersistentQueue at 12da4a6{id=QUEUE.dispatchToNodeQ
| ueue}
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool at a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845252759362864 40564 org.jboss.mq.server.PersistentQueue at 12da4a6{id=QUEUE.dispatchToNodeQ
| ueue}
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool at a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305688096079 40564 org.jboss.mq.server.PersistentQueue at 12da4a6{id=QUEUE.dispatchToNodeQ
| ueue}
| 2007-07-15 20:34:10,968 34037115 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool at a425da client=10.0.10.76:1057)#44:) acknowledge AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305690466087 40564 org.jboss.mq.server.PersistentQueue at 12da4a6{id=QUEUE.dispatchToNodeQ
| ueue}
| ....................
|
followed by
anonymous wrote :
| 2007-07-15 20:34:10,976 34037123 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool at 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 at 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 at 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 at 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 at 12da4a6{id=QUEUE.dispatchToNodeQueue}
| 2007-07-15 20:34:10,982 34037129 TRACE [org.jboss.mq.server.BasicQueue] (UIL2(SocketManager.MsgPool at 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 at 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.
anonymous wrote : 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:-
anonymous wrote :
| 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 at 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
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4064396#4064396
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4064396
More information about the jboss-user
mailing list