利用 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 发生了崩溃。

下面是 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 文件能够帮咱们更快的找到解决问题的方向。