Establishing connection to cluster is slow

[jlindwall]

I am performance testing various JMS brokers including hornetq 2.4.0-Final.  My initial tests were done with a single standalone node; I am now moving on to using a cluster.  My simple cluster has 2 nodes; I have tried both nodes on separate machines as well as both on the same box, with the same result.

My problem is this: though the cluster seems to function properly once all connections are established, the initial connecting takes a long time.  My simple "smokescreen" test uses 10 topics; each topic has 16 subscribers and 20 publishers.  To the total number of connections to the broker in this example is 360.  Establishing these connections takes 15 minutes

I'm guessing that I have something configured badly.  I am new to hornetq and doubtless there is a lot of additional info I might provide to help in diagnosing this issue; I am just not sure what to provide.  If I enable debug logging I get a lot of chatter on the boxes, some of which _sounds_ creepy but I am unsure.

Any advice?  Thanks!

John

[jbertram]

Couple of questions...

1. Are you using NIO?
2. Does it take the same amount of time to establish the connections if you connect to a single node instead of a cluster?
3. Can you provide a test I can run myself to (potentially) see the same behavior you're seeing?

[jlindwall]

1. Yes. I am on Solaris spark boxes so cannot use AIO; NIO is enabled by default in my case right?

2. No, it takes 14 seconds to establish all the connection to a single non-clustered node vs 15 minutes for my cluster

3. hmm yes I can.  I will provide one and post the code here

A random note about my environment: I had to add -Djava.net.preferIPv4Stack=true on servers and client (not sure if that matters at all).

Thanks!

[jbertram]

The NIO I was referring to is related to the behavior of Netty (which is used to communicate over the network).  I'm not talking about AIO vs. NIO for the journal on the filesystem.  Take a look at the link in my previous comment and find the documentation on the "use-nio" configuration parameter for Netty.

I'll try out your test-case once you post it.

[jlindwall]

I have reproduced the issue in a test case.  Also, I am now more suspicious of the ipv4 issue I mentioned earlier.  Here is output from the tester against a non-clustered instance:

$ java -jar ~/ConnectionTester-1.0.jar jnp://hostname:2099 360

Time elapsed to create 360 connections to jnp://xapp01:2099: 3 seconds

And now against a cluster with no special options:

$ java -jar ~/ConnectionTester-1.0.jar jnp://hostname:2099

Jun 27, 2014 2:33:47 PM org.hornetq.api.core.UDPBroadcastGroupConfiguration$UDPBroadcastEndpoint openClient

WARN: HQ212049: Could not bind to 239.8.2.2 (IPv4 address); make sure your discovery group-address is of the same type as the IP stack (IPv4 or IPv6).

Ignoring discovery group-address, but this may lead to cross talking.

Jun 27, 2014 2:33:50 PM org.hornetq.api.core.UDPBroadcastGroupConfiguration$UDPBroadcastEndpoint openClient

WARN: HQ212049: Could not bind to 239.8.2.2 (IPv4 address); make sure your discovery group-address is of the same type as the IP stack (IPv4 or IPv6).

Ignoring discovery group-address, but this may lead to cross talking.

Finally, if I add -Djava.net.preferIPv4Stack=true option I "works" but slowly:

$ java -Djava.net.preferIPv4Stack=true -jar ~/ConnectionTester-1.0.jar jnp://hostname:2099

Time elapsed to create 360 connections to jnp://xapp01:2099: 901 seconds

I do not see a way to upload a tar file here, so I'll paste the java file and the pom in a followup msg. Hope it works!

[jlindwall]

package com.xifin;
import javax.jms.*;
import javax.naming.Context;
import javax.naming.InitialContext;
import javax.naming.NamingException;
import java.util.ArrayList;
import java.util.List;
import java.util.Properties;
import static java.lang.String.format;


/** * Created by jlindwall on 6/27/14. */ 
public class ConnectionTester {
    public static final int DEFAULT_NUM_CONNS = 360;
    private final String brokerUrl;
    private final int numConns;


    public ConnectionTester(String brokerUrl, int numConns) {
        this.brokerUrl = brokerUrl;
        this.numConns = numConns;
    }


    public static void main(String[] args) throws JMSException, NamingException {
        if( args.length < 1 ) {             System.err.println("Usage: ConnectionTester []");
            System.err.println("");
            System.err.println("  brokerUrl  The url of the hornetq broker");
            System.err.println("  numConns    How many connections to create; defaults to 360");
            System.exit(1);
        }
        String brokerUrl = args[0];
        int numConns = DEFAULT_NUM_CONNS;
        if( args.length > 1 ) {
            numConns = Integer.valueOf(args[1]);
        }
        ConnectionTester tester = new ConnectionTester(brokerUrl, numConns);
        tester.go();
    }


    private void go() throws JMSException, NamingException {
        long start = System.currentTimeMillis();
        List conns = new ArrayList(numConns);
        try {
            for( int i = 0; i < numConns; i++ ) {
                conns.add( createConnection(brokerUrl, i) );
            }
            long end = System.currentTimeMillis();
            long elapsedSecs = (end-start) / 1000;
            System.out.printf("Time elapsed to create %d connections to %s: %d seconds\n", numConns, brokerUrl, elapsedSecs);
        } finally {
            closeConnections(conns);
        }
    }


    private void closeConnections(List conns) {
        for( TopicConnection tc: conns ) {
            try {
                tc.close();
            } catch (JMSException e) {
                System.err.println("Failed to close conn: " + e.getMessage());
            }
        }
    }


    private TopicConnection createConnection(String brokerUrl, int index) throws JMSException, NamingException {
        InitialContext context = createInitialContext(brokerUrl);
        TopicConnectionFactory topicConnectionFactory = (TopicConnectionFactory) createInitialContext(brokerUrl).lookup("/ConnectionFactory");
        TopicConnection topicConnection = topicConnectionFactory.createTopicConnection();
        return topicConnection;
    }


    public InitialContext createInitialContext(String brokerUrl) throws NamingException {
        Properties env = new Properties();
        env.put(Context.PROVIDER_URL, brokerUrl);
        env.put(Context.INITIAL_CONTEXT_FACTORY, "org.jnp.interfaces.NamingContextFactory");
        env.put(Context.URL_PKG_PREFIXES, "org.jboss.naming:org.jnp.interfaces");
        return new InitialContext(env);
    }
}

[jlindwall]

Well, that code looks terrible.. is there some nice way for me to send you the maven project?

[jbertram]

When you're composing a comment click the "Use advanced editor" near the top right of the text box and you can attach files.

[jlindwall]

Here is my maven project to demonstrate my slow connection issue with a cluster (see attached). My machine environment is sparc Solaris.

$ uname -a

SunOS xapp01 5.11 11.1 sun4u sparc SUNW,SPARC-Enterprise

[jbertram]

I used your test to connect to both a single instance of HornetQ as well as a 2 node cluster.  In both instances I received this:

Time elapsed to create 360 connections to jnp://localhost:1099: 4 seconds

As far as I can tell this issue is environmental.  One thing you might try is not doing the JNDI look-up every single time you create a connection.  Cache the result of the look-up and re-use the result for subsequent connections.

BTW, I'm on Linux.

$ uname -a
Linux workhorse 3.13.0-30-generic #54-Ubuntu SMP Mon Jun 9 22:45:01 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux