Java類加載與鎖
本文寫作的靈感來自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進行監視及檢測,因此定位這類問題就不再需要掌握這么多技術才能完成了。