JVM Crash日志分析

转自：http://book.51cto.com/art/201408/448846.htm

8.7.3  JVM Crash日志分析（1）

JVM有时也会因为一些原因而导致直接垮掉，因为JVM本身也是一个正在运行的程序，这个程序本身也会有很多情况直接出问题，如JVM本身也有一些Bug，这些Bug可能会导致JVM异常退出。JVM退出一般会在工作目录下产生一个日志文件，也可以通过JVM参数来设定，如-XX:ErrorFile=/tmp/log/hs_error_%p.log。

下面是一个日志文件：
 

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00002ab12ba7103a, pid=7748, tid=1363515712
#
# JRE version: 6.0_26-b03
# Java VM: OpenJDK 64-Bit Server VM (20.0-b11-internal mixed mode linux- amd64 )
# Problematic frame:
# V  [libjvm.so+0x8bf03a]  jni_GetFieldID+0x22a
#
# If you would like to submit a bug report, please visit:
#   http://java.sun.com/webapps/bugreport/crash.jsp
#
---------------  T H R E A D  ---------------
Current thread (0x00002aabd0ba5000):  JavaThread "http-0.0.0.0-7001-32" daemon [_thread_in_vm, id=8192, stack(0x0000000051359000,0x000000005145a000)]

siginfo:si_signo=SIGSEGV: si_errno=0, si_code=1 (SEGV_MAPERR), si_addr= 0x0000000000000010

Registers:
...
Top of Stack: (sp=0x0000000051455620)
...
Instructions: (pc=0x00002ab12ba7103a)
0x00002ab12ba7101a:   01 00 00 48 8b 5f 10 48 8d 43 08 48 3b 47 18 0f
0x00002ab12ba7102a:   87 53 02 00 00 48 89 47 10 48 89 13 48 83 c2 10
0x00002ab12ba7103a:   48 8b 0a 48 89 d7 4c 89 fe 31 c0 ff 51 58 49 8b
0x00002ab12ba7104a:   47 08 48 85 c0 0f 85 f7 01 00 00 48 c7 45 90 00
Register to memory mapping:

RAX=
[error occurred during error reporting (printing register info), id 0xb]

Stack: [0x0000000051359000,0x000000005145a000],  sp=0x0000000051455620,  free space=1009k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x8bf03a]  jni_GetFieldID+0x22a
C  [libocijdbc10.so+0xcc81]  Java_oracle_jdbc_driver_T2CConnection_ t2cDescribeError+0x205
C  [libocijdbc10.so+0x878b]  Java_oracle_jdbc_driver_T2CConnection_ t2cCreateState+0x193
j  oracle.jdbc.driver.T2CConnection.t2cCreateState([BI[BI[BI[BISI[S[B[B]I+0
j  oracle.jdbc.driver.T2CConnection.logon()V+589
j  oracle.jdbc.driver.PhysicalConnection.<init>(Ljava/lang/String;Ljava/ lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/util/Properties;Loracle/jdbc/driver/OracleDriverExtension;)V+370
j  oracle.jdbc.driver.T2CConnection.<init>(Ljava/lang/String;Ljava/lang/ String;Ljava/lang/String;Ljava/lang/String;Ljava/util/Properties;Loracle/jdbc/driver/OracleDriverExtension;)V+10
j  oracle.jdbc.driver.T2CDriverExtension.getConnection(Ljava/lang/String; Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/util/Properties;)Ljava/sql/Connection;+67
j  oracle.jdbc.driver.OracleDriver.connect(Ljava/lang/String;Ljava/util/ Properties;)Ljava/sql/Connection;+831
...
---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )
  0x000000004d11e800 JavaThread "IdleRemover" daemon [_thread_blocked, id=8432, stack(0x00000000584ca000,0x00000000585cb000)]
=>0x00002aabd0ba5000 JavaThread "http-0.0.0.0-7001-32" daemon [_thread_in_ vm, id=8192, stack(0x0000000051359000,0x000000005145a000)]
...
VM state:not at safepoint (normal execution)

VM Mutex/Monitor currently owned by a thread: None

Heap
 par new generation   total 1474560K, used 1270275K [0x00002aaaae0f0000, 0x00002aab120f0000, 0x00002aab120f0000)
  eden space 1310720K,  89% used [0x00002aaaae0f0000, 0x00002aaaf5d634e0, 0x00002aaafe0f0000)
  from space 163840K,  57% used [0x00002aab080f0000, 0x00002aab0dcfd748, 0x00002aab120f0000)
  to   space 163840K,   0% used [0x00002aaafe0f0000, 0x00002aaafe0f0000, 0x00002aab080f0000)
 concurrent mark-sweep generation total 2555904K, used 888664K [0x00002aab120f0000, 0x00002aabae0f0000, 0x00002aabae0f0000)
 concurrent-mark-sweep perm gen total 262144K, used 107933K [0x00002aabae0f0000, 0x00002aabbe0f0000, 0x00002aabbe0f0000)

Code Cache  [0x00002aaaab025000, 0x00002aaaabcd5000, 0x00002aaaae025000)
 total_blobs=3985 nmethods=3447 adapters=491 free_code_cache=37205440 largest_free_block=30336

Dynamic libraries:
40000000-40009000 r-xp 00000000 ca:06 224241                             /opt/ xxx/install/jdk-1.6.0_26/bin/java
...
---------------  S Y S T E M  ---------------

OS:Red Hat Enterprise Linux Server release 5.4 (Tikanga)

在这个文件中的信息主要分为4种：退出原因分类、导致退出的Thread信息、退出时的Process状态信息、退出时与操作系统相关信息。

JVM退出一般有三种主要原因，在上面这个例子中是SIGSEGV（0xb），这三种原因分别如下。

1．EXCEPTION_ACCESS_VIOLATION

正在运行JVM自己的代码，而不是外部的Java代码或其他类库代码。这种情况很可能是JVM自己的Bug，遇到这种错误时，可以根据出错信息到http://bugreport.sun.com/bugreport/index.jsp去搜索一下已经发行的Bug。

在大部分情况下是由于JVM的内存回收导致的，所以可以观察Process部分的信息，查看堆的内存占用情况。

2．SIGSEGV

JVM正在执行本地或JNI的代码，出这种错误很可能是第三方的本地库有问题，可以通过gbd和core文件来分析出错原因。

3．EXCEPTION_STACK_OVERFLOW

这是个栈溢出的错误，注意JVM在执行Java线程时出现的栈溢出通常不会导致JVM退出，而是抛出java.lang.StackOverflowError，但是在Java虚拟机中，Java的代码和本地C或C++代码共用相同的栈，这时如果出现栈溢出的话，就有可能直接导致JVM退出。建议将JVM的栈尺寸调大，主要涉及两个参数：-Xss和-XX:StackShadowPages=n。

日志文件的Thread部分的信息对我们排查这个问题的原因最有帮助，这部分有两个关系信息，包括Machine Instructions和Thread Stack。Mchine Instructions是当前系统执行的机器指令，是16进制的。我们可以将它转成指令，通过udis86工具来转换，该工具可以在http://udis86.sourceforge.net/?下载，安装在Linux中，将上面的16进制数字复制到命令行中用如下方式执行转换：
 

[junshan@xxx ~]$ echo "47 08 48 85 c0 0f 85 f7 01 00 00 48 c7 45 90 00"  | udcli -64 -x
0000000000000000 47084885         or [r8-0x7b], r9b
0000000000000004 c00f85           ror byte [rdi], 0x85
0000000000000007 f701000048c7     test dword [rcx], 0xc7480000
000000000000000d 4590             xchg r8d, eax

可以得到汇编指令，由于是64位机器，所以是udcli -64 –x，如果是32机器，则改成udcli -32 –x。可以通过这个指令来判断当前正在执行什么指令而导致了垮掉。例如，如果当前在访问寄存器地址，那么这个地址是否合法，以及如果是除法指令，操作数是否合法等。

8.7.3  JVM Crash日志分析（2）

而Stack信息最直接，可以帮助我们看到到底是哪个库的哪行代码出错，如在上面的错误信息中显示的是由于执行Oracle的Java驱动程序引起出错的。我们还可以通过生成的core文件来更详细地看出是执行到哪行代码出错的，如下所示：
 

$gdb /opt/xxx/java/bin/java /home/admin/xxxx/target/core.14595
GNU gdb Fedora (6.8-37.el5)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/ gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu"...
…
(gdb) bt
#0  0x000000320ea30265 in raise () from /lib64/libc.so.6
#1  0x000000320ea31d10 in abort () from /lib64/libc.so.6
#2  0x00002b4ba59d80e9 in os::abort () from /opt/taobao/install/jdk-1.6.0_ 26/jre/lib/amd64/server/libjvm.so
#3  0x00002b4ba59d1e0f in VMError::report_and_die () from /opt/taobao/ install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
…

通过gdb来调试core文件可以看到更详细的信息，还可以通过frame n和info local组合命令来更进一步地查看这一行所包含的local变量值，但这只能是程序使用-g命名编译的结果，也就是编译后的程序包含debug信息。

日志文件的第三部分包含的是Process信息，这里详细列出了该程序产生的所有线程，以及线程正处于的状态。由于在同一时刻只能有一个线程具有CPU使用权，所以可以看到，其他所有线程的状态都是_thread_blocked，而执行的正是那个出错的线程。

这部分最有价值的部分就是记录下来了当前JVM的堆信息，如下所示：
 

Heap
 par new generation   total 1474560K, used 1270275K [0x00002aaaae0f0000, 0x00002aab120f0000, 0x00002aab120f0000)
  eden space 1310720K,  89% used [0x00002aaaae0f0000, 0x00002aaaf5d634e0, 0x00002aaafe0f0000)
  from space 163840K,  57% used [0x00002aab080f0000, 0x00002aab0dcfd748, 0x00002aab120f0000)
  to   space 163840K,   0% used [0x00002aaafe0f0000, 0x00002aaafe0f0000, 0x00002aab080f0000)
 concurrent mark-sweep generation total 2555904K, used 888664K [0x00002aab120f0000, 0x00002aabae0f0000, 0x00002aabae0f0000)
 concurrent-mark-sweep perm gen total 262144K, used 107933K [0x00002aabae0f0000, 0x00002aabbe0f0000, 0x00002aabbe0f0000]

通过每个分区当前所使用的空间大小，尤其是Old区的空间是否已经满了，可以判断出当前的GC是否正常。

还有一个信息也比较有价值，那就是当前JVM的启动参数，设置的堆大小和使用的GC方式等都可以从这里看出。

最后一部分是System信息，这部分主要记录了当前操作系统的状态信息，如操作系统的CPU信息和内存情况等。