12 Replies Latest reply on Apr 11, 2008 2:24 PM by bodrin

    Message delivery delay > 30 sec sometimes

    bodrin

      jboss-4.2.2.GA / jboss-messaging-1.4.0.SP3 / jboss-remoting-2.2.2.SP5

      I have a test which sends a message (persistent & transacted) to queue A and waits a response in queue B.
      The SystemInTest that answers in queue B is in a separate JVM and is a consumer of queue A.

      The strange thing is that the delivery of the message to SystemInTest sometimes is greater then 30s and
      it is delivered exactly at the time when I get the following warning at the JBoss console:

      17:44:06,547 WARN [SimpleConnectionManager] A problem has been detected with the connection to remote client 4sg1e4f-7tkxjl-feskzgma-1-feskzh69-d, jmsClientID=a-8tgzksef-1-amgzksef-ljxkt7-f4e1gs4. It is possible the client has exited without closing its connection(s) or the network has failed. All connection resources corresponding to that client process will now be removed.
      


      While I was waiting for the message to arraive at SystemInTest consumer I have checked the database,
      but nothing strange for me there :
      mysql>
      mysql> select * from JBM_MSG_REF;
      +------------+------------+----------------+-------+-------------------+----------+----------------+----------------+
      | MESSAGE_ID | CHANNEL_ID | TRANSACTION_ID | STATE | ORD | PAGE_ORD | DELIVERY_COUNT | SCHED_DELIVERY |
      +------------+------------+----------------+-------+-------------------+----------+----------------+----------------+
      | 3584 | 5 | NULL | C | 39572792630870034 | NULL | 0 | 0 |
      +------------+------------+----------------+-------+-------------------+----------+----------------+----------------+
      1 row in set (0.00 sec)
      
      mysql> select MESSAGE_ID,RELIABLE,EXPIRATION,TIMESTAMP,PRIORITY,TYPE from JBM_MSG;
      +------------+----------+------------+---------------+----------+------+
      | MESSAGE_ID | RELIABLE | EXPIRATION | TIMESTAMP | PRIORITY | TYPE |
      +------------+----------+------------+---------------+----------+------+
      | 3584 | Y | 0 | 1207665718203 | 4 | 2 |
      +------------+----------+------------+---------------+----------+------+
      1 row in set (0.00 sec)
      
      mysql>
      


      Do you have any idea what could be the reason for this delay?
      It appears almost every 2nd time I run the test.




        • 1. Re: Message delivery delay > 30 sec sometimes
          clebert.suconic

           

          I have a test which sends a message (persistent & transacted) to queue A and waits a response in queue B.
          The SystemInTest that answers in queue B is in a separate JVM and is a consumer of queue A.


          30 seconds is the default ping timeout. It looks like you have something receiving a message and then that JVM is killed, and as you probably didn't ack the message it will return to the queue and is received again.

          The message you receive ("A problem has been detected...") also confirms you probably have a lost connection somewhere.

          • 2. Re: Message delivery delay > 30 sec sometimes
            bodrin

            Ok, this sounds logical, but the problem is that there is nothing killed and no connection is lost. Except if someone else tries to consume messages from my queue, but always rejects them and then I receive them.
            Because I always receive the message I sent, but once it is immediate and other time is with a delay.

            Is there a way to track which client is with

            client 4sg1e4f-7tkxjl-feskzgma-1-feskzh69-d, jmsClientID=a-8tgzksef-1-amgzksef-ljxkt7-f4e1gs4
            


            .. to extract this info somehow from the connection object or some jboss specific way at the client side ?

            • 3. Re: Message delivery delay > 30 sec sometimes
              bodrin

              If I send 10 messages for example they are always received immediately.
              But when I send one message -> the delay/not delay behaviour described.

              Now I have checked the tcp connections. My consumer has established the following connections to the JBoss:

              java.exe:2712 TCP bobrin:38355 10.58.100.162:2412 ESTABLISHED
              java.exe:2712 TCP bobrin:38357 10.58.100.162:2412 ESTABLISHED
              java.exe:2712 TCP bobrin:38358 10.58.100.162:2412 ESTABLISHED
              
              java.exe:2712 TCP bobrin:38354 10.58.100.162:4557 ESTABLISHED
              java.exe:2712 TCP bobrin:38356 10.58.100.162:4557 ESTABLISHED
              

              ...and this one:
              java.exe:2712 TCP bobrin:38438 10.58.100.162:1201 ESTABLISHED
              

              It (:1201) appears just when the consumer succeeds to receive the message, and then disapears again:
              [System Process]:0 TCP bobrin:38438 10.58.100.162:1201 TIME_WAIT
              


              Note that I'm running in cluster with two nodes, one of them is started only.

              • 4. Re: Message delivery delay > 30 sec sometimes
                clebert.suconic

                 

                "bodrin" wrote:
                Ok, this sounds logical, but the problem is that there is nothing killed and no connection is lost. Except if someone else tries to consume messages from my queue, but always rejects them and then I receive them.
                Because I always receive the message I sent, but once it is immediate and other time is with a delay.

                Is there a way to track which client is with
                client 4sg1e4f-7tkxjl-feskzgma-1-feskzh69-d, jmsClientID=a-8tgzksef-1-amgzksef-ljxkt7-f4e1gs4
                


                .. to extract this info somehow from the connection object or some jboss specific way at the client side ?


                The first part is org.jboss.jms.client.container.JMSClientVMIdentifier.instance


                The second part, inside the JBossConnection, you will find a JBossRemote.Client. That ID will be one of the IDs inside Remote. (The invoker inside the remote object).

                • 5. Re: Message delivery delay > 30 sec sometimes
                  clebert.suconic

                  Do you have a testcase?

                  • 6. Re: Message delivery delay > 30 sec sometimes
                    clebert.suconic

                    Are you sure you don't have any firewall dropping connections or anything like that? I "believe" I have seen another situation like that.

                    • 7. Re: Message delivery delay > 30 sec sometimes
                      bodrin

                      There is no firewall.
                      I have tried to isolate this and I think I succeeded at least partialy.

                      The testcase can be downloaded at: http://85.187.184.114/~hongildon/test-case-delays.zip

                      I'm running the examples (test-case) queue-consumer and queue-producer on machine A while the JBM is running on machine B.
                      How to reproduce:
                      1) start queue-consumer
                      Details:
                      -Transacted event driven consumer.
                      -It shows the delay of the message.

                      2) start queue-producer multiple times to check the delay
                      Details:
                      Two sessions:
                      -First session (transacted) used to just create a consumer which is never used!
                      -Second session (transacted) used to send the message to the queue.


                      The strange thing is that if you comment the not used consumer creation in queue-producer (there is a line in the code
                      /** !!! if you comment the line below the delay is not present any more !!!*/
                      ) you get this durations:

                      [java] 11.04.2008 09:54:24 (duration: 63 ms ) onMessage: delegator->JBossMessage[96256]:PERSISTENT, deliveryId=20
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:54:30 (duration: 46 ms ) onMessage: delegator->JBossMessage[96768]:PERSISTENT, deliveryId=21
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:54:36 (duration: 47 ms ) onMessage: delegator->JBossMessage[97280]:PERSISTENT, deliveryId=22
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:54:42 (duration: 47 ms ) onMessage: delegator->JBossMessage[97792]:PERSISTENT, deliveryId=23
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:54:50 (duration: 63 ms ) onMessage: delegator->JBossMessage[98304]:PERSISTENT, deliveryId=24
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:54:58 (duration: 47 ms ) onMessage: delegator->JBossMessage[98816]:PERSISTENT, deliveryId=25
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:55:04 (duration: 63 ms ) onMessage: delegator->JBossMessage[99328]:PERSISTENT, deliveryId=26
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:55:10 (duration: 63 ms ) onMessage: delegator->JBossMessage[99840]:PERSISTENT, deliveryId=27
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:55:17 (duration: 63 ms ) onMessage: delegator->JBossMessage[100352]:PERSISTENT, deliveryId=28
                      [java] -----------------------------------------
                      [java] 11.04.2008 09:55:27 (duration: 63 ms ) onMessage: delegator->JBossMessage[100864]:PERSISTENT, deliveryId=29
                      
                      


                      And if you leave the same line uncommented you get:
                      [java] 11.04.2008 10:04:59 (duration: 47 ms ) onMessage: delegator->JBossMessage[101376]:PERSISTENT, deliveryId=30
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:05:12 (duration: 5093 ms ) onMessage: delegator->JBossMessage[101888]:PERSISTENT, deliveryId=31
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:05:17 (duration: 47 ms ) onMessage: delegator->JBossMessage[102400]:PERSISTENT, deliveryId=32
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:05:30 (duration: 5093 ms ) onMessage: delegator->JBossMessage[102912]:PERSISTENT, deliveryId=33
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:05:34 (duration: 62 ms ) onMessage: delegator->JBossMessage[103424]:PERSISTENT, deliveryId=34
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:05:49 (duration: 5078 ms ) onMessage: delegator->JBossMessage[103936]:PERSISTENT, deliveryId=35
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:05:55 (duration: 31 ms ) onMessage: delegator->JBossMessage[104448]:PERSISTENT, deliveryId=36
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:06:08 (duration: 5094 ms ) onMessage: delegator->JBossMessage[104960]:PERSISTENT, deliveryId=37
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:06:14 (duration: 62 ms ) onMessage: delegator->JBossMessage[105472]:PERSISTENT, deliveryId=38
                      [java] -----------------------------------------
                      [java] 11.04.2008 10:06:25 (duration: 5078 ms ) onMessage: delegator->JBossMessage[105984]:PERSISTENT, deliveryId=39
                      


                      Not that it is not as the original case where I got much bigger delays, but currently this is what I have managed to isolate ~ 5sec delay (and note the order - small delay, bigger delay, small delay,bigger delay,...).


                      • 8. Re: Message delivery delay > 30 sec sometimes
                        bodrin

                        I have managed to reproduce bigger delay:
                        If you add for example the following line just after the producer sends and commits the message:

                        Thread.sleep(30000);
                        

                        ... so, that the connection is not closed immediately after the send the delays get bigger 5s + 30s (?):
                        [java] -----------------------------------------
                        [java] 11.04.2008 13:25:14 (duration: 35094 ms ) onMessage:...
                        


                        • 9. Re: Message delivery delay > 30 sec sometimes
                          bodrin

                          So, if you have two MessageConsumer-s on the same queue in two different connections / sessions / VMs, but only one of them has a MessageListener attached (consumer.setMessageListener(...)) and you send a message using the other session (without a MessageListener attached) - there is some unexpected delay.

                          Additionaly if you close the connection after you send the message the delay is smaller.

                          • 10. Re: Message delivery delay > 30 sec sometimes
                            clebert.suconic

                            When you created this consumer:

                            /** !!! if you comment the line below the delay is not present any more !!!*/
                             MessageConsumer consumer = session.createConsumer(queue);
                            


                            It will actually receive messages, but you will never call consumer.receive();

                            As the message was received on the "dead" consumer, the message will eventually get back to the queue when you close the consumer, and that's probably the delay you are seeing.

                            We do this for performance reasons, where we cache the messages on the consumer. Now if you can actually have a situation like this on your system, you could set the option slowConsumers=true on the ConnectionFactory.

                            http://www.jboss.org/file-access/default/members/jbossmessaging/freezone/docs/userguide-1.4.1.Beta1/html/configuration.html#conf.connectionfactory.attributes.slowconsumers

                            • 11. Re: Message delivery delay > 30 sec sometimes
                              clebert.suconic

                              So... for your test, the best thing to do is to remove that consumer.

                              In a real situation, a slow consumer should use that option I told you before. You have the option to disable the performance improvement if your usecase requires that.

                              • 12. Re: Message delivery delay > 30 sec sometimes
                                bodrin

                                OK, I see. Thanks!