Micronaut's EmbeddedServer startup extremely slow

Question

I created a micronaut "Hello World!" application and a JUnit test according to the Micronaut user guide:

https://docs.micronaut.io/latest/guide/index.html#creatingClient

on macOS Mojave (10.14) with Java 1.8.0_25-b17.

Unit test:

package hello;

import io.micronaut.http.HttpStatus;
import io.micronaut.http.client.RxHttpClient;
import io.micronaut.runtime.server.EmbeddedServer;
import io.micronaut.test.annotation.MicronautTest;
import org.junit.jupiter.api.Test;
import javax.inject.Inject;

import static org.junit.jupiter.api.Assertions.assertEquals;

@MicronautTest
public class HelloControllerTest {

    @Inject
    EmbeddedServer embeddedServer;

    @Test
    public void testIndex() throws Exception {
        // or (instead of the @Inject): 
        // EmbeddedServer embeddedServer = ApplicationContext.run(EmbeddedServer.class);

        try(RxHttpClient client = embeddedServer.getApplicationContext().createBean(RxHttpClient.class, embeddedServer.getURL())) {
            assertEquals(HttpStatus.OK, client.toBlocking().exchange("/hello").status());
        }
    }
}

The "Hello World!" application starts up quickly (about a second). The JUnit test, however, takes more than 75 seconds to complete. It 'hangs' on the following line for 75 seconds:

server = ApplicationContext.run(EmbeddedServer.class);

Suggested fix in /etc/hosts doesn't work

I've tried this suggested fix (adding the hostname to /etc/hosts after the "127.0.0.1 localhost" and "::1 localhost" entries -- both with and without the '.local' suffix):

https://docs.micronaut.io/latest/guide/index.html#problems

Jvm takes a long time to resolve ip-address for localhost

with no luck. I restarted my machine after changes to /etc/hosts.

The hostname resolution does not seem to be the problem though; I tested it with the inetTester.jar mentioned in the above link (download here: https://github.com/thoeni/inetTester), it takes only 6ms. I guess it must be something else.

(On the other hand, everyone who had problems with micronaut application startup time (which I do not) on macOS, and fixed it by adding hostname to /etc/hosts, also mentions this same ~75 second delay -- this can't really be a coincidence?)

Log file

The two lines in the log file, before and after the 75 second pause:

22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Registering singleton bean io.micronaut.http.server.netty.NioEventLoopGroupFactory@4b1c0397 for type [io.micronaut.http.server.netty.EventLoopGroupFactory] using bean key io.micronaut.http.server.netty.NioEventLoopGroupFactory
22:56:22.040 [main] DEBUG io.micronaut.context.lifecycle - Created bean [io.micronaut.http.server.netty.NettyHttpServer@2fe88a09] from definition [Definition: io.micronaut.http.server.netty.NettyHttpServer] with qualifier [null]

And a bit of context:

22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Finding candidate beans for type: interface io.micronaut.http.server.netty.ssl.ServerSslBuilder
22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Resolved bean candidates [] for type: interface io.micronaut.http.server.netty.ssl.ServerSslBuilder
22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Resolving beans for type: io.netty.channel.ChannelOutboundHandler
22:55:06.833 [main] TRACE i.m.context.DefaultBeanContext - Looking up existing beans for key: io.netty.channel.ChannelOutboundHandler
22:55:06.833 [main] TRACE i.m.context.DefaultBeanContext - No beans found for key: io.netty.channel.ChannelOutboundHandler
22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Finding candidate beans for type: interface io.netty.channel.ChannelOutboundHandler
22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Resolved bean candidates [] for type: interface io.netty.channel.ChannelOutboundHandler
22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Found no possible candidate beans of type [io.netty.channel.ChannelOutboundHandler] for qualifier: null 
22:55:06.833 [main] TRACE i.m.context.DefaultBeanContext - Looking up existing bean for key: io.micronaut.http.server.netty.EventLoopGroupFactory
22:55:06.833 [main] TRACE i.m.context.DefaultBeanContext - No existing bean found for bean key: io.micronaut.http.server.netty.EventLoopGroupFactory
22:55:06.833 [main] DEBUG i.m.context.DefaultBeanContext - Finding candidate beans for type: interface io.micronaut.http.server.netty.EventLoopGroupFactory
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Finding candidate beans for type: class io.micronaut.http.server.netty.EpollEventLoopGroupFactory
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Resolved bean candidates [] for type: class io.micronaut.http.server.netty.EpollEventLoopGroupFactory
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Finding candidate beans for type: class io.micronaut.http.server.netty.KQueueEventLoopGroupFactory
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Resolved bean candidates [] for type: class io.micronaut.http.server.netty.KQueueEventLoopGroupFactory
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Resolved bean candidates [Definition: io.micronaut.http.server.netty.NioEventLoopGroupFactory] for type: interface io.micronaut.http.server.netty.EventLoopGroupFactory
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Finalized bean definitions candidates: [Definition: io.micronaut.http.server.netty.NioEventLoopGroupFactory]
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Found concrete candidate [Definition: io.micronaut.http.server.netty.NioEventLoopGroupFactory] for type: io.micronaut.http.server.netty.EventLoopGroupFactory 
22:55:06.834 [main] DEBUG io.micronaut.context.lifecycle - Created bean [io.micronaut.http.server.netty.NioEventLoopGroupFactory@4b1c0397] from definition [Definition: io.micronaut.http.server.netty.NioEventLoopGroupFactory] with qualifier [null]
22:55:06.834 [main] DEBUG i.m.context.DefaultBeanContext - Registering singleton bean io.micronaut.http.server.netty.NioEventLoopGroupFactory@4b1c0397 for type [io.micronaut.http.server.netty.EventLoopGroupFactory] using bean key io.micronaut.http.server.netty.NioEventLoopGroupFactory
22:56:22.040 [main] DEBUG io.micronaut.context.lifecycle - Created bean [io.micronaut.http.server.netty.NettyHttpServer@2fe88a09] from definition [Definition: io.micronaut.http.server.netty.NettyHttpServer] with qualifier [null]
22:56:22.041 [main] DEBUG i.m.context.DefaultBeanContext - Registering singleton bean io.micronaut.http.server.netty.NettyHttpServer@2fe88a09 for type [io.micronaut.runtime.server.EmbeddedServer] using bean key io.micronaut.http.server.netty.NettyHttpServer
22:56:22.042 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
22:56:22.050 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
22:56:22.050 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
22:56:22.056 [main] DEBUG i.n.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
22:56:22.063 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@2ca6546f
22:56:22.063 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@6b63d445
22:56:22.063 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@7578e06a
22:56:22.064 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@30b2b76f
22:56:22.064 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@56da52a7
22:56:22.064 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@23ee75c5

Definitely seems like the same problem. I would ensure you edited the hosts file correctly. You can do a simple test using the project in the SO answer you linked to verify with certainty whether or not that is the problem. — James Kleeh, May 18 '19 at 17:49
Double checked my changes to the /etc/hosts file and updated my question. Nothing can really go wrong there, I have a dead simple hosts file with only the "127.0.0.1 localhost" and "::1 localhost" and "255.255.255.255 broadcasthost" entries and nothing else. Tested it with and without the "255.255.255.255 broadcasthost" entry. Also tested hostname resolution with the mentioned inetTester.jar tool and that only takes about 6ms. Starting the EmbeddedServer still takes 75 seconds... — Tikus Kucing, May 21 '19 at 20:42
"The "Hello World!" application starts up quickly (about a second). The JUnit test, however, starts an EmbeddedServer:" The typical hello world app also starts an embedded server — James Kleeh, May 22 '19 at 02:41

score 3 · Answer 1 · answered Jul 15 '20 at 12:48

I had a similar issue where the compiled native image was taking over 40 seconds to start. The problem in my case was the environment detection, disabling it solved my problem. I did it in code, you can do it via properties as explained in their docs.

fun main(args: Array<String>) {
            Micronaut.build()
                .packages("com.example")
                .deduceEnvironment(false)  // this line did the trick
                .mainClass(Application.javaClass)
                .start()
        }

score 1 · Answer 2 · answered Nov 24 '20 at 12:06

For anybody coming with the same problem for me only the hosts edit fixes it. For me just normal startup is between 1.6 and 6-8 seconds depending on what is in the hosts file /etc/hosts.

127.0.0.1 localhost -> 6-8s startup

127.0.0.1 localhost MacBook-Pro.local -> 1.6s startup.

So essentially just add $hostname to your 127.0.0.1 route in the hosts file.

cgrim · Answer 3 · 2019-08-01T11:38:30.613

0

I had the same issue where in my case it was 2 minutes and 20 seconds of waiting. Simple workaround is to specify a server port in the Micronaut application configuration like this:

micronaut:
  server:
    host: localhost
    port: 8080

But it will not work when you want to run more than one test at once.

I think that the problem is caused by searching for any available port implemented in SocketUtils.findAvailableTcpPort() and executed in the constructor of the NettyHttpServer class when no port is specified and the environment is Environment.TEST.

Update: from my experience the problem appears only on some networks. For example I don't have any problem in my home network but I had that problem in a hotel network. Probably domain name lookup can influence that - so what about to try to change the DNS server?

edited Aug 01 '19 at 11:38

answered Jun 09 '19 at 20:54

cgrim

4,890
1
23
42

Thanks. I now have this behavior: [A] unit test from IntelliJ: test method and test class take 75 sec. [A'] unit test from IntelliJ, with your addition to application.yml: test method succeeds in <1 sec, class still runs for 75 seconds. When (after 75 seconds) the next unit test in the suite starts, I get "NettyHttpServer - Unable to start server. Port already 8080 in use." [B] and [B'] "mvn clean test" from IntelliJ: Same behavior as [A] and [A'] [C] and [C'] "mvn clean test" from terminal: test method and test class finish within seconds. – Tikus Kucing Jun 11 '19 at 21:20
So my 75 seconds issue now apparantly is an IntelliJ problem. With or without your addition to application.yml, in IntelliJ (maven or not) the test takes 75 sec, but with maven from a (bash) terminal it works fine. As long as I haven't figured out why running micronaut tests from IntelliJ is so slow, I'll just run the test suites from the command line. – Tikus Kucing Jun 11 '19 at 21:22
The "Port already 8080 in use" is of course a completely different issue. I have to find out how to stop the @Injected EmbeddedServer before the unit test class finishes. – Tikus Kucing Jun 11 '19 at 21:23
You are right, this is not a good solution when you need to execute the whole suite and have different port for each test. It is applicable only for a single test execution. Crazy is that today it is fast for me also without specifying the port. The true is that I restarted the system after about month. Which Java version and OS do you use? – cgrim Jun 12 '19 at 07:50

score 0 · Answer 4 · answered May 09 '20 at 10:44

it seems coming from the network. when i plugged out my cable and my wifi, i had that :

12:34:31.324 [main] INFO  i.m.context.env.DefaultEnvironment - Established active environments: [test]
12:34:32.061 [main] WARN  i.netty.util.internal.MacAddressUtil - Failed to find a usable hardware address from the network interfaces; using random bytes: 11:02:e9:bf:a8:0e:df:83

and my test ran in 267ms (without it's about 30s)

Micronaut's EmbeddedServer startup extremely slow

Suggested fix in /etc/hosts doesn't work

Log file

4 Answers4