利用 Java dump 進行 JVM 故障診斷

時間  2019-11-07
標籤 利用 java dump 進行 jvm 故障 診斷 欄目 Java 简体版
原文   原文鏈接

引言

對於大型 java 應用程序來講，再精細的測試都難以堵住全部的漏洞，即使咱們在測試階段進行了大量卓有成效的工做，不少問題仍是會在生產環境下暴露出來，而且很難在測試環境中進行重現。JVM 可以記錄下問題發生時系統的運行狀態並將其存儲在轉儲(dump)文件中，從而爲咱們分析和診斷問題提供了重要的依據。常見的轉儲文件包括 Java Dump， Heap dump 和 System dump。這裏咱們主要介紹 Java dump 在 JVM 故障診斷中的應用。html

Java dump，也叫作 Thread dump，是 JVM 故障診斷中最重要的轉儲文件之一。JVM 的許多問題均可以使用這個文件進行診斷，其中比較典型的包括線程阻塞，CPU 使用率太高，JVM Crash，堆內存不足，和類裝載等問題。做爲一款輕量級（與 Heap dump 和 System dump 相比）的轉儲文件，Java dump 的確是咱們診斷 JVM 問題的首選。本文將系統的介紹使用 Java dump 進行 JVM 故障診斷的方法和技巧，但願可以爲你們提供一些幫助。java

回頁首程序員

Java dump 文件的格式和內容

Java dump 一般是文本格式(.txt)，所以能夠經過通常的文本編輯器進行閱讀，閱讀時須要注意段與行的格式：web

段格式

爲了便於你們的分析，Java dump 的每一段的開頭，都會用「-----」與上一段明顯的區分開來。而每一段的標題也會用「=====」做爲標識，這樣咱們就可以很容易的找到每一段的開頭和標題部分（如清單 1）。數據庫

清單 1. Java dump 段標題示例
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」等等；其他部分爲信息的概述。編程

清單 2. Java dump 行標籤和內容示例
1TISIGINFO Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" received

不一樣版本的 JVM 所產生的 Java dump 的格式可能會稍有不一樣，但基本上都會包含如下幾個方面的內容：後端

  • TITLE 信息塊：描述 JAVA DUMP 產生的緣由，時間以及文件的路徑。多線程

  • GPINFO信息塊：GPF 信息。app

  • ENVINFO 信息塊：系統運行時的環境及 JVM 啓動參數。eclipse

  • 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 <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 函數。結果致使 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
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 模塊發生問題，用戶可使用 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 <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 利用率太高的問題時，咱們不須要關心那些處於等待狀態的線程，由於線程處於等待狀態不須要消耗 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)

回頁首

結束語

本文比較全面的介紹了 Java dump 在 JVM 故障診斷過程當中的做用。正像你所看到的，Java dump 文件主要幫咱們解決與線程相關的各類問題，但同時它還爲咱們提供了不少其它有用的信息（好比 JVM Crash），在某些狀況下，這些信息對於咱們相當重要，因此充分的利用 Java dump 文件能夠幫咱們更快的找到解決問題的方向。

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程