- QueueDepth dropping to 0, Message Cach 2007-07-15 - By syedtaj
Back
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@(protected) 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@(protected) 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@(protected) client=10.0.10.76:1057)
#44:) ARG : org.jboss.mq.TransactionRequest@(protected)
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue]
(UIL2(SocketManager.MsgPool@(protected) client=10.0.10.76:1057)#44:) acknowledge
AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845251473901932
40564 org.jboss.mq.server.PersistentQueue@(protected){id=QUEUE.dispatchToNodeQ
| ueue}
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue]
(UIL2(SocketManager.MsgPool@(protected) client=10.0.10.76:1057)#44:) acknowledge
AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845252759362864
40564 org.jboss.mq.server.PersistentQueue@(protected){id=QUEUE.dispatchToNodeQ
| ueue}
| 2007-07-15 20:34:10,967 34037114 TRACE [org.jboss.mq.server.BasicQueue]
(UIL2(SocketManager.MsgPool@(protected) client=10.0.10.76:1057)#44:) acknowledge
AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305688096079
40564 org.jboss.mq.server.PersistentQueue@(protected){id=QUEUE.dispatchToNodeQ
| ueue}
| 2007-07-15 20:34:10,968 34037115 TRACE [org.jboss.mq.server.BasicQueue]
(UIL2(SocketManager.MsgPool@(protected) client=10.0.10.76:1057)#44:) acknowledge
AcknowledgementRequest:NACK,QUEUE.dispatchToNodeQueue,ID:80-11845305690466087
40564 org.jboss.mq.server.PersistentQueue@(protected){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@(protected) 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@(protected) 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@(protected) 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@(protected) 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@(protected){id=QUEUE.dispatchToNodeQueue}
| 2007-07-15 20:34:10,982 34037129 TRACE [org.jboss.mq.server.BasicQueue]
(UIL2(SocketManager.MsgPool@(protected) 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@(protected){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@(protected){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
__ ____ ____ ____ ____ ____ ____ ____ ____ ____
jboss-user mailing list
jboss-user@(protected)
https://lists.jboss.org/mailman/listinfo/jboss-user
|
|
