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信息和内存情况等。