[实践] 深入调查 - Java(1.8.0_45) Applet加载缓慢问题

介绍
最近（201506），碰到一个关于在java 8_45下加载applet非常缓慢的问题。而java 1.7（如 1.7.0_51)没有这个问题。

本文章将介绍该问题调查过程与结论，包括此间涉及的相关细节。
基本上涉及以下方面的知识
1) JVM CPU profiling - JVisualVM
2) DNS

3) Java 8 关于Applet的更改

 

实际工作中的问题可能是比较复杂的。如本文中的问题，它不仅是简单的检查cpu使用，还涉及DNS解析、新版JDK引入的对既有行为的改变等。忽然想起一句话：没有人会像教科书上讲的那样生病。

 

有道云笔记链接： http://note.youdao.com/share/?id=1e426753c042c0b420be2ccd2259dad7&type=note

根本原因

1）Applet在加载第一个图片(toolkit.getImage)时，出现SocketPermission。此过程时间长度不定，有时很快（1秒内），有时10秒+.

此过程为crossdomain检查是，JDK(1.8.0_45)调用了DNS解析(参考下面章节中的调用栈)。此 解析被JDK8自身新引入的RIA permission变化所拦截，导致无法解析。异常信息 如：java.security.AccessControlException: access denied ("java.net.SocketPermission" "your_domain_name.com" "resolve") 。 

2）在加载接下来的其他图片(还是toolkit.getImage)时，每个图片5秒钟时间，共30+个图片。作为客户，算是等的花儿已谢了。

是由于JDK调用了DNS反向解析(从ip 查询域名)- java.net.Inet64AddressImpl.getHostByAddr。此解析失败。

第N(N>=2)此加载图片，JDK的调用分支改变为调用DNS反向解析，而非1）中的正向解析，可能是记住了上次的permission检查失败的状态，此不同可以通过比较上面1）中AccessControlException的调用栈，和 本2）中的cpu profiling结果得到。

注意：虽然加载图片出现了异常或者timeout，图片最终还是成功加载。具体原因也将在后面所描述。

关于java 8引入的Permision,请参考

http://docs.oracle.com/javase/8/docs/technotes/guides/deploy/whatsnew_deployment.html

http://stackoverflow.com/questions/23189650/new-java-security-accesscontrolexception-in-java-8

 

解决方案

暂时没有最终完美解决方案

 

1 将所有图片文件写入一个zip包，applet读取的时候缓存整个zip包

那么，加载很多图片文件不会引起多次5秒timeout。因为只有一次获取zip文件的过程。

 

或者

2 将域名加入本地hosts文件

 

或者

3 更改本地java.policy,加入socketpermission，允许resolve

 

接下来将详细解释如何发现的这个问题，其过程比较曲折。


步骤
1. 重现问题
本机安装1.8.0_45, 访问测试环境的applet。重现成功！ 注意：测试环境的url也使用域名，而非ip。域名解析是使用公司内部的域名服务器。

 

同时，还通过Eclipse ，以调用application的形式试图重现，发现其在非sandbox环境下，没有问题！

 

2.检查java console log

感谢写图片加载的同事，每个图片加载前和加载成功分别打印了log。由此成功发现了直接原因 - 即加载每个图片都花费了5秒钟之间。

目前可以定位到具体代码行。

 

大概看了一下，只有两行实际调用的程序,如下：

print 'begin loading'
URL URL = this.getClass().getResource(imageFileName);
iconImg = Toolkit.getDefaultToolkit().getImage(URL);
pring 'load done' 

都是jdk内部类，使用方法也没看到什么不妥的地方，而且只有jdk8有问题，jdk7没问题，此中必有隐情(元芳,你怎么看).

 

3. 明确到底是上面哪行代码(getResource, OR getImage )出了问题， by JVisualVM Sampler

 同时确定线程名称，对接下来的profiling JDK的时候，快速定位有帮助。否则jdk的profiling结果老长老长。

 

JVisualVM的操作步骤很简单

1) 网页打开applet 2) visualvm挂载applet 3) 在load图片之前，点击 Sampler -> CPU 4) 等图片load结束以后，点击 'Snapshot'保存当前profiling结果。Snapshot可以作为单独文件保存，使用jvisualvm随时查看。

备注：为什么使用Sampler，而非Profilger标签。因为Sampler简单实用。关于 Sampler标签与Profiler标签区别，可以参考http://stackoverflow.com/questions/12130107 /difference-between-sampling-and-profiling-in-jvisualvm

 

检查也很简单，上图

此图明确的告诉我们，getImage花费了146秒。它就是真凶，但为什么呢？由于再往里的调用均为JDK内部的实现，我们需要更改JVisualVM的设置，才能捕捉到。下一个步骤就做这个事情。


 
 

 

4. 检查JVM里面到底在做什么, by JVisualVM Sampler

 JVisualVM的操作步骤与上面一样，除了在点击 ‘CPU' 进行profiling之前，设定Settings 为 只检查 java.*. javax.*, sun.* 等等(这是java 8 visualvm 默认的).

 

检查结果如下（好深的调用! 要尽量避免如此深的调用栈。）

看来是在进行DNS反向解析的时候，5秒钟TimeOut了（这个5秒是另外一个同事告诉我的，他调查过Java7的一个相关问题)。

备注：为啥调用URL.hashCode就扯出这么长的一段调用呢。URL应该设计成不可变类。我们写程序要注意，尽量多用。快速看了一下java.net.URL类,只有StreamHandler可以修改它，其他情况下，它是不可变的。继续上图

 

 

 

 

备注：其实在上面检查步骤的同时，我通过google查询了java 8的关于applet的release note，以及其他人是否碰到过加载applet缓慢的问题。

--java 8在applet permission方面，增加了一些限制(https://docs.oracle.com/javase/8/docs/technotes /guides/deploy/whatsnew_deployment.html)，我粗粗看了一下，认为与此无关（我错了！）。想起一篇文章《Tomcat7连接数异常导致超时问题的排查》，文中作者碰到问题，应用了很多很厉害的troubleshooting过程，最后定位到根本原因。但是他最后也发现其实log中已经有有偶发的StackOverflowError。我猜测也是log太多，这行log没有得到及时发现。否则可能更快的找到问题。

 

--有人在加载文件(jar in jar)时，加载缓慢(http://stackoverflow.com/questions/28504943/java-sound- dramatically-slower-after-jvm-8-update)。我们的applet不是这个情况，也排除了。

此处，我想说明的是，要从内向外(profiler)，和从外向内(java 8 release note)双向调查。不要拘泥于profiling。一头扎进profiling，可能会使你迷失方向。

 

5. 下面着手如何解决这个问题，此过程中才真正调查清楚了其根本原因

[写最简单的applet来重现，以方便实验如何解决该问题解决]

写了一个最简单的applet（只有加载3张图片），部署在测试环境上。其Console log清晰极了。由此我才注意到SocketPermissin失败的问题。

而且发现了之前没有注意到的东西

1) 只有加载第一个图片时，才抛出此异常。 Production环境也是这样的，但是由于product console log冗长无比，略过了。

备注：仔细检查log中的每个异常/Error. 它比你想象的还重要。

java.security.AccessControlException: access denied ("java.net.SocketPermission" "your_domain_name.com" "resolve")

2) Java 7_51 与 java 8_45的console log有如下不同

Java 8中赋予jar文件ULRPermission，而Java7中赋予SocketPermission.

Java 8

security: Grant connect perm for https://your_domain_name/your.jar : java.security.Permissions@1839786 (

 ("java.net.URLPermission" "https://your_domain_name:443" "*:*")

 ("java.net.URLPermission" "https://your_domain_name:443/-" "*:*")

)

Java 7

security: Grant connect perm for https://your_domain_name/your.jar : java.security.Permissions@628e1 (
 ("java.net.SocketPermission" "your_domain_name" "connect,accept,resolve")
)

[重新回到原因调查，关注permission]

进而，我认真的调查了关于Permission的问题。阅读了Java8中关于Perssion的bug list(google 所有上面那个异常，就会搜索出).以及Java8 Release note中关于Permission的描述。如下两个link非常有帮助

http://docs.oracle.com/javase/8/docs/technotes/guides/deploy/whatsnew_deployment.html

http://stackoverflow.com/questions/23189650/new-java-security-accesscontrolexception-in-java-8

略加分析，得到如下关于根本原因的结论：

1）在加载第一个图片(toolkit.getImage())时，JDK(1.8.0_45)调用意外的调用 了DNS解析(参考下面章节中的调用栈)。而此解析被JDK8自身新引入的RIA permission变化所拦截，导致无法解析。异常信息 如：java.security.AccessControlException: access denied ("java.net.SocketPermission" "your_domain_name.com" "resolve") 。 此过程时间长度不定，有时很快（1秒内），有时10秒+.

2）在加载接下来的其他图片时，JDK记住了上次的permission检 查失败(原因未明，但与sun.plugin2.applet.SecurityManager.checkConnectionHelper有关)，而 改变了调用分支，最终调用了 DNS反向解析(从ip 查询域名)- java.net.Inet64AddressImpl.getHostByAddr。此解析失败，有5秒钟的time out时间。
每个图片5秒钟，共30+个图片，共花了150秒左右。作为客户，算是等的花儿已谢了。

通过更改本地的java.policy文件，此缓慢以及Exception都搞定。也验证了此调查的正确性。

permission java.net.SocketPermission "your_domain_name", "resolve";

注 意:resolve是域名解析相关的” The action "resolve" refers to host/ip name service lookups.The "resolve" action is implied when any of the other actions are present.“ --http://docs.oracle.com/javase/7/docs/api/java/net/SocketPermission.html

通过将域名加入本地hosts文件也可以解决这个问题（已验证)

因为通过本地hosts解析域名，不需要建立socket！

这是一个很有意思的事情。因为java在拦截resovle的时候，好像只是在建立socket之前做了拦截。而读取本体hosts文件作为resolve/域名解析的第一次尝试，并没有被拦截。留给充满好奇心的你去探究 :)

 

[深入:为啥JDK7没问题]

如上所述，JDK7中允许socketpermission,所以木有问题！

 

[深入:JDK7的调用栈啥样的]

TODO

很遗憾，我没有搞定。我很想比较一下JDK7 与 8 的调用栈区别，但是无法搞定7的调用栈。

1. 使用Sampler无法捕捉到getImage时间。肯定是因为调用太快，而Sampler的调用间隔相对太长。

2. 使用Profilter的instrument方式，也没有得到。暂时不知道为啥

3. 试图使用HPROF，在JRE中增加参数-agentlib:hprof=cpu=times,file=D:/tmp/cpu_times.txt,depth=30

为了得到每个调用方法的时间，结果applet加载都不行。看来HPROF与applet配合有问题哦。

HPROF，一个挺好用的JDK工具，http://docs.oracle.com/javase/7/docs/technotes/samples/hprof.html 

 

[深入:JDK(1.8.0_45)为什调用DNS解析？JDK7调用了吗？]

调 用DNS解析是因为 geyImage(url). url形式如： http://your_domain_name/abc/your_image.jpg. JDK(1.8.0_45)内部实现中，for some reason,要试图解析your_domain_name

根据我的实验，JDK7 与 JDK8（更改过java.policy后），都没有连接DNS服务器. how:在load第一个图片前Thread.sleep(30*1000). 加载wiresharp监听与DNS服务器的网络包。我也尝试了，在Thread.sleep过程中，清空了DNS缓存 ipconfig/flushdns.

note:此处我暂时无法解释为什么最终没有连接DNS服务器，可能使用了内部已有的哪些缓存。如果你有兴趣，可以进一步调查--20150612.

 

[深入：为什么第一次解析以后不存下来，后面每次重新解析一次导致了每个5秒的延时？]

因为：第一次压根就没成功，以后任意一次也都没有成功！

不管怎样，临时解决方案出来了，虽然很Ugly。把域名加到客户本地的hosts文件。客户是不会同意的，但技术上是可行的(已验证)

[深入：图片到底加载成功了没？为什么？]

TO BE ADDED

YES, 程序中检查返回image是否为null，不为null则打印getImage成功。每个图片(including 1st image)都打印了getImage成功。看来load 1st图片的exception在某个步骤中捕捉打印控制台后，并没有影响返回结果。

[深入： applet如何通过URL（http://your_domain_name/a.jar!/a.image.jpg)加载该文件，实际上其就在jar内部]

TO BE ADDED -

其并不会真的通过URL中的domain name去远端取文件。

本问题之所以调用了DNS解析，是因为调用栈中，某一个步骤要使用hashcode。在计算hashcode时，一步一步深入调用(URL.getHostName)引起的与DNS解析。

 

 

[深入：反向解析时，5秒钟的TIMEOUT到底等什么呢，为什么]

TO BE ADDED

1) 快速的看了一下jdk源码(opensdk),没有理出头绪来。

2) 如何通过profiler或者snapshot，或者dump，或者实时monitor，来检查某次jdk调用时到底传递了哪些值呢？

由于Eclipse环境的debug，并不能还原applet(sandbox)在浏览器中真实情况。

 

此问题试一下在家庭网络中访问该地址，看看是否还有5秒的timeout。因为家庭网路环境简单，没有防火墙或者代理服务器。

但是由于伟大的长城阻止了我进一步探究的能力。