對于大型 java 應用程序來(lái)說(shuō)，再精細的測試都難以堵住所有的漏洞，即便我們在測試階段進(jìn)行了大量卓有成效的工作，很多問(wèn)題還是會(huì )在生產(chǎn)環(huán)境下暴露出來(lái)，并且很難在測試環(huán)境中進(jìn)行重現。JVM 能夠記錄下問(wèn)題發(fā)生時(shí)系統的運行狀態(tài)并將其存儲在轉儲(dump)文件中，從而為我們分析和診斷問(wèn)題提供了重要的依據。常見(jiàn)的轉儲文件包括 Java Dump， Heap dump 和 System dump。這里我們主要介紹 Java dump 在 JVM 故障診斷中的應用。
Java dump，也叫做 Thread dump，是 JVM 故障診斷中最重要的轉儲文件之一。JVM 的許多問(wèn)題都可以使用這個(gè)文件進(jìn)行診斷，其中比較典型的包括線(xiàn)程阻塞，CPU 使用率過(guò)高，JVM Crash，堆內存不足，和類(lèi)裝載等問(wèn)題。作為一款輕量級（與 Heap dump 和 System dump 相比）的轉儲文件，Java dump 的確是我們診斷 JVM 問(wèn)題的首選。本文將系統的介紹使用 Java dump 進(jìn)行 JVM 故障診斷的方法和技巧，希望能夠為大家提供一些幫助。
  |
|
Java dump 通常是文本格式(.txt)，因此可以通過(guò)一般的文本編輯器進(jìn)行閱讀，閱讀時(shí)需要注意段與行的格式：
為了便于大家的分析，Java dump 的每一段的開(kāi)頭，都會(huì )用“-----”與上一段明顯的區分開(kāi)來(lái)。而每一段的標題也會(huì )用“=====”作為標識，這樣我們就能夠很容易的找到每一段的開(kāi)頭和標題部分（如清單 1）。
NULL -------------------------------- 0SECTION TITLE subcomponent dump routine NULL =============================== |
Java dump 文件中，每一行都包含一個(gè)標簽，這個(gè)標簽最多由 15 個(gè)字符組成（如清單2中所示）。其中第一位數字代表信息的詳細級別（0，1，2，3，4），級別越高代表信息越詳細；接下來(lái)的兩個(gè)字符是段標題的縮寫(xiě)，比如，“CI” 代表 “Command-line interpreter”，“CL” 代表 “Class loader”，“LK” 代表 “Locking”，“ST” 代表 “Storage”，“TI” 代表 “Title”，“XE” 代表 “Execution engine”等等；其余部分為信息的概述。
1TISIGINFO Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received |
不同版本的 JVM 所產(chǎn)生的 Java dump 的格式可能會(huì )稍有不同，但基本上都會(huì )包含以下幾個(gè)方面的內容：
 |
|
由于 Java dump 文件包含的內容比較廣泛，因此 JVM 的很多問(wèn)題都可以通過(guò) java dump進(jìn)行診斷。這些問(wèn)題主要包括線(xiàn)程阻塞，CPU 使用率過(guò)高，JVM Crash，堆內存不足，和類(lèi)裝載等問(wèn)題。
線(xiàn)程阻塞是我們在 java 多線(xiàn)程編程中經(jīng)常遇到的問(wèn)題。由于對后端有限資源的爭用以及過(guò)度同步等問(wèn)題，經(jīng)常會(huì )發(fā)現 Java dump 中某個(gè)資源（鎖對象）下有太多的線(xiàn)程處于等待狀態(tài)，這時(shí)候我們通常需要從以下三個(gè)方面去診斷這個(gè)問(wèn)題：
比線(xiàn)程阻塞更嚴重的是死鎖問(wèn)題，當兩個(gè)以上的線(xiàn)程互相等待對方的鎖，從而形成一個(gè)環(huán)的時(shí)候，就會(huì )發(fā)生死鎖。關(guān)于如何使用 Java dump 診斷死鎖的問(wèn)題，請參考 在 WebSphere Application Server V6.1 應用程序中跟蹤死鎖 一文，該文對此問(wèn)題做了較為詳細的介紹。
JVM Crash 是我們所碰到的最棘手的問(wèn)題之一，它對整個(gè)系統的影響是致命的，并且總是讓人防不勝防。導致 JVM 崩潰的原因有很多，通常都是一些底層的錯誤。比如 JVM 本身的 bug，錯誤的 JNI 調用，第三方原生模塊（比如數據庫驅動(dòng)程序）中的 bug 等。JVM崩潰的原因復雜，并且大多都難以重現，所以診斷起來(lái)有一定的難度。
一般來(lái)說(shuō)，JVM 崩潰的時(shí)候，系統一般會(huì )自動(dòng)產(chǎn)生一個(gè) Java dump 文件（JVM 默認的設置參數就會(huì )觸發(fā)）。這個(gè) Java dump 會(huì )幫我們記錄下 JVM 崩潰的原因，相關(guān)的信息會(huì )記錄在 TITLE 信息塊，GPINFO 信息塊和 THREADS 信息塊中。
下面我們通過(guò)一個(gè)具體的例子來(lái)介紹 JVM Crash 問(wèn)題的診斷方法。TestJni 是一個(gè)簡(jiǎn)單的 Java 應用，它通過(guò) JNI 調用本地代碼 CallJin.dll 中的 doSomeThing() 函數。
package test; public class TestJin { /** * @param args */ public static void main(String[] args) { // TODO Auto-generated method stub TestJin testObj = new TestJin(); testObj.work(); } public void work() { CallJni.doSomeThing(); } } package test; public class CallJni { static { System.loadLibrary("CallJni"); System.out.println("Dll Loaded"); } public native static void doSomeThing(); } |
CallJin.dll 是 C++ 編寫(xiě)得本地庫，其源代碼如清單 3 所示：
#include <com_test_CallJni.h> /* * Class: com_test_CallJni * Method: doSomeThing */ JNIEXPORT void JNICALL Java_test_CallJni_doSomeThing (JNIEnv *, jclass){ int *i; *i = 100; } |
在這段 C++ 代碼中，整形指針 I 還沒(méi)有分配空間就被賦了值，這是一個(gè)非常嚴重的錯誤。當然 java 應用程序員并不知道這一點(diǎn)，并且在 java 應用程序中調用了 doSomeThing（） 這個(gè) JNI 函數。結果導致 JVM 發(fā)生了崩潰。
在這段 C++ 代碼中，整形指針 I 還沒(méi)有分配空間就被賦了值，這是一個(gè)非常嚴重的錯誤。當然 java 應用程序員并不知道這一點(diǎn)，并且在 java 應用程序中調用了 doSomeThing（） 這個(gè) JNI 函數。結果導致 JVM 發(fā)生了崩潰。
下面是 JVM 崩潰時(shí)，系統為我們生成的 Java dump 文件的片斷。
NULL ---------------------------------------------- 0SECTION TITLE subcomponent dump routine NULL =============================== 1TISIGINFO Dump Event "gpf" (00002000) received 1TIDATETIME Date: 2008/11/12 at 20:45:24 1TIFILENAME Javacore filename: C:\eclipse\workspace\Serviceability\TestApps\SampleLeak\TestJin javacore.20081112.204522.5656.txt |
從 TITLE 信息塊中我們可以看到，這個(gè) java 是由一個(gè) "gpf" 事件觸發(fā)的，GPF 是 General Protection Fault 的縮寫(xiě)，表明應用程序發(fā)生了一般性保護錯誤，這種錯誤常常導致 JVM 突然崩潰。
除了 "gpf" 之外，Java dump 還可能由如下事件觸發(fā)（清單 6）。
user SIGQUIT signal (Ctrl-Brk on Windows, Ctrl-\ on Linux, Ctrl-V on z/OS) abort a controlled crash, as triggered by the abort() system call vmstart the VM has finished initialization vmstop the VM is about to shutdown load a new class has been loaded unload a classloader has been unloaded throw a Java exception has been thrown catch a Java exception has been caught uncaught a Java exception was not handled by the application thrstart a new thread has started thrstop an old thread has stopped blocked a thread is blocked entering a monitor fullgc garbage collection has started |
從 TITLE 信息塊，我們只能初步了解問(wèn)題產(chǎn)生的原因，如果要進(jìn)一步了解問(wèn)題的詳細信息，還要查看 GPINFO 信息塊（清單 7）：
NULL ---------------------------------------------- 0SECTION GPINFO subcomponent dump routine NULL ================================ 2XHOSLEVEL OS Level : Windows XP 5.1 build 2600 Service Pack 3 2XHCPUS Processors - 3XHCPUARCH Architecture : x86 3XHNUMCPUS How Many : 2 NULL 1XHEXCPCODE J9Generic_Signal_Number: 00000004 1XHEXCPCODE ExceptionCode: C0000005 1XHEXCPCODE ExceptionAddress: 412E136E 1XHEXCPCODE ContextFlags: 0001003F 1XHEXCPCODE Handler1: 7EFB04E0 1XHEXCPCODE Handler2: 7F057A80 1XHEXCPCODE InaccessibleAddress: CCCCCCCC NULL 1XHEXCPMODULE Module: C:\eclipse\workspace\Serviceability\TestApps\SampleLeak\TestJin\CallJni.dll 1XHEXCPMODULE Module_base_address: 412D0000 1XHEXCPMODULE Offset_in_DLL: 0001136E NULL 1XHFLAGS VM flags:00040000 NULL |
GPINFO 信息塊中我們可以找到問(wèn)題的異常代碼，ExceptionCode: C0000005 代表內存訪(fǎng)問(wèn)錯誤或者非法的內存操作。Module: C:\eclipse\workspace\Serviceability\TestApps\TestJin\CallJni.dll 指明了發(fā)生問(wèn)題的原生模塊。 CallJni.dll 這個(gè)動(dòng)態(tài)連接庫是我們自己的 JNI 代碼，因此很容易發(fā)現問(wèn)題的所在。在一個(gè)復雜的 java 運行環(huán)境下，很多時(shí)候異常是在第三方的代碼庫中產(chǎn)生的，我們沒(méi)有辦法查看源代碼中的問(wèn)題，這時(shí)候只能通過(guò)文件名中的一些關(guān)鍵字來(lái)推測問(wèn)題發(fā)生的位置，這些關(guān)鍵字包括（清單 8）：
GC = garbage collection/collector (how Java frees memory) JIT = just-in-time compiler, a feature of JVM JDBC = Java feature for database access ORB = object request broker, lower layer of app server JMS = java messaging service, feature of web server or add-on |
例如，Module: C:\JDK\IBM\java1.5.0\jre\bin\j9jit23.dll
說(shuō)明 JIT 模塊發(fā)生問(wèn)題，用戶(hù)可以使用 JITC_COMPILEOPT 變量的 SKIP 選項禁用對當前方法進(jìn)行 JIT 編譯，然后再對系統的運行情況進(jìn)行進(jìn)一步的跟蹤。
JITC_COMPILEOPT=SKIP{failingPackage/failingClass}{failingMethod}
除此之外，查看 THREADS 信息塊中當前線(xiàn)程的執行堆棧也有助于我們對問(wèn)題的診斷。從清單 9 我們可以看到 main 線(xiàn)程在執行 CallJni.doSomeThing 方法數的過(guò)程中發(fā)生了問(wèn)題，據此我們可以返回源代碼中查找相應的方法，進(jìn)而確定問(wèn)題的根源。
NULL ---------------------------------------------------- 0SECTION THREADS subcomponent dump routine NULL ================================= NULL 1XMCURTHDINFO Current Thread Details NULL ---------------------- 3XMTHREADINFO "main" (TID:0x408C7C00, sys_thread_t:0x00366278, state:R, native ID:0x000016CC) prio=5 4XESTACKTRACE at test/CallJni.doSomeThing(Native Method) 4XESTACKTRACE at test/TestJin.work(TestJin.java:16) 4XESTACKTRACE at test/TestJin.main(TestJin.java:11) NULL |
CPU 使用率過(guò)高可能是由于某些線(xiàn)程陷入了死循環(huán)或者執行了不適當的操作引起的，其診斷方法就是將這些線(xiàn)程找出來(lái)，修正問(wèn)題或者進(jìn)行代碼優(yōu)化。由于 Java Dump 中并沒(méi)有包含各線(xiàn)程的資源使用情況，因此我們需要結合其他的操作系統命令/工具（prstat、top、pslist 等等），將 CPU 使用率較高的線(xiàn)程映射到 Java Dump 中，并分析這些線(xiàn)程的狀態(tài)以及可能發(fā)生的問(wèn)題。
從下面這段 PSList 的輸出結果中我們可以看到 jvm 內部每個(gè)線(xiàn)程消耗的總的“用戶(hù)時(shí)間”和“內核時(shí)間”，比較幾次 PSList 的輸出結果，我們就能從中找出那些 CPU 使用時(shí)間顯著(zhù)增加的線(xiàn)程，再將這些線(xiàn)程的 TID 映射到Java Dump中，進(jìn)而查看問(wèn)題線(xiàn)程的詳細信息。
pslist -d <Java PID> Tid Pri Cswtch State User Time Kernel Time Elapsed Time 2908 8 2025 Wait:Executive 0:00:00.359 0:00:01.312 1:48:08.046 4344 15 157 Wait:UserReq 0:00:00.218 0:00:00.015 1:48:07.921 4836 15 415456 Wait:UserReq 0:00:00.000 0:00:00.000 1:48:07.921 2496 8 1 Wait:UserReq 0:00:00.000 0:00:00.000 1:48:07.796 4648 9 1 Wait:UserReq 0:00:00.000 0:00:00.000 1:48:07.796 3116 9 7 Wait:UserReq 0:00:00.000 0:00:00.000 1:48:07.796 5268 8 189 Wait:UserReq 0:00:00.015 0:00:00.000 1:48:07.796 5220 7 6991523 Running 1:47:42.031 0:00:01.218 1:48:05.593 3932 9 2 Wait:UserReq 0:00:00.000 0:00:00.000 1:48:05.125 |
與線(xiàn)程死鎖問(wèn)題不同，在分析 CPU 利用率過(guò)高的問(wèn)題時(shí)，我們不需要關(guān)心那些處于等待狀態(tài)的線(xiàn)程，因為線(xiàn)程處于等待狀態(tài)不需要消耗 CPU 資源。我們關(guān)注的重點(diǎn)應該是 THREADS 信息塊中那些正在運行（state:R 狀態(tài)）的線(xiàn)程。很多時(shí)候為了分析線(xiàn)程狀態(tài)的一些變化，我們需要對比多個(gè) Java Dump 文件，看哪些線(xiàn)程狀態(tài)發(fā)生了變化，哪些一直在執行相同的函數，從而找出那些可疑的問(wèn)題線(xiàn)程。
除了 Thread 相關(guān)的信息外，Java Dump 還包含 Memory 和 GC 等方面的信息，雖然這些信息不像 Heap Dump 和 VerboseGC 那么詳細，但對于一些比較簡(jiǎn)單的問(wèn)題定位還是很有幫助的。例如，下面的 Java dump 清單中，Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received 告訴我們問(wèn)題是由于內存溢出引起的，并且從 MEMINFO 信息塊中可以找到當前堆中的空間使用情況， 1ffa0 的剩余空間說(shuō)明系統的可用堆內存已經(jīng)嚴重不足了，需要我們擴大堆內存的大小或者修改應用程序使其占用更少的內存。
NULL ---------------------------------------------------- 0SECTION TITLE subcomponent dump routine NULL =============================== 1TISIGINFO Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received 1TIDATETIME Date: 2008/04/20 at 19:13:50 1TIFILENAME Javacore filename: c:\Serviceability\AppServer\profiles\AppSrv01\javacore.20080420.185326.948.txt NULL ---------------------------------------------------- 0SECTION MEMINFO subcomponent dump routine NULL ================================= 1STHEAPFREE Bytes of Heap Space Free: 1ffa0 1STHEAPALLOC Bytes of Heap Space Allocated: 40000000 |
常見(jiàn)的類(lèi)加載問(wèn)題包括： ClassNotFoundException，Jar 包沖突以及由類(lèi)裝入引發(fā)的其他問(wèn)題（例如 jdk 1.4 中的內存碎片問(wèn)題） Java Dump 文件的 Classes 信息塊的格式如清單中示，這些信息可以幫我們確定以下問(wèn)題：
NULL --------------------------------------------------------- 0SECTION CLASSES subcomponent dump routine NULL ================================= 1CLTEXTCLLOS Classloader summaries 1CLTEXTCLLSS 12345678: 1=primordial,2=extension,3=shareable,4=middleware,5=system, 6=trusted,7=application,8=delegating 2CLTEXTCLLOADER p---st-- Loader *System*(0x008DA0B0) 3CLNMBRLOADEDLIB Number of loaded libraries 3 3CLNMBRLOADEDCL Number of loaded classes 347 2CLTEXTCLLOADER -x--st-- Loader sun/misc/Launcher$ExtClassLoader(0x008E5E38), Parent *none*(0x00000000) 3CLNMBRLOADEDLIB Number of loaded libraries 0 3CLNMBRLOADEDCL Number of loaded classes 0 2CLTEXTCLLOADER -----ta- Loader sun/misc/Launcher$AppClassLoader(0x008EF3E0), Parentsun/misc/Launcher$ExtClassLoader(0x008E5E38) 3CLNMBRLOADEDLIB Number of loaded libraries 0 3CLNMBRLOADEDCL Number of loaded classes 2 1CLTEXTCLLIB ClassLoader loaded libraries 2CLTEXTCLLIB Loader *System*(0x008DA0B0) 3CLTEXTLIB C:\JDK\IBM\java1.5.0\jre\bin\java 3CLTEXTLIB C:\JDK\IBM\java1.5.0\jre\bin\jclscar_23 3CLTEXTLIB C:\JDK\IBM\java1.5.0\jre\bin\zip 1CLTEXTCLLOD ClassLoader loaded classes 2CLTEXTCLLOAD Loader *System*(0x008DA0B0) 3CLTEXTCLASS java/io/ByteArrayOutputStream(0x40D40098) 3CLTEXTCLASS sun/nio/ByteBuffered(0x40D40330) 3CLTEXTCLASS java/lang/ref/PhantomReference(0x40DB9360) 3CLTEXTCLASS sun/misc/Cleaner(0x40DB94A8) |
|
|
關(guān)于 Java dump，下面是一些有可能讓你產(chǎn)生困惑的問(wèn)題：
為什么發(fā)生 JVM Crash 時(shí)，JVM 沒(méi)有自動(dòng)生成 Java dump 文件？
答：這種情況大多與系統的環(huán)境變量或者 JVM 啟動(dòng)參數的設置有關(guān)，比如設置了 DISABLE_JAVADUMP=true，IBM_NOSIGHANDLER=true 等等，因此可以首先檢查系統設置和 JVM 啟動(dòng)參數。當然也不排除因為一些不確定因素導致 JVM 無(wú)法產(chǎn)生 Java dump，雖然這種可能性比較小。
JVM 在生成 Java dump 的同時(shí)也生成了 Heap dump，它們之間有沒(méi)有什么聯(lián)系？
答：有，但是關(guān)系不大。因為 java dump 主要反映的是線(xiàn)程的運行狀態(tài)，而 Heap dump 則主要反映對象之間的引用關(guān)系，所以?xún)烧咧g沒(méi)有太大的聯(lián)系。有時(shí)候我們可以通過(guò)鎖對象或者 Class 對象的起始地址找到它在 Heap dump 中的位置，但大多數時(shí)候這對故障診斷并沒(méi)有多大意義。
為什么有些 java dump 的鎖沒(méi)有 owner?
答：并不是所有的鎖都被其它線(xiàn)程持有，有些鎖是用作主動(dòng)等待的，比如 sleep() ，wait()，join() 等，這些鎖并沒(méi)有被其它線(xiàn)程占用，被它阻塞的線(xiàn)程只是在等待通知，即 “Waiting to be notified”。從線(xiàn)程狀態(tài)上看，這些鎖一般都處于 “CW” 狀態(tài)。
Java Dump 中的很多線(xiàn)程處于 state:CW 和 state:B 狀態(tài)，它們之間有何區別？
答：兩者都處于等待狀態(tài)。不同是：
CW - Condition Wait – 條件等待. 這種等待一般是線(xiàn)程主動(dòng)等待或者正在進(jìn)行某種 IO 操作，而并非等待其它線(xiàn)程釋放資源。比如 sleep() ，wait()，join() 等方法的調用。
B – Blocked – 線(xiàn)程被阻塞，與條件等待不同，線(xiàn)程被阻塞一般不是線(xiàn)程主動(dòng)進(jìn)行的，而是由于當前線(xiàn)程需要的資源正在被其他線(xiàn)程占用，因此不得不等待資源釋放以后才能繼續執行，例如 synchronized 代碼塊。
為什么我在 PsList 里看到的線(xiàn)程無(wú)法映射到 Java dump 中？
答：由于很多操作系統工具和命令輸出的線(xiàn)程的 TID 都是十進(jìn)制的，映射到 Java dump 時(shí)首先要將其轉換為十六進(jìn)制數字，然后再到 Java dump 中查找對應的 native ID。Java dump 中每個(gè)線(xiàn)程都有兩個(gè)ID, 一個(gè)是 java 線(xiàn)程的TID, 另一個(gè)是對應操作系統線(xiàn)程的 native ID。
閱讀 Websphere Appliaction Server 產(chǎn)生的 Java dump 文件有沒(méi)有什么特別的技巧？
答：對于 WAS 應用程序來(lái)說(shuō)，線(xiàn)程信息往往要比一般的應用程序復雜的多。記住一些常見(jiàn)的 ThreadName 可以幫助我們更好的理解應用程序的運行狀態(tài)，例如：
| 線(xiàn)程名 | 線(xiàn)程信息 |
| Web Container: # | WAS web container * |
| Alarm Thread # | handles timer processing |
| Session.Transports.Threads:### | servlet threads for processing HTTP requests |
| ORB.thread.pool:### | ORB thread (ORB data) |
| P=437206:O=0: StandardRT=19027:LocalPort=9001:RemoteHost=hostname.ibm.com:RemoteP | an ORB thread for receiving an EJB request or other ORB request |
| Thread-## | JVM thread (default name) |
聯(lián)系客服
