Tests take too long to run

[jboynes]

Many of the unit tests start a server which is a process that can take many seconds - about 80 on my machine, for each test, due to the number of interfaces being probed by jMDNS. This makes development quite inefficient as it takes around an hour to run the test suite.

I propose we move most of those to integration tests that will be run during the "verify" phase and add new unit tests that do not require starting an entire server.

[rob42]

Hmm, I dont see the same delays you are getting - can you advise the OS and number of interfaces pls? I'm on kubuntu 15.04, one wifi interface. I just noticed the pull request for released version of jmdns - I'm not using it yet, maybe related?

[jboynes]

I attached a log from running a single test using HEAD (i.e. without the jmdns patch). Run time was 01:35, most of it spent running the test. There's a 69s pause at 20:40:10,239 after Saved state loaded from ./conf/self.json

$ sw_vers
ProductName:    Mac OS X
ProductVersion: 10.11.2
BuildVersion:   15C50

$ java -version
java version "1.8.0_66"
Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode)

$ ifconfig | grep '^[a-z0-9]*:'
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> mtu 16384
gif0: flags=8010<POINTOPOINT,MULTICAST> mtu 1280
stf0: flags=0<> mtu 1280
en0: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500
en1: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500
en2: flags=963<UP,BROADCAST,SMART,RUNNING,PROMISC,SIMPLEX> mtu 1500
en3: flags=963<UP,BROADCAST,SMART,RUNNING,PROMISC,SIMPLEX> mtu 1500
p2p0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 2304
awdl0: flags=8943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST> mtu 1484
bridge0: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500
vboxnet0: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
vboxnet1: flags=8943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST> mtu 1500
vboxnet2: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
utun0: flags=8051<UP,POINTOPOINT,RUNNING,MULTICAST> mtu 1500

With the new version I was seeing messages about probes on all interfaces but that test does not seem to emit that. I'm rerunning all to see. Nope, no output and completed in 17:55 so a bit quicker.

I'll continue to dig in

[rob42]

Hmm, you have a lot more interfaces, I have eth0, lo, virbr0, wlan0. Its happening in RouteManager.configure0(), at:

SignalKModelFactory.load(signalkModel); //this is the `Saved state..` message

        //set shutdown quickly, 5 min is too long
        CamelContextFactory.getInstance().getShutdownStrategy().setShutdownNowOnTimeout(true);
        CamelContextFactory.getInstance().getShutdownStrategy().setTimeout(10);

        //DNS-SD
        //NetworkTopologyDiscovery netTop = NetworkTopologyDiscovery.Factory.getInstance();

        jmdns = JmmDNS.Factory.getInstance();

        jmdns.registerServiceType(_SIGNALK_WS_TCP_LOCAL);
        jmdns.registerServiceType(_SIGNALK_HTTP_TCP_LOCAL);
        ServiceInfo wsInfo = ServiceInfo.create(_SIGNALK_WS_TCP_LOCAL,"signalk-ws",wsPort, 0,0, getMdnsTxt());
        jmdns.registerService(wsInfo);

        ServiceInfo httpInfo = ServiceInfo
                .create(_SIGNALK_HTTP_TCP_LOCAL, "signalk-http",restPort,0,0, getMdnsTxt());
        jmdns.registerService(httpInfo);

        //Netty tcp server 
        skServer = new NettyServer(null, ConfigConstants.OUTPUT_TCP); //the nio log messages

So the 69 sec is in the JmmDNS library. Wonder if that can be improved....its a significant part of the boot.

[rob42]

Found this at http://sourceforge.net/p/jmdns/bugs/82/

"Starting an mDNS incur a penalty of at least 6 seconds so if you create JmDNS when the user ask for the registration there will be 9 to 10 seconds before the service is visible. This has been discussed before and cannot be compressed. The way MacOSX and IOS run around that problem is by having a daemon running in the background on a permanent basis. That way you only need to register the service which take 3 to 4 seconds."

[jboynes]

This is my dev machine which has Docker and other things running. The 6 seconds corresponds with what I was seeing in the logs for the probe timeouts on each interface. If the 6 sec is part of the protocol (admittedly I've not read the spec) there's not much we can do.

I don't see this as a problem for normal use as the server would not be restarted often. We may be able to speed things up by starting jmdns on a background thread, IOW start all protocol handlers in parallel, but for now that seems like over-complicating things.

I'll take a look at moving tests over to the integration-test phase.

[rob42]

Actually what about setting a system param and wrapping the start in an if(startMdns){..}? That would solve it for integration tests too. It can be set on the tests that dont need it before Camel is started?

[rob42]

Maybe SignalKCamelTestSupport needs another method startMdns(boolean start) that sets the system property, then auto unset at test end?

[rob42]

Ive just commited a fix for this into master - it just runs the mdns init in a background thread. Seems to work for me, but will possibly cause problems with 10 interfaces (6 secs x 10 = 60sec) which may be longer than the test, hence shutdown may not complete nicely. Let me know.

[rob42]

Added a setDaemon(true) so the thread will die when the JVM exits, hence it should now stop initialising if the test finishes earlier than the init.