利用 Java dump 進行 JVM 故障診斷

Java dump 檔案的格式和內容

Java dump 通常是文字格式(.txt)，因此可以通過一般的文字編輯器進行閱讀，閱讀時需要注意段與行的格式：

段格式

為了便於大家的分析，Java dump 的每一段的開頭，都會用“-----”與上一段明顯的區分開來。而每一段的標題也會用“=====”作為標識，這樣我們就能夠很容易的找到每一段的開頭和標題部分（如清單 1）。

NULL --------------------------------
0SECTION TITLE subcomponent dump routine
NULL ===============================

行格式

Java dump 檔案中，每一行都包含一個標籤，這個標籤最多由 15 個字元組成（如清單2中所示）。其中第一位數字代表資訊的詳細級別（0，1，2，3，4），級別越高代表資訊越詳細；接下來的兩個字元是段標題的縮寫，比如，“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 所產生的 Java dump 的格式可能會稍有不同，但基本上都會包含以下幾個方面的內容：

• TITLE 資訊塊：描述 JAVA DUMP 產生的原因，時間以及檔案的路徑。
• GPINFO資訊塊：GPF 資訊。
• ENVINFO 資訊塊：系統執行時的環境及 JVM 啟動引數。
• MEMINFO 資訊塊：記憶體的使用情況和垃圾回收記錄。
• LOCKS 資訊塊：使用者監視器(Monitor)和系統監視器(Monitor)。
• THREADS資訊塊：所有 java 執行緒的狀態資訊和執行堆疊。
• CLASSES資訊塊：類載入資訊。

  利用 Java Dump 進行 JVM 故障診斷

  由於 Java dump 檔案包含的內容比較廣泛，因此 JVM 的很多問題都可以通過 java dump進行診斷。這些問題主要包括執行緒阻塞，CPU 使用率過高，JVM Crash，堆記憶體不足，和類裝載等問題。

  診斷執行緒阻塞問題

  執行緒阻塞是我們在 java 多執行緒程式設計中經常遇到的問題。由於對後端有限資源的爭用以及過度同步等問題，經常會發現 Java dump 中某個資源（鎖物件）下有太多的執行緒處於等待狀態，這時候我們通常需要從以下三個方面去診斷這個問題：

  • 這個鎖存在的目的是什麼？有沒有可能去掉這個鎖或者縮小這個鎖保護的範圍，從而減少執行緒等待問題發生的機率。
  • 有哪些執行緒需要用到這個鎖，有沒有可能改用其它更好的替代方案。
  • 當前哪個執行緒正在持有這個鎖，持有的時間是多長，有沒有可能縮短持有的時間。

  比執行緒阻塞更嚴重的是死鎖問題，當兩個以上的執行緒互相等待對方的鎖，從而形成一個環的時候，就會發生死鎖。關於如何使用 Java dump 診斷死鎖的問題，請參考 在 WebSphere Application Server V6.1 應用程式中跟蹤死鎖 一文，該文對此問題做了較為詳細的介紹。

  診斷 JVM Crash 問題

  JVM Crash 是我們所碰到的最棘手的問題之一，它對整個系統的影響是致命的，並且總是讓人防不勝防。導致 JVM 崩潰的原因有很多，通常都是一些底層的錯誤。比如 JVM 本身的 bug，錯誤的 JNI 呼叫，第三方原生模組（比如資料庫驅動程式）中的 bug 等。JVM崩潰的原因複雜，並且大多都難以重現，所以診斷起來有一定的難度。

  一般來說，JVM 崩潰的時候，系統一般會自動產生一個 Java dump 檔案（JVM 預設的設定引數就會觸發）。這個 Java dump 會幫我們記錄下 JVM 崩潰的原因，相關的資訊會記錄在 TITLE 資訊塊，GPINFO 資訊塊和 THREADS 資訊塊中。

  • TITLE 資訊塊：用於確認問題產生的原因，即是否是由於一些底層錯誤而導致 JVM Crash。
  • GPINFO 資訊塊：用於檢視問題的詳細資訊和問題定位。
  • THREADS資訊塊：用於瞭解問題執行緒的執行情況。

  下面我們通過一個具體的例子來介紹 JVM Crash 問題的診斷方法。TestJni 是一個簡單的 Java 應用，它通過 JNI 呼叫原生程式碼 CallJin.dll 中的 doSomeThing() 函式。

  
  清單 3. 在 TestJni 類中呼叫 CallJin.dll 中的函式
  

  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++ 實現程式碼
  

  #include /* * 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 函式。結果導致 JVM 發生了崩潰。

  在這段 C++ 程式碼中，整形指標 I 還沒有分配空間就被賦了值，這是一個非常嚴重的錯誤。當然 java 應用程式設計師並不知道這一點，並且在 java 應用程式中呼叫了 doSomeThing（） 這個 JNI 函式。結果導致 JVM 發生了崩潰。

  下面是 JVM 崩潰時，系統為我們生成的 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" 事件觸發的，GPF 是 General Protection Fault 的縮寫，表明應用程式發生了一般性保護錯誤，這種錯誤常常導致 JVM 突然崩潰。

  除了 "gpf" 之外，Java dump 還可能由如下事件觸發（清單 6）。

  
  清單 6. 常見 Java dump 觸發事件
  

  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 資訊塊，我們只能初步瞭解問題產生的原因，如果要進一步瞭解問題的詳細資訊，還要檢視 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 指明瞭發生問題的原生模組。 CallJni.dll 這個動態連線庫是我們自己的 JNI 程式碼，因此很容易發現問題的所在。在一個複雜的 java 執行環境下，很多時候異常是在第三方的程式碼庫中產生的，我們沒有辦法檢視原始碼中的問題，這時候只能通過檔名中的一些關鍵字來推測問題發生的位置，這些關鍵字包括（清單 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 RB = 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 模組發生問題，使用者可以使用 JITC_COMPILEOPT 變數的 SKIP 選項禁用對當前方法進行 JIT 編譯，然後再對系統的執行情況進行進一步的跟蹤。

  JITC_COMPILEOPT=SKIP{failingPackage/failingClass}{failingMethod}

  除此之外，檢視 THREADS 資訊塊中當前執行緒的執行堆疊也有助於我們對問題的診斷。從清單 9 我們可以看到 main 執行緒在執行 CallJni.doSomeThing 方法數的過程中發生了問題，據此我們可以返回原始碼中查詢相應的方法，進而確定問題的根源。

  
  清單 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 使用率過高可能是由於某些執行緒陷入了死迴圈或者執行了不適當的操作引起的，其診斷方法就是將這些執行緒找出來，修正問題或者進行程式碼優化。由於 Java Dump 中並沒有包含各執行緒的資源使用情況，因此我們需要結合其他的作業系統命令/工具（prstat、top、pslist 等等），將 CPU 使用率較高的執行緒對映到 Java Dump 中，並分析這些執行緒的狀態以及可能發生的問題。

  從下面這段 PSList 的輸出結果中我們可以看到 jvm 內部每個執行緒消耗的總的“使用者時間”和“核心時間”，比較幾次 PSList 的輸出結果，我們就能從中找出那些 CPU 使用時間顯著增加的執行緒，再將這些執行緒的 TID 對映到Java Dump中，進而檢視問題執行緒的詳細資訊。

  
  清單 10. PSList 的輸出結果
  

  pslist -d 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 利用率過高的問題時，我們不需要關心那些處於等待狀態的執行緒，因為執行緒處於等待狀態不需要消耗 CPU 資源。我們關注的重點應該是 THREADS 資訊塊中那些正在執行（state:R 狀態）的執行緒。很多時候為了分析執行緒狀態的一些變化，我們需要對比多個 Java Dump 檔案，看哪些執行緒狀態發生了變化，哪些一直在執行相同的函式，從而找出那些可疑的問題執行緒。

  診斷堆記憶體不足問題

  除了 Thread 相關的資訊外，Java Dump 還包含 Memory 和 GC 等方面的資訊，雖然這些資訊不像 Heap Dump 和 VerboseGC 那麼詳細，但對於一些比較簡單的問題定位還是很有幫助的。例如，下面的 Java dump 清單中，Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received 告訴我們問題是由於記憶體溢位引起的，並且從 MEMINFO 資訊塊中可以找到當前堆中的空間使用情況， 1ffa0 的剩餘空間說明系統的可用堆記憶體已經嚴重不足了，需要我們擴大堆記憶體的大小或者修改應用程式使其佔用更少的記憶體。

  
  清單 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 包衝突以及由類裝入引發的其他問題（例如 jdk 1.4 中的記憶體碎片問題） Java Dump 檔案的 Classes 資訊塊的格式如清單中示，這些資訊可以幫我們確定以下問題：

  • 當前系統中有哪些 Class 檔案被載入進來。
  • 確認某個 Class 是否被正確的 ClassLoader 所載入，即不同的 ClassLoader 之間是否有 Jar 包衝突。
  • 已經載入的 Class 的個數。在IBM Jre1.4中，我們可以參考系統中 Class 的個數來設定 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，下面是一些有可能讓你產生困惑的問題：

  為什麼發生 JVM Crash 時，JVM 沒有自動生成 Java dump 檔案？

  答：這種情況大多與系統的環境變數或者 JVM 啟動引數的設定有關，比如設定了 DISABLE_JAVADUMP=true，IBM_NOSIGHANDLER=true 等等，因此可以首先檢查系統設定和 JVM 啟動引數。當然也不排除因為一些不確定因素導致 JVM 無法產生 Java dump，雖然這種可能性比較小。

  JVM 在生成 Java dump 的同時也生成了 Heap dump，它們之間有沒有什麼聯絡？

  答：有，但是關係不大。因為 java dump 主要反映的是執行緒的執行狀態，而 Heap dump 則主要反映物件之間的引用關係，所以兩者之間沒有太大的聯絡。有時候我們可以通過鎖物件或者 Class 物件的起始地址找到它在 Heap dump 中的位置，但大多數時候這對故障診斷並沒有多大意義。

  為什麼有些 java dump 的鎖沒有 owner?

  答：並不是所有的鎖都被其它執行緒持有，有些鎖是用作主動等待的，比如 sleep() ，wait()，join() 等，這些鎖並沒有被其它執行緒佔用，被它阻塞的執行緒只是在等待通知，即 “Waiting to be notified”。從執行緒狀態上看，這些鎖一般都處於 “CW” 狀態。

  Java Dump 中的很多執行緒處於 state:CW 和 state:B 狀態，它們之間有何區別？

  答：兩者都處於等待狀態。不同是：

  CW - Condition Wait – 條件等待. 這種等待一般是執行緒主動等待或者正在進行某種 IO 操作，而並非等待其它執行緒釋放資源。比如 sleep() ，wait()，join() 等方法的呼叫。

  B – Blocked – 執行緒被阻塞，與條件等待不同，執行緒被阻塞一般不是執行緒主動進行的，而是由於當前執行緒需要的資源正在被其他執行緒佔用，因此不得不等待資源釋放以後才能繼續執行，例如 synchronized 程式碼塊。

  為什麼我在 PsList 裡看到的執行緒無法對映到 Java dump 中？

  答：由於很多作業系統工具和命令輸出的執行緒的 TID 都是十進位制的，對映到 Java dump 時首先要將其轉換為十六進位制數字，然後再到 Java dump 中查詢對應的 native ID。Java dump 中每個執行緒都有兩個ID, 一個是 java 執行緒的TID, 另一個是對應作業系統執行緒的 native ID。

  閱讀 Websphere Appliaction Server 產生的 Java dump 檔案有沒有什麼特別的技巧？

  答：對於 WAS 應用程式來說，執行緒資訊往往要比一般的應用程式複雜的多。記住一些常見的 ThreadName 可以幫助我們更好的理解應用程式的執行狀態，例如：

  執行緒名	執行緒資訊
  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)

  
  
  

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/14789789/viewspace-582735/，如需轉載，請註明出處，否則將追究法律責任。