InetAddress.getLocalHost() 执行很慢?
背景介绍
某次在 SpringBoot 2.2.0 项目的一个配置类中引入了这么一行代码:
导致项目启动明显变慢。同时报出了相关的警告信息:
2022-10-03 23:32:01.806 [TID: N/A] WARN [main] o.s.b.StartupInfoLogger - InetAddress.getLocalHost().getHostName() took 5007 milliseconds to respond. Please verify your network configuration (macOS machines may need to add entries to /etc/hosts).

根据报警信息可知,只要获取主机信息的耗时超过了阈值 HOST_NAME_RESOLVE_THRESHOLD=200ms,就会提示这个信息。很明显,我们的耗时已经超过 5s。同时,如果为 Mac 系统,还会贴心地提示在/etc/hosts 文件中配置本地 dns。
我们看看目前 hosts 文件中的配置:
根据网上各种文章的提示,我们将主机名追加进去,变成这样:
其中,xiaoxi666s-MacBook-Pro.local 就是我的主机名。
注:更改 hosts 文件内容后,可使用命令
sudo killall -HUP mDNSResponder
刷新 dns,无需重启电脑。
再次启动 SpringBoot 程序,我们发现警告信息消失了,也就意味着主机信息获取的耗时不会超过 200ms。
那么问题来了,这背后究竟是什么机制,让我们一探究竟。
使用 Wireshark 抓包看看
由于我们要获取自己的主机信息,这里走的是本地回环网络,因此选中 Loopback 网络接口:

先把 hosts 改回去,抓一下 hosts 文件改动前的网络包:

按照时间顺序,可以将抓到的网络包分为三段,每段中又可以分为 Ipv4 和 Ipv6 两种地址的请求。
其中用到的协议是 mdns,也即多播 dns(Multicast DNS),它主要实现了在没有传统 dns 服务器的情况下使局域网内的主机实现相互发现和通信,使用的端口为 5353,遵从 dns 协议。随便点开一个请求查看详情便可以得到验证:

另外,网络包中的目标 ip 224.0.0.251 是 Mac 的官方 mdns 查询地址,详情可参见https://github.com/apple-oss-distributions/mDNSResponder/tree/mDNSResponder-1096.100.3
实际多次测试发现,主机信息都在第三次发送网络包后返回(阻塞在 InetAddress.getLocalHost() 方法上。参见下图,阻塞在第 18 行,5 秒后才跳到第 19 行)。从上图的时间线看,约在 8 秒时返回,整体耗时与上面报出的 5007ms 吻合。再仔细观察网络包,看起来是连续发了三次请求。第一次在 3.1s 时发出,第二次在 4.1s 时发出,第三次在 7.1s 时发出,重试间隔分别为 1s 和 3s,看起来像是一种指数退避的重试。当然,8 秒左右时返回结果,就对应第一次请求,剩下两次请求的结果被忽略了。

我们再看看 hosts 中添加主机信息后,对应的网络包:

啊噢,这次没有抓到任何相关的网络包,猜测直接读取了 hosts 文件拿到了主机名,根本没走网络。
那么,这段获取主机信息的程序究竟是怎么运作的呢,hosts 文件中没有添加主机名时,时间都耗在了哪里?
看看对应的源码
源码比较好找,参见下图:

我们再次把 hosts 中的主机名去掉,并使用 Arthas 工具的 trace
命令看看链路耗时:

提示:如果抓包时出现 No class or method is affected 的报错,可查看对应的日志文件进行排查,见下图:


可知需要提升下权限,执行命令 options unsafe true
后,再尝试使用 trace
命令即可。
但好巧不巧,居然抓不到调用链?那我们试试用 Arthas 的 profiler
命令生成一下火焰图吧:

可以看到很多编译相关的,我们忽略之,只把主机信息获取的那部分放大:

哦吼,时间基本都耗在了 InetAddress.getAddressesFromNameService 这行代码:

往下追溯,可知时间基本耗在了 nameService.lookupAllHostAddr:


再往下就到了 native 方法:

于是我们到 jdk 源码中看看(我用的 jdk8):

接下来需要找 getaddrinfo 的实现,由于不知道具体的实现源码在哪里,于是我们在网上找一下 Linux 系统的源码作为参考,参见:https://codebrowser.dev/glibc/glibc/sysdeps/posix/getaddrinfo.c.html#getaddrinfo

内部的具体实现基本都是和操作系统交互,我们简单瞄几眼就行。另外,在 getaddrinfo 源码中没有找到火焰图给出的调用链,我们暂时不再深入。

目前,我们知道了方法 getaddrinfo 会被调用,因此简单写段 c 程序复现一下:
其中的 hostname 即为主机名 xiaoxi666s-MacBook-Pro.local,我们在 Java 项目中调试时也可以看到,上面的程序中直接将其写死。
运行程序,对比下 hosts 文件中 没有添加主机名 和 添加主机名后的输出结果:
可以看到,当 hosts 文件中没有添加主机名时,根本找不到对应的网络地址(因为 dns 中也没有解析到),添加之后就能返回对应的 ip 127.0.0.1 了。
这里有几个地方需要注意:
即使 hosts 文件中添加主机名,标准 Linux 的 getaddrinfo 方法执行时,也会有接近两秒的耗时,但我们在 Java 代码中运行时却只有几十毫秒;
前文我们使用 Wireshark 抓包时提到,mdns 查询时存在重试机制,但标准 Linux 的 getaddrinfo 方法中没有看到对应的代码;
前面提到的 5 秒返回结果,其实不是返回结果,而是超时了。但标准 Linux 的 getaddrinfo 方法中没有看到对应的超时控制代码;
因此,我们可以大胆猜测 MaxOS 系统对标准 Linux 代码进行了修改,加了本地缓存、重试、超时等机制。
接着上面的第 3 点,回到 Java 项目调试一下,看看为什么超时了还能返回结果。
当 hosts 文件中没有添加主机名时,会返回本机所有的 ip 地址:

当 hosts 文件中添加主机名后,只会返回配置的 127.0.01 的 ip 地址:

其中,当 hosts 文件中没有添加主机名时,getaddrinfo 调用返回错误码,此时 jdk 会转而调用 lookupIfLocalhost 方法,它内部调用了操作系统的 getifaddrs 方法,以获取本机所有 ip 地址:


对应的源码可以参考https://codebrowser.dev/glibc/glibc/sysdeps/unix/sysv/linux/ifaddrs.c.html。
总结
本文以 Java 中获取主机名慢的场景为契机,使用多种技术手段研究背后的原理,包括使用 Wireshark 抓包,使用 Arthas 工具定位到性能瓶颈,再转到 jdk 中查看对应的 native 方法实现,由于没找到最底层调用链路源码,转而参照标准 Linux 的相关源码,简单复现了上述场景。
进一步地,由于没找到最底层调用链路源码,我们根据现象猜测的本地缓存、重试、超时等机制没有得到验证,有兴趣的同学可以进一步研究探索。
参考文章
版权声明: 本文为 InfoQ 作者【xiaoxi666】的原创文章。
原文链接:【http://xie.infoq.cn/article/2bb1eb21f80a56c0a43046fa2】。
本文遵守【CC-BY 4.0】协议,转载请保留原文出处及本版权声明。
评论