I'm trying to find ways to speed up the rebuild process in my application and am stuck trying to figure out what's happening between these log lines after a restart is triggered:
2022-07-04 18:30:16.716 DEBUG 94429 --- [ Thread-5] o.s.boot.devtools.restart.Restarter : Starting application com.example.demo.DemoApplicationKt with URLs [file:/Users/monroe/ws/demo/build/classes/kotlin/main/, file:/Users/monroe/ws/demo/build/resources/main/]
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.7.1)
2022-07-04 18:30:21.747 INFO 94429 --- [ restartedMain] com.example.demo.DemoApplicationKt : Starting DemoApplicationKt using Java 11.0.15 on Monroes-MacBook-Pro.local with PID 94429 (/Users/monroe/ws/demo/build/classes/kotlin/main started by monroe in /Users/monroe/ws/demo)
This is on a brand new repo from Spring Initializr. I've tried three different Java SDKs and see the same 5 second delay each time. I set the root log level to TRACE, but nothing is logged between those lines. I tried profiling the application, but as far as I can tell, nothing is happening in that 5 second window (though I have no experience with Java profilers).
What's happening in that time?
This is on macOS Big Sur v 11.6.7
edit: Trying this in a docker container doesn't result in the same 5 second delay
Comment From: mwalkerr
Just found out this is due to a macOS hostname lookup issue described on these pages: - https://github.com/netty/netty/issues/8993 - https://thoeni.io/post/macos-sierra-java/ - https://stackoverflow.com/questions/39636792/jvm-takes-a-long-time-to-resolve-ip-address-for-localhost/39698914#39698914
The solution for me was to sudo vim /etc/hosts and add the entries recommended in the Stackoverflow answer
127.0.0.1 Monroes-MacBook-Pro.local
::1 Monroes-MacBook-Pro.local
Comment From: wilkinsona
Thanks for the report, @mwalkerr. Ideally, you would have seen a warning logged about the slow hostname resolution (https://github.com/spring-projects/spring-boot/issues/7087) but it doesn't look like that happened in this case. I wonder if some other component called InetAddress.getLocalHost().getHostName() before our StartupInfoLogger. It would be very interesting to know what calls getHostName() when you start the application. If you have time, could you please debug your application with a breakpoint on getHostName and let us know everything that calls it, up to and including the call that's made by StartupInfoLogger?
Comment From: mwalkerr
@wilkinsona sure, will share the stacks here: 1.
getHostName:577, InetAddress (java.net)
getVmId:144, VMManagementImpl (sun.management)
getName:59, RuntimeImpl (sun.management)
getPid:54, ApplicationPid (org.springframework.boot.system)
<init>:45, ApplicationPid (org.springframework.boot.system)
apply:139, LoggingSystemProperties (org.springframework.boot.logging)
apply:87, LogbackLoggingSystemProperties (org.springframework.boot.logging.logback)
apply:134, LoggingSystemProperties (org.springframework.boot.logging)
apply:129, LoggingSystemProperties (org.springframework.boot.logging)
initialize:275, LoggingApplicationListener (org.springframework.boot.context.logging)
onApplicationEnvironmentPreparedEvent:240, LoggingApplicationListener (org.springframework.boot.context.logging)
onApplicationEvent:216, LoggingApplicationListener (org.springframework.boot.context.logging)
doInvokeListener:176, SimpleApplicationEventMulticaster (org.springframework.context.event)
invokeListener:169, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:143, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:131, SimpleApplicationEventMulticaster (org.springframework.context.event)
environmentPrepared:85, EventPublishingRunListener (org.springframework.boot.context.event)
lambda$environmentPrepared$2:66, SpringApplicationRunListeners (org.springframework.boot)
accept:-1, SpringApplicationRunListeners$$Lambda$87/0x0000000800ca1c90 (org.springframework.boot)
forEach:1511, ArrayList (java.util)
doWithListeners:120, SpringApplicationRunListeners (org.springframework.boot)
doWithListeners:114, SpringApplicationRunListeners (org.springframework.boot)
environmentPrepared:65, SpringApplicationRunListeners (org.springframework.boot)
prepareEnvironment:344, SpringApplication (org.springframework.boot)
run:302, SpringApplication (org.springframework.boot)
run:1306, SpringApplication (org.springframework.boot)
run:1295, SpringApplication (org.springframework.boot)
runApplication:30, DemoApplicationKt (com.example.demo)
main:13, DemoApplicationKt (com.example.demo)
invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:77, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:568, Method (java.lang.reflect)
run:49, RestartLauncher (org.springframework.boot.devtools.restart)
2.
getHostName:577, InetAddress (java.net)
lambda$appendOn$1:114, StartupInfoLogger (org.springframework.boot)
call:-1, StartupInfoLogger$$Lambda$219/0x0000000800d63b28 (org.springframework.boot)
callIfPossible:174, StartupInfoLogger (org.springframework.boot)
append:160, StartupInfoLogger (org.springframework.boot)
append:156, StartupInfoLogger (org.springframework.boot)
appendOn:114, StartupInfoLogger (org.springframework.boot)
getStartingMessage:71, StartupInfoLogger (org.springframework.boot)
get:-1, StartupInfoLogger$$Lambda$216/0x0000000800d632b8 (org.springframework.boot)
buildString:155, LogMessage$SupplierMessage (org.springframework.core.log)
toString:70, LogMessage (org.springframework.core.log)
valueOf:4218, String (java.lang)
info:454, LogAdapter$Slf4jLocationAwareLog (org.apache.commons.logging)
logStarting:55, StartupInfoLogger (org.springframework.boot)
logStartupInfo:618, SpringApplication (org.springframework.boot)
prepareContext:377, SpringApplication (org.springframework.boot)
run:307, SpringApplication (org.springframework.boot)
run:1306, SpringApplication (org.springframework.boot)
run:1295, SpringApplication (org.springframework.boot)
runApplication:30, DemoApplicationKt (com.example.demo)
main:13, DemoApplicationKt (com.example.demo)
invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:77, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:568, Method (java.lang.reflect)
run:49, RestartLauncher (org.springframework.boot.devtools.restart)
Looks like the other call is coming from ApplicationPid.getPid()
Comment From: wilkinsona
Thanks, @mwalkerr.
I guess we could time the call to Runtime.getName() and log a warning when it takes too long. Its call getHostName() is an implementation detail so the warning could be inaccurate on some JVMs, however I suspect it's unlikely to take too long unless it's calling getHostName().
I'll flag this for discussion at a team meeting. A little bit of good news is that we already avoid this problem in 3.0 where we use ProcessHandle.current().pid() that was introduced in Java 9.
Comment From: philwebb
We're going to copy/paste the warning logic currently in StartupInfoLogger to ApplicationPid.
Comment From: mwalkerr
That sounds good to me, thank you both for looking at and handling this :)