8 Replies Latest reply on Mar 30, 2016 12:19 AM by Tomohisa igarashi

    WF10/Artemis - significant delay on receiving

    Tomohisa igarashi Master

      Hi,


      I've been using org.hornetq.client module to connect with WildFly/JMS server, and it was working fine on WildFly 10.0.0.CR4. I hit a significant delay on receiving once I updated to WildFly 10.0.0.Final like consumer.receive(1000) takes 15-20 seconds. If I write the client with ActiveMQ Artemis native API then that delay doesn't occur.


      My question is, is the org.hornetq.client module not supposed to be used to connect with ActiveMQ Artemis embedded in WildFly 10?


      Thanks,

      Tomo



      * * *  Updated: 2016/03/23

      It turned out client API doesn't matter, the delay also occur with Artemis client API. So both of the testcase I attached could hit delay problem. However it's not 100%, it happens intermittently. Restarting WildFly10 instance often changes the outcome.

      And I couldn't reproduce it with standalone ActiveMQ Artemis server (1.1.0 nor 1.2.0). It seems to be happening only on WildFly via http upgrade connection.

        • 1. Re: WF10/Artemis - significant delay on receiving via HornetQ client
          Justin Bertram Master

          I'm not sure I understand your issue...

           

          I've been using org.hornetq.client module to connect with WildFly/JMS server, and it was working fine on WildFly 10.0.0.CR4.

          When you say you've been using the "org.hornetq.client module" are you referring to a client that's running in the same JVM as Wildfly or are you referring to a remote, legacy HornetQ client?

           

          If I write the client with ActiveMQ Artemis native API then that delay doesn't occur.

          The "core" API for both HornetQ and Artemis is basically the same.  The class names have changed, but all the methods are the same.  What API was your client using previously?  Was it JMS?

           

          My question is, is the org.hornetq.client module not supposed to be used to connect with ActiveMQ Artemis embedded in WildFly 10?

          Legacy HornetQ clients should still be able to connect to ActiveMQ Artemis, but if you are able to move the client to current libraries then that's the recommended approach.

           

           

          Lastly, do you have a reproducible test-case you can share for this issue?

          • 2. Re: WF10/Artemis - significant delay on receiving via HornetQ client
            Tomohisa igarashi Master

            Thanks for the reply Justin,

             

            Oops sorry my word was wrong, the client is standalone and not really using "org.hornetq.client module" in WildFly, but using hornetq-jms-client 2.4.7.Final. It's doing like this:

            https://github.com/jboss-switchyard/switchyard/blob/master/components/test/mixins/hornetq/src/main/java/org/switchyard/component/test/mixins/hornetq/HornetQMixIn.java#L376-L395

             

            Right now the code is a part of SwitchYard, so I'll try to make a minimal reproducer later if it's still worth.

            • 3. Re: WF10/Artemis - significant delay on receiving via HornetQ client
              Tomohisa igarashi Master

              Attaching a testcase reproduces the symptom, but...

               

              Unexpectedly that delay only happens with Artemis client, but not with HornetQ client with this testcase. When I run this here against WildFly 10.0.0.Final, the first receive(1000) call was blocked 30 seconds with Artemis client while HornetQ client finished in 1 sec.

               

              Anyway, if I try this against WildFly 10.0.0.CR4 then both of Artemis client and HornetQ client finishes to receive all the messages within 1 sec, so something wrong seems to have happened between artemis 1.1.0.wildfly.007 and artemis 1.1.0.wildfly-011.

               

              jbertram, could you have a look at this please?

               

              Thanks,

              Tomo

              • 4. Re: WF10/Artemis - significant delay on receiving via HornetQ client
                Miroslav Novak Master

                Could you double check that there was no connection left opened? For example if test is interrupted before connection is close then server has a timeout (30s) after which dead connection is disconnected. If there was consumer created on this "old" connection then it can happen that messages will not be delivered to consumer on "new" connection as it was created later. It will wait untill "old" connection is timeouted.

                • 5. Re: WF10/Artemis - significant delay on receiving via HornetQ client
                  Tomohisa igarashi Master

                  Thanks for the reply, but connection is closed in finally. Moreover receive(timeout) shouldn't be blocked over timeout in any reason.

                   

                  I tried to create ConnectionFactory for every session instead of reusing it, but it didn't help at all. Of course it is closed in finally.

                  • 6. Re: WF10/Artemis - significant delay on receiving via HornetQ client
                    Justin Bertram Master

                    I finally got around to running your test.  My results indicate no problem with the Artemis client.  However, I do see the delay with the HornetQ client.  Here's the results:

                     

                    Running ArtemisHornetQClientTest
                    13:47:22,986 INFO  [ArtemisHornetQClientTest] [ 204]: * Starting to send/receive using HornetQ client API
                    13:47:23,005 INFO  [ArtemisHornetQClientTest] [ 224]: * * Sent a message 'foobar-0' to 'HornetQQueue[DLQ]'
                    13:47:23,008 INFO  [ArtemisHornetQClientTest] [ 227]: * * Sent a message 'foobar-1' to 'HornetQQueue[DLQ]'
                    13:47:23,012 INFO  [ArtemisHornetQClientTest] [ 231]: * * Sent a message 'foobar-2' to 'HornetQQueue[DLQ]'
                    13:47:23,014 INFO  [ArtemisHornetQClientTest] [ 233]: * * Sent a message 'foobar-3' to 'HornetQQueue[DLQ]'
                    13:47:23,017 INFO  [ArtemisHornetQClientTest] [ 236]: * * Sent a message 'foobar-4' to 'HornetQQueue[DLQ]'
                    13:47:52,973 INFO  [ArtemisHornetQClientTest] [ 30192]: * * Received a message 'foobar-0' to 'HornetQQueue[DLQ]'
                    13:47:52,973 INFO  [ArtemisHornetQClientTest] [ 30192]: * * Received a message 'foobar-1' to 'HornetQQueue[DLQ]'
                    13:47:52,973 INFO  [ArtemisHornetQClientTest] [ 30192]: * * Received a message 'foobar-2' to 'HornetQQueue[DLQ]'
                    13:47:52,974 INFO  [ArtemisHornetQClientTest] [ 30193]: * * Received a message 'foobar-3' to 'HornetQQueue[DLQ]'
                    13:47:52,974 INFO  [ArtemisHornetQClientTest] [ 30193]: * * Received a message 'foobar-4' to 'HornetQQueue[DLQ]'
                    13:47:52,980 INFO  [ArtemisHornetQClientTest] [ 30199]: * Finished
                    13:47:53,061 INFO  [ArtemisHornetQClientTest] [ 76]: * Starting to send/receive using Artemis client API
                    13:47:53,079 INFO  [ArtemisHornetQClientTest] [ 94]: * * Sent a message 'foobar-0' to 'ActiveMQQueue[DLQ]'
                    13:47:53,082 INFO  [ArtemisHornetQClientTest] [ 97]: * * Sent a message 'foobar-1' to 'ActiveMQQueue[DLQ]'
                    13:47:53,085 INFO  [ArtemisHornetQClientTest] [ 100]: * * Sent a message 'foobar-2' to 'ActiveMQQueue[DLQ]'
                    13:47:53,089 INFO  [ArtemisHornetQClientTest] [ 104]: * * Sent a message 'foobar-3' to 'ActiveMQQueue[DLQ]'
                    13:47:53,092 INFO  [ArtemisHornetQClientTest] [ 107]: * * Sent a message 'foobar-4' to 'ActiveMQQueue[DLQ]'
                    13:47:53,116 INFO  [ArtemisHornetQClientTest] [ 131]: * * Received a message 'foobar-0' to 'ActiveMQQueue[DLQ]'
                    13:47:53,116 INFO  [ArtemisHornetQClientTest] [ 131]: * * Received a message 'foobar-1' to 'ActiveMQQueue[DLQ]'
                    13:47:53,117 INFO  [ArtemisHornetQClientTest] [ 132]: * * Received a message 'foobar-2' to 'ActiveMQQueue[DLQ]'
                    13:47:53,118 INFO  [ArtemisHornetQClientTest] [ 133]: * * Received a message 'foobar-3' to 'ActiveMQQueue[DLQ]'
                    13:47:53,119 INFO  [ArtemisHornetQClientTest] [ 134]: * * Received a message 'foobar-4' to 'ActiveMQQueue[DLQ]'
                    13:47:53,126 INFO  [ArtemisHornetQClientTest] [ 141]: * Finished
                    Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 30.471 sec
                    
                    
                    Results :
                    
                    
                    Tests run: 2, Failures: 0, Errors: 0, Skipped: 0
                    

                     

                    Can you confirm you're seeing the delay with the Artemis client?

                    • 7. Re: WF10/Artemis - significant delay on receiving via HornetQ client
                      Tomohisa igarashi Master

                      Thanks for trying it Justin!

                      I actually saw this delay issue on both of HornetQ client and Artemis client. If I add @Ignore on HornetQ client test, then the delay occur in Artemis client test. But it's not 100%, sometimes it succeeds without delay, which suggests it may be a timing issue.

                       

                      Jeff found a workaround for this delay issue, it seems if JMS2.0 API (JMSContext) is used then the delay doesn't occur.

                      [WFLY-6420] 30secs delay on consumer.receive() in spite of shorter timeout - JBoss Issue Tracker

                       

                      It means we need to add separate client helper for the WildFly test in SwitchYard though... as we still need to support EAP6 at the same time.

                      • 8. Re: WF10/Artemis - significant delay on receiving via HornetQ client
                        Tomohisa igarashi Master

                        Just to share the conclusion so that anyone else hit this issue would find....

                         

                        The root cause was in my test code which didn't set required property TransportConstants.HTTP_UPGRADE_ENDPOINT_PROP_NAME

                        transportParams.put(org.apache.activemq.artemis.core.remoting.impl.netty.TransportConstants.HTTP_UPGRADE_ENDPOINT_PROP_NAME, "http-acceptor");
                        

                         

                        Once I set this property then delay issue went away from any combination of JMS1.1/2.0 and Artemis/HornetQ client.

                         

                        Aside, I hit another pitfall in HornetQ client dependency. Although WildFly 10 Final contains netty 4.0.32.Final, HornetQ client 2.4.7.Final doesn't work well with that version. I needed to explicitly override netty dependency with 4.0.13.Final. So if you have a dependency on wildfly-parent, wrong combination (hornetq-2.4.7&netty-4.0.32) is brought into the project and it hits packet decode error.