Java crash问题分析

Java的应用有时候会因为各种原因Crash，这时候会产生一个类似java_errorpid.log的错误日志。可以拿到了

这个日志，怎样分析Crash的原因呢？下面我们来详细讨论如何分析java_errorpid.log的错误日志。

一. 如何得到这个日志文件

如果有一个严重的错误引起Java进程非正常退出，我们叫Crash，这时候会产生一个日志文件。缺省情况下，这个

文件会产生在工作目录下。但是，可以在Java启动参数通过下面的设置，来改变这个文件的位置和命名规则。例如：

java -XX:ErrorFile=/var/log/java/java_error_%p.log

就将这个错误文件放在/var/log/java下，并且以java_error_pid.log的形式出现。

二.产生错误的原因

造成严重错误的原因有多种可能性。Java虚拟机自身的Bug是原因之一，但是这种可能不是很大。在绝大多数情况下，是由于系统的库文件、API或第三方的库文件造成的；系统资源的短缺也有可能造成这种严重的错误。在发生了Crash之后，如果无法定位根本原因，也应该迅速找到Work Around的方法。

三.对日志文件的分析

首先要检查日志的文件头：例如，下面是从一个客户发过来的错误日志的文件头

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
#
# An unexpected error has been detected by HotSpot Virtual Machine:
#
# EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x0815e87e, pid=7268, tid=4360
#
# Java VM: Java HotSpot(TM) Server VM (1.4.2_13-b06 mixed mode)
# Problematic frame:
# V [jvm.dll+0x15e87e]
#
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

文件头中有很多有用的信息，“EXCEPTION_ACCESS_VIOLATION ”意味着Java应用Crash的时候，正在运行JVM自己的代码，而不是外部的Java代码或其他类库代码。这种情况很可能是JVM的Bug，但是也不一定。除了“EXCEPTION_ACCESS_VIOLATION ”，还有可能是别的信息，例如“SIGSEGV(0xb)”，意味着JVM正在执行本地或JNI的代码;“EXCEPTION_STACK_OVERFLOW”意味着这是个栈溢出的错误。（**********看到这里我们知道我报错时正在运行JVM自己的代码，而不是外部的Java代码或其他类库代码*********）

另外一个有用的JVM崩溃信息就是：

# Problematic frame:
# V [jvm.dll+0x15e87e]

它说明Crash的时候，JVM正在从哪个库文件执行代码。除了“V”以外，还有可能是“C”、“j”、“v”、“J”。具体的表示意思如下：

FrameType Description：
C: Native C frame
j: Interpreted Java frame
V: VMframe
v: VMgenerated stub frame
J: Other frame types, including compiled Java frames

（**********看到这里我们知道我报错时是V: VMframe这种情况*********）

文件头之后，是当前线程的DUMP信息，线程之后是JVM进程的DUMP信息，包括所有线程的状态、地址和ID。最后还有JVM状态，

Heap状态，动态连接库等等的信息。这些烦乱的信息中，包含有非常有用的信息。下面我们根据几个具体的实例来分析JVM崩溃的典型例子。

四.内存回收引起的Crash

内存回收引起的Crash有以下的特点：在日志文件头一般有“ EXCEPTION_ACCESS _VIOLATION”和

“# Problematic frame: # V [jvm.dll+....”的信息，意味着这是在JVM内部处理，而且多半是JVM的Bug。

（**********看到这里我们知道我报错时意味着这是在JVM内部处理，而且多半是JVM的Bug*********）

对于这类问题，最快的方法就是绕过它。

另外，在Thread的DUMP信息最后，还能看到有关内存回收的行为例如：

--------------- T H R E A D ---------------
Current thread (0x00a56668): VMThread [id=4360]
siginfo: ExceptionCode=0xc0000005, reading address 0x00000057
Registers:
........

Stack: [0x03cf0000,0x03d30000), sp=0x03d2fc18, free space=255k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [jvm.dll+0x15e87e]

VM_Operation (0x063efbac): full generation collection, mode: safepoint, requested by thread 0x040f83f8
------------------------------------------------------------

可以清楚的看到JVM正在做 “full generation collection”。另外还有可能看到，其他的回收行为：

对于内存回收的错误，一般

generation collection for allocation
full generation collection
parallel gc failed allocation
parallel gc failed permanent allocation
parallel gc system gc
（***********这些错，俺都没碰到***********）

采取改变回收的算法和参数的方法来绕过去。例如，来自客户的日志除了上面的日志信息，在日志中Heap信息中还能发现一些其他信息：

--------------------------------------------------------------
Heap
def new generation total 22592K, used 19530K [0x10010000, 0x11890000, 0x138f0000)
eden space 20096K, 97% used [0x10010000, 0x11322bd8, 0x113b0000)
from space 2496K, 0% used [0x113b0000, 0x113b0000, 0x11620000)
to space 2496K, 0% used [0x11620000, 0x11620000, 0x11890000)
tenured generation total 190696K, used 100019K [0x138f0000, 0x1f32a000, 0x30010000)
the space 190696K, 52% used [0x138f0000, 0x19a9cf38, 0x19a9d000, 0x1f32a000)
compacting perm gen total 38656K, used 38588K [0x30010000, 0x325d0000, 0x34010000)
the space 38656K, 99% used [0x30010000, 0x325bf038, 0x325bf200, 0x325d0000)
----------------------------------------------------------------

上面的信息能看出在Crash的时候，JVM的PermSize空间几乎已经消耗完了，并且回收算法在压缩Perm空间的时候出了错。因此，建议改变内存回收的算法，或扩大PermSize和MaxPermSize的数值。

（*******这个倒是可以尝试*******）

五.栈溢出引起的Crash

Java代码引起的栈溢出，通常不会引起JVM的Crash，而是抛出一个Java异常：java.lang.StackOverflowError。但是在Java虚拟机中，Java的代码和本地C或C++代码公用相同的Stack。这样，在执行本地代码所造成的栈溢出，就有可能引起JVM的Crash了。栈溢出引起的Crash会在日志的文件头中看到“EXCEPTION_STACK_OVERFLOW”字样。另外，在当前线程的Stack信息中也能发现一些信息。例如下面的例子：

-----------------------------------------------------------------------------------
# An unexpected error has been detected by HotSpot Virtual Machine:
#
# EXCEPTION_STACK_OVERFLOW (0xc00000fd) at pc=0x10001011, pid=296, tid=2940
#
# Java VM: Java HotSpot(TM) Client VM (1.6-internal mixed mode, sharing)
# Problematic frame:
# C [App.dll+0x1011]
#
--------------- T H R E A D ---------------
Current thread (0x000367c0): JavaThread "main" [_thread_in_native, id=2940]
:
Stack: [0x00040000,0x00080000), sp=0x00041000, free space=4k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [App.dll+0x1011]
C [App.dll+0x1020]
C [App.dll+0x1020]
:
C [App.dll+0x1020]
C [App.dll+0x1020]
......
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j Test.foo()V+0
j Test.main([Ljava/lang/String;)V+0
v ~StubRoutines::call_stub

--------------------------------------------------------------------------------

在上面的信息中，可以发现这是个栈溢出的错误。并且当前栈剩余的空间已经很小了(free space =4k)。

因此建议将JVM的Stack的尺寸调大，主要设计两个参数：“-Xss” 和“-XX:StackShadowPages=n”。但是，将栈的尺寸调大，也意味着在有限的内存资源中，能打开的最大线程数会减少。

 

JVM致命错误日志（hs_err_pid.log）解读

 

致命错误出现的时候，JVM生成了hs_err_pid<pid>.log这样的文件，其中往往包含了虚拟机崩溃原因的重要信息。因为经常遇到，在这篇文章里，我挑选了一个，并且逐段分析它包含的内容（文件可以在文章最后下载）。默认情况下文件是创建在工作目录下的（如果没权限创建的话JVM会尝试把文件写到/tmp这样的临时目录下面去），当然，文件格式和路径也可以通过参数指定，比如：

java -XX:ErrorFile=/var/log/java/java_error%p.log

这个文件将包括：

• 触发致命错误的操作异常或者信号；
• 版本和配置信息；
• 触发致命异常的线程详细信息和线程栈；
• 当前运行的线程列表和它们的状态；
• 堆的总括信息；
• 加载的本地库；
• 命令行参数；
• 环境变量；
• 操作系统CPU的详细信息。

首先，看到的是对问题的概要介绍：

#  SIGSEGV (0xb) at pc=0x03568cf4, pid=16819, tid=3073346448

一个非预期的错误被JRE检测到，其中：

• SIGSEGV是信号名称
• 0xb是信号码
• pc=0x03568cf4指的是程序计数器的值
• pid=16819是进程号
• tid=3073346448是线程号

如果你对JVM有了解，应该不会对这些东西陌生。

接下来是JRE和JVM的版本信息：

# JRE version: 6.0_32-b05
# Java VM: Java HotSpot(TM) Server VM (20.7-b02 mixed mode linux-x86 )

运行在mixed模式下。

然后是问题帧的信息：

# Problematic frame:
# C  [libgtk-x11-2.0.so.0+0x19fcf4]  __float128+0x19fcf4

C：帧类型为本地帧，帧的类型包括：

• C：本地C帧
• j：解释的Java帧
• V：虚拟机帧
• v：虚拟机生成的存根栈帧
• J：其他帧类型，包括编译后的Java帧
• libgtk-x11-2.0.so.0+0x19fcf4：和程序计数器（pc）表达的含义一样，但是用的是本地so库+偏移量的方式。

接下去第一部分是线程信息：

Current thread (0x09f30c00):  JavaThread”main”[_thread_in_native, id=16822, stack(0xb72a8000,0xb72f9000)]

当前线程的：

• 0x09f30c00：指针
• JavaThread：线程类型，可能的类型包括：
  • JavaThread
  • VMThread
  • CompilerThread
  • GCTaskThread
  • WatcherThread
  • ConcurrentMarkSweepThread
• main：名字
  • _thread_in_native：线程当前状态，状态枚举包括：
  • _thread_uninitialized：线程还没有创建，它只在内存原因崩溃的时候才出现
  • _thread_new：线程已经被创建，但是还没有启动
  • _thread_in_native：线程正在执行本地代码，一般这种情况很可能是本地代码有问题
  • _thread_in_vm：线程正在执行虚拟机代码
  • _thread_in_Java：线程正在执行解释或者编译后的Java代码
  • _thread_blocked：线程处于阻塞状态
  • …_trans：以_trans结尾，线程正处于要切换到其它状态的中间状态
• id=16822：线程ID
• 0xb72a8000,0xb72f9000：栈区间

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

这部分是导致虚拟机终止的非预期的信号信息，含义前面已经大致提到过了。其中si_errno和si_code是Linux下用来鉴别异常的，Windows下是一个ExceptionCode。

EAX=0×00000000,EBX=0x0375dd84,ECX=0×00000000,EDX=0×00000000
ESP=0xb72f0fa0,EBP=0xb72f0fb8,ESI=0×00000000,EDI=0x0a6c1800
EIP=0x03568cf4,EFLAGS=0×00010246,CR2=0×00000010

这是寄存器上下文。

Top of Stack: (sp=0xb72f0fa0)
0xb72f0fa0:  00000000004022500040217f 0375dd84
0xb72f0fb0:  000000000a6c1800 b72f0fe8 0356c2c0
0xb72f0fc0:  000000000a6c1800 b72f0fe8 003b3e77
0xb72f0fd0:   003e6c8b 0a1a70d0 0a193358 0375dd84
0xb72f0fe0:   0a276418 0a276418 b72f1048 03536c56
0xb72f0ff0:   0acad000 0b3ca978 0000000c 00dd0674
0xb72f1000:  000000030a2c7d50 b72f1038 0000330c
0xb72f1010:   ffffffff ffffffff0000000100000001
Instructions: (pc=0x03568cf4)
0x03568cd4:  8914248975f889d6897d fc89c7 e8 7e 1b
0x03568ce4:   ea ff8934248987d4020000e83000ea ff
0x03568cf4:   8b4010893c24c7442408000000008987
0x03568d04:   d00200008b838824000089442404e8 dd

栈顶程序计数器旁的操作码，它们可以被反汇编成系统崩溃前执行的指令。

Register to memory mapping:
EAX=0x00000000isan unknown value
EBX=0x0375dd84: <offset 0x394d84>in/usr/lib/libgtk-x11-2.0.so.0 at 0x033c9000
ECX=0x00000000isan unknown value
EDX=0x00000000isan unknown value
ESP=0xb72f0fa0ispointing into the stackforthread: 0x09f30c00
EBP=0xb72f0fb8ispointing into the stackforthread: 0x09f30c00
ESI=0x00000000isan unknown value
EDI=0x0a6c1800isan unknown value

寄存器和内存映射信息。

Stack: [0xb72a8000,0xb72f9000],  sp=0xb72f0fa0,  free space=291k
Native frames: (J=compiled Java code, j=interpreted, Vv=VMcode,C=native code)
C [libgtk-x11-2.0.so.0+0x19fcf4]  __float128+0x19fcf4
C [libgtk-x11-2.0.so.0+0x1a32c0]  __float128+0xc0
… …
C [libswt-pi-gtk-3738.so+0x33f6a]  Java_org_eclipse_swt_internal_gtk_OS__1Call+0xf
J org.eclipse.swt.internal.gtk.OS._Call(III)I
J org.eclipse.swt.internal.gtk.OS.Call(III)I
Java frames: (J=compiled Java code, j=interpreted, Vv=VMcode)
J org.eclipse.swt.internal.gtk.OS._Call(III)I
J org.eclipse.swt.internal.gtk.OS.Call(III)I
j  org.eclipse.swt.widgets.Widget.fixedSizeAllocateProc(II)I+5
j  org.eclipse.swt.widgets.Display.fixedSizeAllocateProc(II)I+17
v  ~StubRoutines::call_stub
… …

线程栈。包含了地址、栈顶、栈计数器和线程尚未使用的栈信息，由于栈可能非常长，打印的长度有限制，但是至少本地栈和Java栈都打印出来了（很多时候本地栈打印不出来，但是Java栈一般都能打印出来）。从中可以看到，Eclipse的虚拟机崩溃了。

Java Threads: ( => current thread )
  0x0b4c1000 JavaThread”Worker-247″[_thread_blocked, id=25417, stack(0x741bc000,0x7420d000)]
  0x0a300c00 JavaThread”Worker-246″[_thread_blocked, id=25235, stack(0x7d30c000,0x7d35d000)]
… …

线程信息。一目了然，不解释了。

VMstate:notat safepoint (normal execution)

虚拟机状态。包括：

• not at a safepoint：正常运行状态；
• at safepoint：所有线程都因为虚拟机等待状态而阻塞，等待一个虚拟机操作完成；
• synchronizing：一个特殊的虚拟机操作，要求虚拟机内的其它线程保持等待状态。

VMMutex/Monitor currently owned by a thread: None

虚拟机的Mutex和Monitor目前没有被线程持有。Mutex是虚拟机内部的锁，而Monitor则关联到了Java对象。

Heap
PSYoungGen      total149056K, used125317K[0xa9700000, 0xb41a0000, 0xb41a0000)
eden space123520K,95% used [0xa9700000,0xb0ac0de0,0xb0fa0000)
from space25536K,26% used [0xb28b0000,0xb2f50748,0xb41a0000)
to   space25600K,0% used [0xb0fa0000,0xb0fa0000,0xb28a0000)
PSOldGen        total261248K, used239964K[0x941a0000, 0xa40c0000, 0xa9700000)
object space261248K,91% used [0x941a0000,0xa2bf7018,0xa40c0000)
PSPermGen       total163328K, used130819K[0x841a0000, 0x8e120000, 0x941a0000)
object space163328K,80% used [0x841a0000,0x8c160c40,0x8e120000)

堆信息。新生代、老生代、永久代。对JVM有了解的人应该都清楚，不解释了。

Code Cache  [0xb4262000, 0xb5ac2000, 0xb7262000)
 total_blobs=5795nmethods=5534adapters=209free_code_cache=25103616largest_free_block=38336

代码缓存（Code Cache）。这是一块用于编译和保存本地代码的内存，注意是本地代码，它和PermGen（永久代）是不一样的，永久带是用来存放Java类定义的。

Dynamic libraries:
00101000-00122000 r-xp 00000000 08:01 3483560    /usr/lib/libjpeg.so.62.0.0
00122000-00123000 rwxp 00020000 08:01 3483560    /usr/lib/libjpeg.so.62.0.0
00125000-00130000 r-xp 00000000 08:01 9093202    /lib/libgcc_s-4.1.2-20080825.so.1
00130000-00131000 rwxp 0000a000 08:01 9093202    /lib/libgcc_s-4.1.2-20080825.so.1
... ...

内存映射。这些信息是虚拟机崩溃时的虚拟内存列表区域。在定位崩溃原因的时候，它可以告诉你哪些类库正在被使用，位置在哪里，还有堆栈和守护页信息。就以列表中第一条为例说明：

• 00101000-00122000：内存区域
• r-xp：权限，r/w/x/p/s分别表示读/写/执行/私有/共享
• 00000000：文件内的偏移量
• 08:01：文件位置的majorID和minorID
• 3483560：索引节点号
• /usr/lib/libjpeg.so.62.0.0：文件位置

每一个lib都有两块虚拟内存区域——代码和数据，它们的权限不同，代码区域是r-xp；数据区域是rwxp。守护页（guard page）由权限为--xp和rwxp的一对组成。

VMArguments:
jvm_args: -Dosgi.requiredJavaVersion=1.5-XX:MaxPermSize=256m -Xms40m -Xmx512m -Dorg.eclipse.swt.browser.XULRunnerPath=''
java_command: /.../eclipse/plugins/org.eclipse.equinox.launcher_1.2.0.v20110502.jar -os linux -ws gtk -arch x86 -showsplash -launcher /.../eclipse/eclipse -name Eclipse ...
Launcher Type:SUN_STANDARD
Environment Variables:
PATH=...
DISPLAY=:0.0

虚拟机参数和环境变量。

Signal Handlers:
SIGSEGV: [libjvm.so+0x726440], sa_mask[0]=0x7ffbfeff, sa_flags=0×10000004
SIGBUS: [libjvm.so+0x726440], sa_mask[0]=0x7ffbfeff, sa_flags=0×10000004
… …

信号句柄。对于Linux下的信号机制，参阅wiki百科。

OS:Red Hat Enterprise Linux Client release 5.4 (Tikanga)
uname:Linux 2.6.18-164.el5 #1 SMP Tue Aug 18 15:51:54 EDT 2009 i686
libc:glibc 2.5 NPTL 2.5
rlimit: STACK 10240k, CORE 0k, NPROC 65536, NOFILE 1024, AS infinity
load average:1.78 1.58 1.54
/proc/meminfo:
…
CPU:total 4 (4 cores per cpu, 1 threads per core) family 6 model 42 stepping 7, cmov, cx8, fxsr, mmx, sse, sse2, sse3, ssse3
/proc/cpuinfo:
…
Memory: 4k page, physical 3631860k(155144k free), swap 5124724k(5056452k free)

系统信息。

【转】：https://blog.csdn.net/u013339596/article/details/18562011