WF10/Artemis - significant delay on receiving

[igarashitm]

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.

[jbertram]

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?

[igarashitm]

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.

[igarashitm]

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

[mnovak]

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.

[igarashitm]

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.

[jbertram]

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?

[igarashitm]

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.

[igarashitm]

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.