利用 Java dump 进行 JVM 故障诊断
ystar 2011-01-11
转自：http://jimmyleeee.blog.163.com/blog/static/930961820091183527621/?fromdm&isFromSearchEngine=yes
引言
对于大型 java 应用程序来说，再精细的测试都难以堵住所有的漏洞，即便我们在测试阶段进行了大量卓有成效的工作，很多问题还是会在生产环境下暴露出来，并且很难在测试环境中进行重现。JVM 能够记录下问题发生时系统的运行状态并将其存储在转储(dump)文件中，从而为我们分析和诊断问题提供了重要的依据。常见的转储文件包括 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 问题的首选。本文将系统的介绍使用 Java dump 进行 JVM 故障诊断的方法和技巧，希望能够为大家提供一些帮助。
 |
Java dump 文件的格式和内容
Java dump 通常是文本格式(.txt)，因此可以通过一般的文本编辑器进行阅读，阅读时需要注意段与行的格式：
段格式
为了便于大家的分析，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 信息。
- 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 <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 信息块中我们可以找到问题的异常代码，DE>ExceptionCode: C0000005DE> 代表内存访问错误或者非法的内存操作。DE>Module: C:\eclipse\workspace\Serviceability\TestApps\TestJin\CallJni.dllDE> 指明了发生问题的原生模块。 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 编译，然后再对系统的运行情况进行进一步的跟踪。
DE>JITC_COMPILEOPT=SKIP{failingPackage/failingClass}{failingMethod}DE>
除此之外，查看 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 清单中，DE>Dump Event "uncaught" (00008000) Detail "java/lang/OutOfMemoryError" receivedDE> 告诉我们问题是由于内存溢出引起的，并且从 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 启动参数的设置有关，比如设置了 DE>DISABLE_JAVADUMP=true，IBM_NOSIGHANDLER=trueDE> 等等，因此可以首先检查系统设置和 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 |
