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

    QueueDepth dropping to 0, Message Cache involved, NACK messa

    Taj Newbie

      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 Master

           

          "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.

          • 2. Re: QueueDepth dropping to 0, Message Cache involved, NACK m
            Taj Newbie

            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