Log warning on slow host resolution

[mbhave]

The current logger startup can be quite slow on a fresh OSX install. The root cause is:

InetAddress.getLocalHost().getHostName() in StartupInfoLogger

See for workaround and background https://thoeni.io/post/macos-sierra-java/

[wilkinsona]

I don't think we should be trying to work around this. The underlying cause has been in Java for some time. I believe it's appearing more frequently now due to the (mis)configuration of macOS after an upgrade to Sierra. It's also happened in the past with other macOS upgrades.

When you request a hostname, the JDK resolves it to IP addresses. It then tries a reverse lookup of those addresses and checks that at least one of the results maps back to the input host name. It's this reverse lookup that's slow. The slowness isn't limited to the JVM. Anything on the OS that tries to perform such a reverse lookup will be slow without appropriate configuration in /etc/hosts.

[snicoll]

For the record, I was about to write something similar this morning and forgot. I don't think we should try to find a workaround in our codebase for this.

[philwebb]

I was hoping there would be a system property that we could use, but I can't find one. I can't get the lookup to slow down locally, but I wondered if this would be an option:

        long time = System.nanoTime();
        if (true) {
            Class<?> inetAddress = InetAddress.class;
            Field field = ReflectionUtils.findField(inetAddress, "impl");
            field.setAccessible(true);
            Object impl = ReflectionUtils.getField(field, null);
            Method method = ReflectionUtils.findMethod(impl.getClass(),
                    "getLocalHostName");
            method.setAccessible(true);
            System.out.println(ReflectionUtils.invokeMethod(method, impl));
        }
        else {
            System.out.println(InetAddress.getLocalHost().getHostName());
        }
        System.out.println(TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - time));

It's probably too hacky!

[philwebb]

Another option might be to call InetAddress.getLocalHost().getHostName() in a thread with and timeout if we don't get an answer quickly.

[spencergibb]

@philwebb we use another thread in InetUtils in spring cloud.

[wilkinsona]

They're all point solutions for a JVM- or even OS- wide problem. People will almost inevitably hit another call to getHostname() that's slow and fix their network configuration. At that point we're needlessly using a reflective hack or spawning a thread. I really don't think we should.

[haskovec]

This has hit me pretty bad on my laptop since upgrading to Sierra. I have a Spring boot app that connects to AWS SQS (using the Spring Messaging AWS starter). It connects to something like 8 or 10 different queues for all sorts of different operations. Prior to Upgrading to Sierra the app would launch in about 11 seconds. After it takes 150 seconds. I heard about this issue being related to the /etc/hosts, so I edited the /etc/hosts file on my Mac and added my hostname as another entry under localhost. That helped a bit as the startup went from 150 to 141 seconds. But there is still something going on. I haven't been able to find any other suggestions to get performance back to El Capitan levels, but it is pretty painful now. I have sort of recommended that everyone avoid upgrading until I can find a reasonable solution.

[wilkinsona]

@haskovec Thanks for the data points. Some thread dumps taken during the 141 second startup period would be interesting if you have time to capture them.

[philwebb]

@haskovec Try adding both <computername> and <computer>.local to your hosts file. That seemed to fix things for us. Also check that your using your actual "computer name" as defined in System Preferences -> Sharing.

[haskovec]

Hey Phil, Thanks for the suggestion. I double checked my System Preferences -> Sharing. I had computername.local in my hosts, but not computername in my hosts. I added it as well, and still no luck. I will try to do some stack traces as I have 2 spring apps which show the issue. One a conventional Spring app running Spring 4.3 whose startup time went from 24 seconds to 60-65 seconds. The second a Spring boot 1.4.1 app (without a Database, but With amazon SQS) whose startup time went from 11 seconds to 141 seconds. I will see if I can do some jstack's on startup as Andy suggested above to see if that gives us any clues.

[haskovec]

I took a bunch of different stack traces on the 141 second app. They all seem to hang on the SQS get EC2 credentials bit:
test10.txt

[philwebb]

2016-10-10 22:35:47
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.102-b14 mixed mode):

"Attach Listener" #21 daemon prio=9 os_prio=31 tid=0x00007f860f811000 nid=0x5d0b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"GC Daemon" #20 daemon prio=2 os_prio=31 tid=0x00007f860d203800 nid=0x6303 in Object.wait() [0x0000700005181000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0000000774cf16e0> (a sun.misc.GC$LatencyLock)
    at sun.misc.GC$Daemon.run(GC.java:117)
    - locked <0x0000000774cf16e0> (a sun.misc.GC$LatencyLock)

"container-0" #19 prio=5 os_prio=31 tid=0x00007f86106d8800 nid=0x6103 waiting on condition [0x000070000507e000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.catalina.core.StandardServer.await(StandardServer.java:427)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedServletContainer$1.run(TomcatEmbeddedServletContainer.java:167)

"ContainerBackgroundProcessor[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[]]" #18 daemon prio=5 os_prio=31 tid=0x00007f860ccbd000 nid=0x5f03 waiting on condition [0x0000700004f7b000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1339)
    at java.lang.Thread.run(Thread.java:745)

"java-sdk-http-connection-reaper" #15 daemon prio=5 os_prio=31 tid=0x00007f860e7cf000 nid=0x1207 waiting on condition [0x00007000035aa000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at com.amazonaws.http.IdleConnectionReaper.run(IdleConnectionReaper.java:157)

"Service Thread" #12 daemon prio=9 os_prio=31 tid=0x00007f860981b000 nid=0x5803 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #11 daemon prio=9 os_prio=31 tid=0x00007f860b840800 nid=0x5603 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #10 daemon prio=9 os_prio=31 tid=0x00007f8608019000 nid=0x5403 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #9 daemon prio=9 os_prio=31 tid=0x00007f860b86a000 nid=0x5203 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #8 daemon prio=9 os_prio=31 tid=0x00007f860a80f000 nid=0x5003 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Command Reader" #7 daemon prio=10 os_prio=31 tid=0x00007f8608815800 nid=0x4e03 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Event Helper Thread" #6 daemon prio=10 os_prio=31 tid=0x00007f860c008000 nid=0x4c03 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Transport Listener: dt_socket" #5 daemon prio=10 os_prio=31 tid=0x00007f860c001000 nid=0x4a03 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007f860c000000 nid=0x4803 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007f860b007000 nid=0x3903 in Object.wait() [0x0000700004254000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006c0015500> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000006c0015500> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007f8608000000 nid=0x3703 in Object.wait() [0x0000700004151000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006c0046f58> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x00000006c0046f58> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=31 tid=0x00007f860a802000 nid=0x1c03 runnable [0x0000700003731000]
   java.lang.Thread.State: RUNNABLE
    at java.net.PlainSocketImpl.socketConnect(Native Method)
    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
    - locked <0x0000000773460e50> (a java.net.SocksSocketImpl)
    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
    at java.net.Socket.connect(Socket.java:589)
    at sun.net.NetworkClient.doConnect(NetworkClient.java:175)
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
    - locked <0x0000000773460dc8> (a sun.net.www.http.HttpClient)
    at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)
    at sun.net.www.http.HttpClient.New(HttpClient.java:308)
    at sun.net.www.http.HttpClient.New(HttpClient.java:326)
    at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1169)
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1105)
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999)
    at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:933)
    at com.amazonaws.internal.EC2CredentialsUtils.readResource(EC2CredentialsUtils.java:70)
    at com.amazonaws.auth.InstanceProfileCredentialsProvider$InstanceMetadataCredentialsEndpointProvider.getCredentialsEndpoint(InstanceProfileCredentialsProvider.java:117)
    at com.amazonaws.auth.EC2CredentialsFetcher.fetchCredentials(EC2CredentialsFetcher.java:121)
    - locked <0x00000006c0ebd3c0> (a com.amazonaws.auth.EC2CredentialsFetcher)
    at com.amazonaws.auth.EC2CredentialsFetcher.getCredentials(EC2CredentialsFetcher.java:82)
    at com.amazonaws.auth.InstanceProfileCredentialsProvider.getCredentials(InstanceProfileCredentialsProvider.java:104)
    at com.amazonaws.auth.AWSCredentialsProviderChain.getCredentials(AWSCredentialsProviderChain.java:115)
    at com.amazonaws.http.AmazonHttpClient.getCredentialsFromContext(AmazonHttpClient.java:781)
    at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:807)
    at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:702)
    at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:454)
    at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:416)
    at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:365)
    at com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:1741)
    at com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:1711)
    at com.amazonaws.services.sqs.AmazonSQSClient.getQueueAttributes(AmazonSQSClient.java:1010)
    at com.amazonaws.services.sqs.buffered.AmazonSQSBufferedAsyncClient.getQueueAttributes(AmazonSQSBufferedAsyncClient.java:262)
    at org.springframework.cloud.aws.messaging.listener.AbstractMessageListenerContainer.queueAttributes(AbstractMessageListenerContainer.java:298)
    at org.springframework.cloud.aws.messaging.listener.AbstractMessageListenerContainer.initialize(AbstractMessageListenerContainer.java:270)
    - locked <0x000000076ee7bc18> (a java.lang.Object)
    at org.springframework.cloud.aws.messaging.listener.SimpleMessageListenerContainer.initialize(SimpleMessageListenerContainer.java:110)
    at org.springframework.cloud.aws.messaging.listener.AbstractMessageListenerContainer.afterPropertiesSet(AbstractMessageListenerContainer.java:250)
    at org.springframework.cloud.aws.messaging.listener.SimpleMessageListenerContainer.afterPropertiesSet(SimpleMessageListenerContainer.java:44)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1637)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1574)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
    - locked <0x00000006c01f2a98> (a java.util.concurrent.ConcurrentHashMap)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:776)
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:861)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:541)
    - locked <0x00000006c0047308> (a java.lang.Object)
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:122)
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:759)
    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:369)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:313)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1185)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1174)
    at com.chooseenergy.dispatcher.DispatcherApplication.main(DispatcherApplication.java:10)

"VM Thread" os_prio=31 tid=0x00007f860b859000 nid=0x3503 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007f8609008800 nid=0x2503 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007f860a80a800 nid=0x2703 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007f860a80b800 nid=0x2903 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007f860a80c000 nid=0x2b03 runnable 

"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007f860a80c800 nid=0x2d03 runnable 

"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007f860a80d000 nid=0x2f03 runnable 

"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007f860a80e000 nid=0x3103 runnable 

"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007f860a80e800 nid=0x3303 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007f8609009000 nid=0x5a03 waiting on condition 

JNI global references: 20272