本文写作的灵感来自Pierre-Hugues Charbonneau的 为什么加载不存在的类会影响系统性能 一文。这让我想起了之前的一次调试经历,当时也遇到了类似的问题,只不过表现略有不同。
出问题的应用程序是Yet Another Webapp,不管什么脏活累活它都接。直到干趴下为止。它这的症状是,终端用户抱怨说应用很慢,经常超时。我从日志文件中倒没发现什么异常,不过能够看出用户体验确实是下降得很厉害。
这个BUG特别恶心——它是属于那种你知道肯定能重现,但是又不确定它什么时候出现的BUG。这样的情况大概一周会出现一到两次。因此我让负责这个应用的同事在发现异常时立即运行一个诊断的脚本。这脚本其实没啥特别的——它主要是收集了几次thread dump以及一些额外的操作系统层面的参数。只能祈祷伟大的Debug大神能够帮帮我了。
这次的祷告貌似灵验了。接下来的这几天我就一直盯着像下面这样的打满了跟踪信息的thread dump文件:
"Thread-96" #106 prio=5 os_prio=31 tid=0x00007fc9b283b800 nid=0x11b03 waiting for monitor entry [0x0000000130133000] java.lang.Thread.State: BLOCKED (on object monitor) at java.lang.ClassLoader.loadClass(ClassLoader.java:404) - waiting to lock <0x00000006c022e608> (a java.lang.Object) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at com.sun.org.apache.xerces.internal.utils.ObjectFactory.findProviderClass(ObjectFactory.java:209) at com.sun.org.apache.xerces.internal.utils.ObjectFactory.newInstance(ObjectFactory.java:157) at com.sun.org.apache.xerces.internal.utils.ObjectFactory.newInstance(ObjectFactory.java:143) at com.sun.org.apache.xerces.internal.impl.dv.DTDDVFactory.getInstance(DTDDVFactory.java:64) at com.sun.org.apache.xerces.internal.impl.dv.DTDDVFactory.getInstance(DTDDVFactory.java:49) at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.(XML11Configuration.java:578) at com.sun.org.apache.xerces.internal.parsers.XIncludeAwareParserConfiguration.(XIncludeAwareParserConfiguration.java:130) at com.sun.org.apache.xerces.internal.parsers.XIncludeAwareParserConfiguration.(XIncludeAwareParserConfiguration.java:91) at com.sun.org.apache.xerces.internal.parsers.DOMParser.(DOMParser.java:144) at com.sun.org.apache.xerces.internal.parsers.DOMParser.(DOMParser.java:128) at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.(DocumentBuilderImpl.java:138) at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl.newDocumentBuilder(DocumentBuilderFactoryImpl.java:76) at ClassloadingLock$Worker.run(ClassloadingLock.java:10)
大多数应用线程都被锁住了,在等待同一个监视器释放掉。有意思的是,这个监视器是类加载时的一个同步访问产生的。这种情况可不太常见,尤其是应用程序已经初始化完毕并经过了好几天的预热之后才出现这样的锁升级(lock escalation)的问题。
深入代码后便发现了问题所在。原来每周都会执行一次某个定时任务,它会启动一系列的后台线程。这些线程会提取数据并进行转换然后存储到数据仓库中。转换规则是配置在XML里的,这些线程会通过javax.xml.parsers.DocumentBuilder来加载这些规则。出于某种原因,每个线程在进行转换的时候都会独立地去加载这个XML文件。
从thread dump中可以看出,这么做会导致每次转换时都会加载这个XML服务提供类。
at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at com.sun.org.apache.xerces.internal.utils.ObjectFactory.findProviderClass(ObjectFactory.java:209)
如果你看下java.lang.ClassLoader.loadClass()的源码,你会发现在检查类是否已经加载了还是要到文件系统中从类文件中去加载之前会做一次同步,这样当多个线程同时访问这个同步块的时候,便会出现锁升级的问题:
protected Class loadClass(String name, boolean resolve) throws ClassNotFoundException { synchronized (getClassLoadingLock(name)) { // First, check if the class has already been loaded Class c = findLoadedClass(name); // ... cut for brevity ... }
在重现这个问题的时候,我构建了下面这个小的测试用例来让大家更好地理解下这个锁的问题。这个示例启动了100个线程来加载javax.xml.parsers.DocumentBuilder这个类:
package eu.plumbr.demo; import javax.xml.parsers.DocumentBuilder; import javax.xml.parsers.DocumentBuilderFactory; import javax.xml.parsers.ParserConfigurationException; public class ClassloadingLock { static class Worker extends Thread { @Override public void run() { while (true) { try { DocumentBuilder b = DocumentBuilderFactory.newInstance() .newDocumentBuilder(); } catch (Exception e) {// Do not do this at home, log all // exceptions } } } } public static void main(String[] args) throws Exception { for (int i = 0; i < 100; i++) { new Worker().start(); } } }
在运行上述这段代码的时候做一下thread dump,或者用 jvisualvm 进行下可视化,你会发现这些线程会不停地等待这个监视器:
这个故事告诉了我们什么呢?查找这个性能问题的其实不应该这么麻烦。我们开发的这些工具提供了 许多更便利的手段来对你的JVM进行监视及检测 ,因此定位这类问题就不再需要掌握这么多技术才能完成了。