0
点赞
收藏
分享

微信扫一扫

45 一个InetAddress.getLocalHost导致SpringBoot启动延迟问题排查


前言 

启动 spring-boot 的相关项目的时候, 会打印如下日志

Connected to the target VM, address: '127.0.0.1:62630', transport: 'socket'

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.1.RELEASE)

但是 在我的机器上面, 似乎是 打印这个 banner 之前, 还要等待 好几秒, 但是 在其他同事的机器上面, 好像是 没有这个问题, main 启动了之后, 基本上马上就打印 banner
然后 花了一些时间, 跟踪了一下 相关代码的开销

我这边的环境为 : jdk1.8 + spring5.1.3 + spring-boot2.1.1 

 

 

问题的排查

1. SpringApplication.run, 通过代码调试, 整理了一些 开销较为明显的地方

1. printBanner 之前的开销
        LoggingApplicationListener - new ApplicationPid() 通过 jmx 获取 MXBeanName 有一定的开销
            Slf4JLoggingSystem.loadConfiguration 还会有一次 new ApplicationPid()
            解析 logback 的配置文件, 有一些开销
    2. SpringApplication.prepareContext, 里面 logStartupInfo, 还会 new ApplicationPid()
        InetAddress.getLocalHost() 也是一个比较大的开销, 以上的 通过 jmx 获取 MXBeanName 的主要开销, 也是这个, 才看到 ..
    3. SpringApplication.prepareContext, 里面 load, 解析bean

然后 在 InetAddress.getLocalHost 里面打了一个断点, 发现这里 host 为 "master.local"[其中 master 为我的 hostname], 然后 nameService 解析 host 对应的 ip 的时候开销比较大
解析出来的 ip 为 内网ip : 172.31.174.6, 可能是去询 dns server 开销比较大

然后 通过调整 /etc/hosts 来避免了 查询 dns server 的开销, 调整方式如下

## 1st column : ip
## 2nd column : domain name
## 3rd column : domain name alias
# master.local, 映射
127.0.0.1       loopLocal      master.local

2. 查询 dns

master:finance jerry$ nslookup master.local
Server:       61.139.2.69
Address:   61.139.2.69#53

** server can't find master.local: NXDOMAIN

61.139.2.69 → 四川省成都市 电信DNS服务器

 

查询 dns 的开销 

dnsSpent.sh 的脚本为以上 nslookup 查询前后加了一个当前时间输出  

master:finance jerry$ ./dnsSpent.sh
Mon Oct 28 20:32:25 CST 2019
Server:       180.76.76.76
Address:   180.76.76.76#53

** server can't find master.local: NXDOMAIN

Mon Oct 28 20:32:27 CST 2019

nslookup master.local 的时间开销, 这里面是 可以感觉明显的停顿, 在程序里面的停顿更加明显, 差不多是 5s 左右

 

3. 通过 jmx 获取 MXBeanName 有一定的开销
最开始 我以为是 jmx 交互的问题, 但是 似乎是不是这个问题, evaluate 了一下, getPid(), 没有 太大的时间开销,, 这几个比较重的开销都指向了 InetAddress.getLocalHost

VMManagementImpl. getVmId
  public String getVmId() {
    int var1 = this.getProcessId();
    String var2 = "localhost";

    try {
      var2 = InetAddress.getLocalHost().getHostName();
    } catch (UnknownHostException var4) {
    }

    return var1 + "@" + var2;
  }

 

 

4. InetAddress 的小测试 

在 InetAddress.getLocalhost 上面打了两个断点输出[一个断点是真正去查询ip的地方, 另外一个地方是走缓存的地方], 来观察 调整 /etc/hosts 的前后不同

4.1 调整之前, 的 InetAddress.getLocalHost 的访问情况, InetAddress 的缓存是 5s, 每次都没有使用到

         可以看出, 这里 InetAddress.getLocalhost 总共是被调用了 5 次, 均没有走缓存 

Connected to the target VM, address: '127.0.0.1:63926', transport: 'socket'
 getAddressInvoked
 getAddressInvoked
 getAddressInvoked

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.1.RELEASE)

 getAddressInvoked
 getAddressInvoked

4.2 调整之前, 的 InetAddress.getLocalHost 的 dns 查询的开销, 为 5s 左右 

Mon Oct 28 21:10:01 CST 2019
Mon Oct 28 21:10:06 CST 2019
Mon Oct 28 21:10:07 CST 2019
Mon Oct 28 21:10:12 CST 2019
Mon Oct 28 21:10:12 CST 2019
Mon Oct 28 21:10:17 CST 2019

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.1.RELEASE)

Mon Oct 28 21:10:17 CST 2019
Mon Oct 28 21:10:22 CST 2019
Mon Oct 28 21:10:22 CST 2019
Mon Oct 28 21:10:27 CST 2019

4.3 调整之后, 的 InetAddress.getLocalHost 的访问情况

        可以看到 后面的几次 调用当前方法都走的是 cachedLocalhost, 所以只有一次开销, 而且相比于上面, 这里查询 hosts 开销要小得多  

Connected to the target VM, address: '127.0.0.1:63900', transport: 'socket'
 getAddressInvoked
 cache hitted
 cache hitted

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.1.RELEASE)

 cache hitted
 cache hitted

 

 

5. 项目启动的开销

5.1 调整之前的项目启动时间开销

# 77s
Mon Oct 28 21:25:30 CST 2019
Mon Oct 28 21:26:47 GMT 2019

# 69s
Tue Oct 29 16:34:40 CST 2019
Tue Oct 29 16:35:49 GMT 2019

5.2 调整之后的项目启动时间开销

# 55s
Mon Oct 28 21:20:20 CST 2019
Mon Oct 28 21:21:15 GMT 2019

# 40s 
Tue Oct 29 16:37:36 CST 2019
Tue Oct 29 16:38:16 GMT 2019

又一次测试差距为 22 s, 理论上来说 应该是 至少 25s, 之余其中的细节, 这里就不去深究了

 

最后

这个问题还是挺神奇的, 在我们同事的机器上面, 也没有配置 /etc/hosts, 但是 启动还是挺快, 不过没看 他的 dns server, 可能是有配置 

如果你也有这样的现象, 不妨以此为切入点 调试 一下 

 

呵呵, 后来在网上也看到了一些和我这里场景类似的文章, 应该是由同一个问题导致的 

1. springboot程序启动慢-未配置hostname


2. 解决Mac机器spring-boot项目启动慢的问题

https://www.jianshu.com/p/0cae67f668ce

3. 解决 idea 运行 Spring Boot 项目启动慢的问题


 

 

完 

 

 

举报

相关推荐

0 条评论