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

Answer 1

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?

Answer 2

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)

Answer 3

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()
        }

Answer 4

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.