jdk出错日志文件分析

本人在用jni调用.dll的时候，经常碰见这类问题，于是在网上查了相关的资料，但最终也没有找到最合理的解释，就整理一些思路：1 修改jvm的内存大小，把size增大一点2 呵呵 很感谢olivesoup和xql80329的关心。这个问题现在有所进展。大幅削减了Log输出后，已经4天没有crash了。由于用了一个第三方的Log工具，当时不知道这个Log工具会向 标准输出 也输出Log。怀疑非常频繁的输出大量的Log到控制台上JVM的处理有问题（也怀疑本身频繁的输出大量的Log到文件中JVM的处理有问题）。（每1秒钟就输出170k的Log）。
是不是这个原因还不能最终确定（因为时间还不够长，不能保证真的没有问题了）。
另外，有一点信息也交流一下：
JDK1.6修改了大量垃圾收集器的问题，如果JDK1.5出现了垃圾收集器引起的crash，可以升级到JDK1.6试试。3 检查环境变量设置 4 在release版下编译dll===================================================================java官方回复：http://java.sun.com/javase/6/webnotes/trouble/TSG-VM/html/crashes.htmlhttp://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4885936http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4912071====================================================================以下引自http://developers.sun.com.cn/blog/yutoujava/entry/20070411一. 如何得到这个日志文件
如果有一个严重的错误引起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”意味着这是个栈溢出的错误。

另外一个有用的信息就是：
# 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

文件头之后，是当前线程的DUMP信息，线程之后是JVM进程的DUMP信息，包括所有线程的状态、地址和ID。最后还有JVM状态，Heap状态，动态连接库等等的信息。这些烦乱的信息中，包含有非常有用的信息。下面我们根据几个具体的实例来分析Java虚拟机Crash的典型例子。




四.内存回收引起的Crash
内存回收引起的Crash有以下的特点：在日志文件头一般有“ EXCEPTION_ACCESS _VIOLATION”和“# Problematic frame: # V [jvm.dll+....”的信息，意味着这是在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]
...<more frames>...
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”。但是，将栈的尺寸调大，也意味着在有限的内存资源中，能打开的最大线程数会减少。


六.动态编译引起的Crash
未完，待续


如果是Java进程不知道什么原因退出或被杀死，想要分析具体原因，一般来说分下面几步：

1 拿到Java应用程序的日志文件。
一般来说日志文件中会有很应用相关的错误信息。Java进程异常退出的原因最有可能就是应用程序本身的问题。因此检查Java应用程序的日志文件可能是最快定位到错误的方法。

2 查找JVM的致命错误日志
如果应用程序日志文件中没有发现什么线索。那么还可以查看 JVM的致命错误日志。有些致命的错误，比如JNI或虚拟机本身产生的错误，可能使得Java应用程序来不及写日志就退出了。这时候可以查一个以 "hs_err_pid" 开头的日志名，例如hs_err_pid1125.log，其中1125是进程号。这个文件中也记录了一些宝贵的信息来提供一些线索，特别是Java自身的一些Bug。这个文件一般为于当前的工作目录中。用户可以用find命令自己搜索到。

3 查找操作系统的core dump文件
作为被操作系统所调度的进程，Java进程也会在不同的信号下产生Core Dump文件，例如Sig_ill和Seg_segv。这些非常严重的错误的确会使得Java虚拟机根本来不及产生任何日志就宕了。拿到core dump文件就可以使用很多工具来分析具体原因了，例如jmap, jstack等等都可以友好的进行Java进程的Core文件的分析。一般来说，Core文件也放到进程的当前工作目录，用户可以用find命令搜索 “core”。另外可以用coreadm来预先指定core文件存放的地方以及文件名的格式，例如：coreadm -g /var/core/core.%f.%p.%t

4使用Dtrace查找“是谁杀死了Java进程”
但是，有很多情况，进程被杀死的原因很复杂。有可能被别的进程以外杀掉，或被一些脚本不小心kill掉，或者被管理员（或入侵者kill -9）处理掉。这些情况都不会产生日志文件和core dump文件。这些情况很难跟踪。但如果是Solaris10下，可以使用下面的Dtrace脚本来确定“是谁杀死了Java进程”


#!/usr/sbin/dtrace -qs

proc:::signal-send
/args[1]->pr_pid == $1/
{
        printf("%s(pid:%d) is sending signal %d to %s\n", execname, pid, args[2],args[1]->pr_fname);
}

如何运行（1125）是进程号
$ ./sig1.d 1125
sched(pid:0) is sending signal 24 to bc
sched(pid:0) is sending signal 24 to bc
bash(pid:3987) is sending signal 15 to bc
bash(pid:3987) is sending signal 15 to bc
bash(pid:3987) is sendg signal 9 to bc