SpringBoot项目启动缓慢问题处理
- 遇到的问
- 解决方案
- 问题思考
- 结语
- 参考资料
遇到的问题
在一个风和日丽的下午，某位和蔼的同事破口大骂：“卧槽，我程序每次启动都2分钟，我受不了啦！”。另外一位同事却说：“我没问题呀，我20多秒就OK了”。此言一出，引发了大家集体共鸣，看来程序启动缓慢，一直困扰着大家，后面经过了解，QA发布Test环境也有此问题。
启动日志截取如下：
部分日志截取
2020-06-12 18:22:09.391|49280|INFO|[wms-interfaces,,,,]|main|c.p.f.a.r.p.AlicloudRocketMqProducer : alicloud rocketmq producer loading！
2020-06-12 18:22:24.668|49280|INFO|[wms-interfaces,,,,]|main|c.p.f.a.r.p.AlicloudRocketMqProducer : alicloud rocketmq producer 启动耗时[15277]
2020-06-12 18:22:34.083|49280|INFO|[wms-interfaces,,,,]|main|c.p.scm.wms.WmsInterfacesApplication : Started WmsInterfacesApplication in 114.212 seconds (JVM running for 120.306)
解决方案
解决方案其实很简单，只需要在/etc/hosts文件中，增加一段配置，即本机hostname到本机IP的映射。
# shell或者手动添加
echo 127.0.0.1 $(hostname) >> /etc/hosts
echo ::1 $(hostname) >> /etc/hosts
#/etc/hosts
127.0.0.1 localhost zhangweideMacBook-Pro.local
::1 localhost zhangweideMacBook-Pro.local
问题思考
这个问题似乎大家都存在，起初并没有过多在意，推测是接入的中间件较多，开发环境网络不佳导致，但是ping中间件网络地址后，发现延迟是很低的，网络方面似乎没有问题。
我在以前的工作经验中，曾经发生过一次线上故障，生产机器修改hostname后，所有服务响应变的非常缓慢（RT增加数秒），最后查询原因是DNS解析有问题，调整本机DNS后遍恢复。随后配置服务器hosts里面本机IP hostname，成为初始化服务器的必要工作。
出现这个问题后，我第一直觉是尝试修改hosts文件配置，没想到修改后，启动速度马上变快，由以前的120秒缩短至30秒内。
尝试检查启动时的堆栈信息，发现一个与网络相关的方法。结合修改hosts能解决问题的现象，感觉这个方法很可疑。
jstack `jps | grep "WmsInterfacesApplication" | awk '{print $1}'`
"main" #1 prio=5 os_prio=31 tid=0x00007f9bd0000800 nid=0xf03 runnable [0x000070000335e000]
java.lang.Thread.State: RUNNABLE
at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:929)
at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1324)
at java.net.InetAddress.getLocalHost(InetAddress.java:1501)
- locked <0x00000006c0018a98> (a java.lang.Object)
at sun.management.VMManagementImpl.getVmId(VMManagementImpl.java:140)
at sun.management.RuntimeImpl.getName(RuntimeImpl.java:59)
at org.springframework.boot.system.ApplicationPid.getPid(ApplicationPid.java:54)
at org.springframework.boot.system.ApplicationPid.<init>(ApplicationPid.java:45)
于是乎，找到这段代码，打上断点，debug之，果不其然，在没有配置本地hosts时，getLocalHost()这个方法耗时长达5s，而SpringBoot启动时，会多次调用此方法，导致项目启动时间很长。贴上部分代码。
# InetAddress.java
# step1
public static InetAddress getLocalHost() throws UnknownHostException {
SecurityManager security = System.getSecurityManager();
try {
String local = impl.getLocalHostName();
if (security != null) {
security.checkConnect(local, -1);
}
if (local.equals("localhost")) {
return impl.loopbackAddress();
}
InetAddress ret = null;
synchronized (cacheLock) {
long now = System.currentTimeMillis();
if (cachedLocalHost != null) {
if ((now - cacheTime) < maxCacheTime) // Less than 5s old?
ret = cachedLocalHost;
else
cachedLocalHost = null;
}
// we are calling getAddressesFromNameService directly
// to avoid getting localHost from cache
if (ret == null) {
InetAddress[] localAddrs;
try {
// 从这里进入
localAddrs = InetAddress.getAddressesFromNameService(local, null);
} catch (UnknownHostException uhe) {
// Rethrow with a more informative error message.
UnknownHostException uhe2 =
new UnknownHostException(local + ": " +
uhe.getMessage());
uhe2.initCause(uhe);
throw uhe2;
}
cachedLocalHost = localAddrs[0];
cacheTime = now;
ret = localAddrs[0];
}
}
return ret;
} catch (java.lang.SecurityException e) {
return impl.loopbackAddress();
}
}
# step2
private static InetAddress[] getAddressesFromNameService(String host, InetAddress reqAddr)
throws UnknownHostException
{
InetAddress[] addresses = null;
boolean success = false;
UnknownHostException ex = null;
if ((addresses = checkLookupTable(host)) == null) {
try {
for (NameService nameService : nameServices) {
try {
// 这里耗时5s
addresses = nameService.lookupAllHostAddr(host);
success = true;
break;
} catch (UnknownHostException uhe) {
if (host.equalsIgnoreCase("localhost")) {
InetAddress[] local = new InetAddress[] { impl.loopbackAddress() };
addresses = local;
success = true;
break;
}
else {
addresses = unknown_array;
success = false;
ex = uhe;
}
}
}
// More to do?
if (reqAddr != null && addresses.length > 1 && !addresses[0].equals(reqAddr)) {
// Find it?
int i = 1;
for (; i < addresses.length; i++) {
if (addresses[i].equals(reqAddr)) {
break;
}
}
// Rotate
if (i < addresses.length) {
InetAddress tmp, tmp2 = reqAddr;
for (int j = 0; j < i; j++) {
tmp = addresses[j];
addresses[j] = tmp2;
tmp2 = tmp;
}
addresses[i] = tmp2;
}
}
cacheAddresses(host, addresses, success);
if (!success && ex != null)
throw ex;
} finally {
updateLookupTable(host);
}
}
return addresses;
}
# step3
public native InetAddress[] lookupAllHostAddr(String hostname) throws UnknownHostException;
一步步跟踪后发现，底层是native方法，底层调用的是操作系统的getaddrinfo()方法。看来问题确实在这里。根据debug结果推断，getaddrinfo()方法根据hostname查询IP，先从本地hosts查询，没有找到再去局域网络中查找，这样导致了getLocalHost缓慢。
我以为故事到这里就结束了，随手改了下hostname，奇怪的事情发生了，getLocalHost()反应又变快了！
zhangweideMacBook-Pro:zhangwei root# hostname zhangweideMacBook-Pro.local2
问题很奇怪，百度一番也无果。打开mac电脑设置看看情况先。
这里有个置灰的.local，似乎不让你修改。但是使用hostname 查看本机的hostname是zhangweideMacBook-Pro.local，而且可以随意修改。没办法纠结这些了，进一步分析，每次返回都需要5秒左右的时间，看起来似乎是一个超时时间。使用scutil --dns查看本机dns解析情况：
zhangweideMacBook-Pro:zhangwei root# scutil --dns
DNS configuration
resolver #1
search domain[0] : xxxx-xxx.com(人工脱敏)
nameserver[0] : 10.134.130.61
nameserver[1] : 10.134.130.62
if_index : 9 (en0)
flags : Request A records
reach : 0x00000002 (Reachable)
resolver #2
domain : local
options : mdns
timeout : 5
flags : Request A records
reach : 0x00000000 (Not Reachable)
order : 300000
resolver #3
domain : 254.169.in-addr.arpa
options : mdns
timeout : 5
flags : Request A records
reach : 0x00000000 (Not Reachable)
order : 300200
resolver #4
domain : 8.e.f.ip6.arpa
options : mdns
timeout : 5
flags : Request A records
reach : 0x00000000 (Not Reachable)
order : 300400
resolver #5
domain : 9.e.f.ip6.arpa
options : mdns
timeout : 5
flags : Request A records
reach : 0x00000000 (Not Reachable)
order : 300600
resolver #6
domain : a.e.f.ip6.arpa
options : mdns
timeout : 5
flags : Request A records
reach : 0x00000000 (Not Reachable)
order : 300800
resolver #7
domain : b.e.f.ip6.arpa
options : mdns
timeout : 5
flags : Request A records
reach : 0x00000000 (Not Reachable)
order : 301000
DNS configuration (for scoped queries)
resolver #1
search domain[0] : xxxx-xxx.com(人工脱敏)
nameserver[0] : 10.1xx.1x0.61(人工脱敏)
nameserver[1] : 10.1xx.1x0.62(人工脱敏)
if_index : 9 (en0)
flags : Scoped, Request A records
reach : 0x00000002 (Reachable)
惊奇的发现这条记录，domain : local，timeout : 5，与之前发生的现象匹配上了。那么继续分析一下，是否是因为.local结尾的hostnane，走了mdns，对结果产生了影响。
推断结论
由此推论如果hostname改为非.local结尾，走内网DNS服务器解析IP，很快获取到了IP信息；否则通过MDNS查找，由于mDNS的工作方式，在整个网络中查询对名称有响应的人，这些查找可能会很慢，超过了超市时间5秒之后停止查询。
验证猜想
由于知识面有限，接下来只能通过谷歌的结果来佐证猜想，请读者见谅。
什么是.local
以.local结尾的网络设备主机名通常在私有网络中使用，在那里它们通过多播域名服务(mDNS)或本地域名系统(DNS)服务器进行解析。在同一网络上实现这两种方法可能会有问题。然而，由于计算机、打印机和其他实现零配置网络(zeroconf)的设备越来越普遍，通过单播DNS服务器解决这些名称的做法已经不受欢迎。
Multicast DNS
getaddrinfo may be slow on OS X #31665
结语
经过一番折腾，问题解决了，但是美中不足的是其中详细的原理摸的不是很透。平时要加强知识面的宽度，在遇到问题时，才有解决问题的方向。如果有了解问题根因的同学，希望不吝赐教，说说细节，惠普大众！
相关资料
列出一些比较关键的，有参考意义的资料。
搞懂 macOS 上的主机名/hostname/ComputerName
多播DNS服务器(MDNS)导致本地HTTP请求阻塞5秒钟问题的解决办法
Mac OS X slow connections - mdns 4-5 seconds - bonjour slow
什么是 mDNS 组播 DNS 多播 DNS
getaddrinfo may be slow on OS X
InetAddress.getLocalHost() slow to run (30+ seconds)
网友评论