原新浪博客的内容转到新博客中
http://blog.sina.com.cn/s/blog_65415e870102wtu9.html
背景和现象
环境
想着时髦一把,也响应公司号召软碍件都升级一把:
1.thinkpad换成了mac(OS:macOS Sierra)
2.jdk从1.6升到1.8,目前在用的版本是jdk 1.8.0_131
3.开发工具也从eclipse升级到intellij idea.
现象
原来在windows+jdk1.6环境下应用启动虽然也慢,但是一般在4分钟内肯定是可以完成的。可是现在发现在新环境里启动需要花10+分钟,实在忍受不了。对于有强迫症的我必须要找到原因。
但是同一套代码,周边同事都是4分钟内启动完成,只有我本地启动超过10分钟。
排查问题
于是开始各种找原因,可是这次软硬件都升级了,不清楚是哪方面的原因造成的。
开始始怀疑intellij idea
第一次真正用intellij idean, 对于出现问题很容易怀疑是新事务引入导致的。刚开始简短的时间怀疑过是不是由intellij idea引起的,但是很快放弃,感觉不应该。
开始怀疑是否是jvm内存调置不合理
提到慢,很自然想到是性能问题,jvm调优等。怀疑是否是jmv内存设置不合理,导致启动慢。
先是通过-xms -xmx调整jvm参数,通过在启动参数中增加堆内存,没发现有明显的效果。然后再通过-XX:+PrintGCDetails增加打印日志的,从日志中发现启动过程中触发了4次full gc,并且出现allocate failur分配内存失败的提示,感觉是内存设置不合理,于是多次通过-xms -xmx调整内存,后来未出现full gc和allocate failur的提示。
但是启动时间的优化上还是没有明显效果(相对于10+分钟,full gc优化只有几秒)
怀疑电脑网络的问题
再次分析启动日志,系统用到的很多中间件、注册"调用远程rpc服务"、以及连接zk的时候特别耗时,有几个rpc服务注册都需要20s。
因为同一套代码,周边的同事都正常,于是怀疑我电脑的网络的问题。
于是ping对应的rpc的对应的域名,响应时间正常。
无果放弃.
查看线程堆栈信息
理论上同一套代码,在线上和其它同事上运行没有问题,一直没有怀疑过是代码或者线程的问题。
但是还是试一试的态度,看一下线程堆栈是否能看出什么问题。通过jvisualvm在启动过程中不断dump 线程堆栈。
不看不知道,一看真看出问题了,原来有好几个线程处于blocked的状态,并且都是在这个位置。
查看源码
从源中看总共分5步
第1步,获取本地的hostname;
第2步,判断hostname是不是localhost,如果是localhost直接解析;
第3步,查看是否需要走缓存,计算"当前时间"与"上次查询到结果的缓存"时间差不是不是在5s内,如果是直接从缓存中读取;注意now变量是在第3步获取了当前系统时间。
第4步,如果不走缓存,则调用dns解析ip。这一步比较花时间(我本机调试花了好几秒);
第5步,如果第4步解析正常,则将当前dns解析结果缓存在本地。
但是这里特别注意,这里写入最后缓存的时间是在第3步拿的系统时间(now变量是在第3步时获取的),而第4步比较耗费时间(24s),所以放到本地缓存时,纪律的缓存时间已经过去24秒了。
所以一般来说下次进来判断,基本上都会超过5s, 不会走缓存。
为了验证缓存基本上生效,我在本地写了一个Demo,连续两次调用InetAddress.getLocalHost(),两次返回的时间都是5+s,显示第二次没有走缓存。
原因总结和解决办法
原因分析
对于企业级应用,有很多rpc的调用,以及分布式协调组件zookeeper的调用。
出于服务治理的需要,对于Rpc调用需要服务端和客户端在启动过程把自己注册登记到注册中心去。rpc注册登记时会调用jdk的InetAddress.getLocalHost()方法获取本机地址信息。但是这个过程会费时(每次调用需要5+s),并且这个方法还是用synchronized进行了同步,并行整成了串行,假如系统有100个地方调用此方法,在此就要消耗500s.
从jdk源码中看是有做缓存,但是由于dns解析很耗时,导致缓存达到效果,造成了这次悲剧。
解决方法
经过各种网络查询,网友给的解决方案是在本地host里做两个host映射绑定,本机的hostname就不走dns解析了。本地hostname不需要走网络解析,达到更快的解析速度,让缓存生效,提高速度。
在本地把本机对应的hostname增加映射到本地ip的host绑定。
结果
经过以上绑定之后,以上demo测试的结果是"连续两次调用InetAddress.getLocalHost()"的时间大缩短,第一次是9毫秒,第二次是0毫秒(走了缓存)
再次启动应用,应用的启动时间也从原来10+分钟,加快到现在启动只需要1分钟多一点点。
心情瞬间舒畅很多了!。
jdk bug还是macOS的bug?
网上有人说是jdk1.8版本的bug, 据说已经有人上报给jdk官方。open jdk据说无此问题。
也有人说此问题jdk1.8在mac最新版本的系统(macO Sierra)上才出现此种现象,我本地的系统是macOS Sierra 10.12.5 本人未验证过其它环境。之所以我同事们没有出现此问题,是因为我周边的同事macOS没有升级到最新版。