級別： 初級
隋 鵬飛 (suipf@cn.ibm.com), 軟件工程師, IBM
伍 亦方 (wuyifang@cn.ibm.com), 軟件工程師, IBM
2009 年 3 月 11 日
本文將向讀者介紹利用 Java dump 診斷 JVM Crash 和 CPU 饑餓等問題的方法和技巧，以便使用戶更加全面的了解 Java dump 在故障診斷過程中的作用。
 |
|
更多關于 Java dump 進行 JVM 故障診斷的內容，請參考：
- 在 WAS V6.1 應用程序中跟蹤死鎖：本文講述了如何使用 WAS V6.1 中的線程轉儲工具了解您的系統(tǒng)環(huán)境，檢查是否發(fā)生死鎖以及提取信息來幫助避免或解決自己應用程序的死鎖情況。
本文對上面的文章做了進一步的補充，介紹了如何利用 Java dump 診斷 JVM Crash 和 CPU 饑餓等問題的方法和技巧。
|
|
引言
對于大型 java 應用程序來說，再精細的測試都難以堵住所有的漏洞，即便我們在測試階段進行了大量卓有成效的工作，很多問題還是會在生產(chǎn)環(huán)境下暴露出來，并且很難在測試環(huán)境中進行重現(xiàn)。JVM 能夠記錄下問題發(fā)生時系統(tǒng)的運行狀態(tài)并將其存儲在轉儲(dump)文件中，從而為我們分析和診斷問題提供了重要的依據(jù)。常見的轉儲文件包括 Java Dump， Heap dump 和 System dump。這里我們主要介紹 Java dump 在 JVM 故障診斷中的應用。
Java dump，也叫做 Thread dump，是 JVM 故障診斷中最重要的轉儲文件之一。JVM 的許多問題都可以使用這個文件進行診斷，其中比較典型的包括線程阻塞，CPU 使用率過高，JVM Crash，堆內存不足，和類裝載等問題。作為一款輕量級（與 Heap dump 和 System dump 相比）的轉儲文件，Java dump 的確是我們診斷 JVM 問題的首選。本文將系統(tǒng)的介紹使用 Java dump 進行 JVM 故障診斷的方法和技巧，希望能夠為大家提供一些幫助。
Java dump 文件的格式和內容
Java dump 通常是文本格式(.txt)，因此可以通過一般的文本編輯器進行閱讀，閱讀時需要注意段與行的格式：
段格式
為了便于大家的分析，Java dump 的每一段的開頭，都會用“-----”與上一段明顯的區(qū)分開來。而每一段的標題也會用“=====”作為標識，這樣我們就能夠很容易的找到每一段的開頭和標題部分（如清單 1）。
清單 1. Java dump 段標題示例
NULL --------------------------------
0SECTION TITLE subcomponent dump routine
NULL ===============================
|
行格式
Java dump 文件中，每一行都包含一個標簽，這個標簽最多由 15 個字符組成（如清單2中所示）。其中第一位數(shù)字代表信息的詳細級別（0，1，2，3，4），級別越高代表信息越詳細；接下來的兩個字符是段標題的縮寫，比如，“CI” 代表 “Command-line interpreter”，“CL” 代表 “Class loader”，“LK” 代表 “Locking”，“ST” 代表 “Storage”，“TI” 代表 “Title”，“XE” 代表 “Execution engine”等等；其余部分為信息的概述。
清單 2. Java dump 行標簽和內容示例
1TISIGINFO Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received
|
不同版本的 JVM 所產(chǎn)生的 Java dump 的格式可能會稍有不同，但基本上都會包含以下幾個方面的內容：
- TITLE 信息塊：描述 JAVA DUMP 產(chǎn)生的原因，時間以及文件的路徑。
- GPINFO信息塊：GPF 信息。
- ENVINFO 信息塊：系統(tǒng)運行時的環(huán)境及 JVM 啟動參數(shù)。
- MEMINFO 信息塊：內存的使用情況和垃圾回收記錄。
- LOCKS 信息塊：用戶監(jiān)視器(Monitor)和系統(tǒng)監(jiān)視器(Monitor)。
- THREADS信息塊：所有 java 線程的狀態(tài)信息和執(zhí)行堆棧。
- CLASSES信息塊：類加載信息。
利用 Java Dump 進行 JVM 故障診斷
由于 Java dump 文件包含的內容比較廣泛，因此 JVM 的很多問題都可以通過 java dump進行診斷。這些問題主要包括線程阻塞，CPU 使用率過高，JVM Crash，堆內存不足，和類裝載等問題。
診斷線程阻塞問題
線程阻塞是我們在 java 多線程編程中經(jīng)常遇到的問題。由于對后端有限資源的爭用以及過度同步等問題，經(jīng)常會發(fā)現(xiàn) Java dump 中某個資源（鎖對象）下有太多的線程處于等待狀態(tài)，這時候我們通常需要從以下三個方面去診斷這個問題：
- 這個鎖存在的目的是什么？有沒有可能去掉這個鎖或者縮小這個鎖保護的范圍，從而減少線程等待問題發(fā)生的幾率。
- 有哪些線程需要用到這個鎖，有沒有可能改用其它更好的替代方案。
- 當前哪個線程正在持有這個鎖，持有的時間是多長，有沒有可能縮短持有的時間。
比線程阻塞更嚴重的是死鎖問題，當兩個以上的線程互相等待對方的鎖，從而形成一個環(huán)的時候，就會發(fā)生死鎖。關于如何使用 Java dump 診斷死鎖的問題，請參考 在 WebSphere Application Server V6.1 應用程序中跟蹤死鎖 一文，該文對此問題做了較為詳細的介紹。
診斷 JVM Crash 問題
JVM Crash 是我們所碰到的最棘手的問題之一，它對整個系統(tǒng)的影響是致命的，并且總是讓人防不勝防。導致 JVM 崩潰的原因有很多，通常都是一些底層的錯誤。比如 JVM 本身的 bug，錯誤的 JNI 調用，第三方原生模塊（比如數(shù)據(jù)庫驅動程序）中的 bug 等。JVM崩潰的原因復雜，并且大多都難以重現(xiàn)，所以診斷起來有一定的難度。
一般來說，JVM 崩潰的時候，系統(tǒng)一般會自動產(chǎn)生一個 Java dump 文件（JVM 默認的設置參數(shù)就會觸發(fā)）。這個 Java dump 會幫我們記錄下 JVM 崩潰的原因，相關的信息會記錄在 TITLE 信息塊，GPINFO 信息塊和 THREADS 信息塊中。
- TITLE 信息塊：用于確認問題產(chǎn)生的原因，即是否是由于一些底層錯誤而導致 JVM Crash。
- GPINFO 信息塊：用于查看問題的詳細信息和問題定位。
- THREADS信息塊：用于了解問題線程的運行情況。
下面我們通過一個具體的例子來介紹 JVM Crash 問題的診斷方法。TestJni 是一個簡單的 Java 應用，它通過 JNI 調用本地代碼 CallJin.dll 中的 doSomeThing() 函數(shù)。
清單 3. 在 TestJni 類中調用 CallJin.dll 中的函數(shù)
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++ 編寫得本地庫，其源代碼如清單 3 所示：
清單 4. CallJni.dll 的 C++ 實現(xiàn)代碼
#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 還沒有分配空間就被賦了值，這是一個非常嚴重的錯誤。當然 java 應用程序員并不知道這一點，并且在 java 應用程序中調用了 doSomeThing（） 這個 JNI 函數(shù)。結果導致 JVM 發(fā)生了崩潰。
在這段 C++ 代碼中，整形指針 I 還沒有分配空間就被賦了值，這是一個非常嚴重的錯誤。當然 java 應用程序員并不知道這一點，并且在 java 應用程序中調用了 doSomeThing（） 這個 JNI 函數(shù)。結果導致 JVM 發(fā)生了崩潰。
下面是 JVM 崩潰時，系統(tǒng)為我們生成的 Java dump 文件的片斷。
清單5. 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 信息塊中我們可以看到，這個 java 是由一個 "gpf" 事件觸發(fā)的，GPF 是 General Protection Fault 的縮寫，表明應用程序發(fā)生了一般性保護錯誤，這種錯誤常常導致 JVM 突然崩潰。
除了 "gpf" 之外，Java dump 還可能由如下事件觸發(fā)（清單 6）。
清單 6. 常見 Java dump 觸發(fā)事件
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 信息塊，我們只能初步了解問題產(chǎn)生的原因，如果要進一步了解問題的詳細信息，還要查看 GPINFO 信息塊（清單 7）：
清單7. GPINFO 信息塊
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 信息塊中我們可以找到問題的異常代碼，ExceptionCode: C0000005 代表內存訪問錯誤或者非法的內存操作。Module: C:\eclipse\workspace\Serviceability\TestApps\TestJin\CallJni.dll 指明了發(fā)生問題的原生模塊。 CallJni.dll 這個動態(tài)連接庫是我們自己的 JNI 代碼，因此很容易發(fā)現(xiàn)問題的所在。在一個復雜的 java 運行環(huán)境下，很多時候異常是在第三方的代碼庫中產(chǎn)生的，我們沒有辦法查看源代碼中的問題，這時候只能通過文件名中的一些關鍵字來推測問題發(fā)生的位置，這些關鍵字包括（清單 8）：
清單 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
說明 JIT 模塊發(fā)生問題，用戶可以使用 JITC_COMPILEOPT 變量的 SKIP 選項禁用對當前方法進行 JIT 編譯，然后再對系統(tǒng)的運行情況進行進一步的跟蹤。
JITC_COMPILEOPT=SKIP{failingPackage/failingClass}{failingMethod}
除此之外，查看 THREADS 信息塊中當前線程的執(zhí)行堆棧也有助于我們對問題的診斷。從清單 9 我們可以看到 main 線程在執(zhí)行 CallJni.doSomeThing 方法數(shù)的過程中發(fā)生了問題，據(jù)此我們可以返回源代碼中查找相應的方法，進而確定問題的根源。
清單 9. Threads 信息塊
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 利用率過高問題
CPU 使用率過高可能是由于某些線程陷入了死循環(huán)或者執(zhí)行了不適當?shù)牟僮饕鸬模湓\斷方法就是將這些線程找出來，修正問題或者進行代碼優(yōu)化。由于 Java Dump 中并沒有包含各線程的資源使用情況，因此我們需要結合其他的操作系統(tǒng)命令/工具（prstat、top、pslist 等等），將 CPU 使用率較高的線程映射到 Java Dump 中，并分析這些線程的狀態(tài)以及可能發(fā)生的問題。
從下面這段 PSList 的輸出結果中我們可以看到 jvm 內部每個線程消耗的總的“用戶時間”和“內核時間”，比較幾次 PSList 的輸出結果，我們就能從中找出那些 CPU 使用時間顯著增加的線程，再將這些線程的 TID 映射到Java Dump中，進而查看問題線程的詳細信息。
清單 10. PSList 的輸出結果
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
|
與線程死鎖問題不同，在分析 CPU 利用率過高的問題時，我們不需要關心那些處于等待狀態(tài)的線程，因為線程處于等待狀態(tài)不需要消耗 CPU 資源。我們關注的重點應該是 THREADS 信息塊中那些正在運行（state:R 狀態(tài)）的線程。很多時候為了分析線程狀態(tài)的一些變化，我們需要對比多個 Java Dump 文件，看哪些線程狀態(tài)發(fā)生了變化，哪些一直在執(zhí)行相同的函數(shù)，從而找出那些可疑的問題線程。
診斷堆內存不足問題
除了 Thread 相關的信息外，Java Dump 還包含 Memory 和 GC 等方面的信息，雖然這些信息不像 Heap Dump 和 VerboseGC 那么詳細，但對于一些比較簡單的問題定位還是很有幫助的。例如，下面的 Java dump 清單中，Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received 告訴我們問題是由于內存溢出引起的，并且從 MEMINFO 信息塊中可以找到當前堆中的空間使用情況， 1ffa0 的剩余空間說明系統(tǒng)的可用堆內存已經(jīng)嚴重不足了，需要我們擴大堆內存的大小或者修改應用程序使其占用更少的內存。
清單 11. MEMINFO 信息塊
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
|
類加載問題
常見的類加載問題包括： ClassNotFoundException，Jar 包沖突以及由類裝入引發(fā)的其他問題（例如 jdk 1.4 中的內存碎片問題） Java Dump 文件的 Classes 信息塊的格式如清單中示，這些信息可以幫我們確定以下問題：
- 當前系統(tǒng)中有哪些 Class 文件被加載進來。
- 確認某個 Class 是否被正確的 ClassLoader 所加載，即不同的 ClassLoader 之間是否有 Jar 包沖突。
- 已經(jīng)加載的 Class 的個數(shù)。在IBM Jre1.4中，我們可以參考系統(tǒng)中 Class 的個數(shù)來設置 KCluster 的大小。
清單 12. CLASSES 信息塊
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)
|
|
|
常見問題
關于 Java dump，下面是一些有可能讓你產(chǎn)生困惑的問題：
為什么發(fā)生 JVM Crash 時，JVM 沒有自動生成 Java dump 文件？
答：這種情況大多與系統(tǒng)的環(huán)境變量或者 JVM 啟動參數(shù)的設置有關，比如設置了 DISABLE_JAVADUMP=true，IBM_NOSIGHANDLER=true 等等，因此可以首先檢查系統(tǒng)設置和 JVM 啟動參數(shù)。當然也不排除因為一些不確定因素導致 JVM 無法產(chǎn)生 Java dump，雖然這種可能性比較小。
JVM 在生成 Java dump 的同時也生成了 Heap dump，它們之間有沒有什么聯(lián)系？
答：有，但是關系不大。因為 java dump 主要反映的是線程的運行狀態(tài)，而 Heap dump 則主要反映對象之間的引用關系，所以兩者之間沒有太大的聯(lián)系。有時候我們可以通過鎖對象或者 Class 對象的起始地址找到它在 Heap dump 中的位置，但大多數(shù)時候這對故障診斷并沒有多大意義。
為什么有些 java dump 的鎖沒有 owner?
答：并不是所有的鎖都被其它線程持有，有些鎖是用作主動等待的，比如 sleep() ，wait()，join() 等，這些鎖并沒有被其它線程占用，被它阻塞的線程只是在等待通知，即 “Waiting to be notified”。從線程狀態(tài)上看，這些鎖一般都處于 “CW” 狀態(tài)。
Java Dump 中的很多線程處于 state:CW 和 state:B 狀態(tài)，它們之間有何區(qū)別？
答：兩者都處于等待狀態(tài)。不同是：
CW - Condition Wait – 條件等待. 這種等待一般是線程主動等待或者正在進行某種 IO 操作，而并非等待其它線程釋放資源。比如 sleep() ，wait()，join() 等方法的調用。
B – Blocked – 線程被阻塞，與條件等待不同，線程被阻塞一般不是線程主動進行的，而是由于當前線程需要的資源正在被其他線程占用，因此不得不等待資源釋放以后才能繼續(xù)執(zhí)行，例如 synchronized 代碼塊。
為什么我在 PsList 里看到的線程無法映射到 Java dump 中？
答：由于很多操作系統(tǒng)工具和命令輸出的線程的 TID 都是十進制的，映射到 Java dump 時首先要將其轉換為十六進制數(shù)字，然后再到 Java dump 中查找對應的 native ID。Java dump 中每個線程都有兩個ID, 一個是 java 線程的TID, 另一個是對應操作系統(tǒng)線程的 native ID。
閱讀 Websphere Appliaction Server 產(chǎn)生的 Java dump 文件有沒有什么特別的技巧？
答：對于 WAS 應用程序來說，線程信息往往要比一般的應用程序復雜的多。記住一些常見的 ThreadName 可以幫助我們更好的理解應用程序的運行狀態(tài)，例如：
| 線程名 |
線程信息 |
| 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) |
結束語
本文比較全面的介紹了 Java dump 在 JVM 故障診斷過程中的作用。正像你所看到的，Java dump 文件主要幫我們解決與線程相關的各種問題，但同時它還為我們提供了很多其它有用的信息（比如 JVM Crash），在某些情況下，這些信息對于我們至關重要，所以充分的利用 Java dump 文件可以幫我們更快的找到解決問題的方向。
參考資料
學習
獲得產(chǎn)品和技術