java crash分析

 

    有一次服务器jvm crash,无任何异常信息。后来想想不对啊，除非是人为的将java的进程kill掉，要不然不可能没有错误日志的，后来突然想起上次价格行情做性能测试时，当jvm crash掉之后，是在命令目录下会生成一个hs_err_pid*****.log文件的，于是找到那个文件，下面是分析过程，这个文件有几部分内容，首先是头部信息，头信息包含了出错的大体信息和位置。

# # A fatal error has been detected by the Java Runtime Environment: # # SIGSEGV (0xb) at pc=0x00002b0d8002534e, pid=3594, tid=1093806400 # # JRE version: 6.0_18-b07 # Java VM: Java HotSpot(TM) 64-Bit Server VM (16.0-b13 mixed mode linux-amd64 ) # # Problematic frame: # V [libjvm.so+0x2de34e] # # If you would like to submit a bug report, please visit: # http://java.sun.com/webapps/bugreport/crash.jsp #  

     在这部分中，有三块内容需要我们注意，一是SIGSEGV是一个信号名称，表示这是一个建立CORE文件段的非法错误;二是指明了运行环境，jre版本以及jvm版本;三是最重要的信息，它指明了出错的地方，这里V表示一种frame type，这里是指vmframe,而中括号里则表示出错是在libjvm.so这个文件里，具体位置的偏移量为+号后面的数据。由这里可以知道这是由于jvm自身运行错误导致。

        这个文件的第二部分则是当前处理的线程，或者说是当jvm crash时在运行的线程，详细内容如下：

--------------- T H R E A D --------------- Current thread (0x0000000056406800): GCTaskThread [stack: 0x0000000041222000,0x0000000041323000] [id=3605] siginfo:si_signo=SIGSEGV: si_errno=0, si_code=1 (SEGV_MAPERR), si_addr=0xfffffffffffffffc Registers: RAX=0x0000000000000001, RBX=0x00002aaac867b688, RCX=0x00002aaaaf332cb0, RDX=0xfffffffffffffffc RSP=0x0000000041321ed0, RBP=0x0000000041321ef0, RSI=0x00002aaac867b688, RDI=0x0000000056451280 R8 =0x00002aaaaf332c78, R9 =0x0000000000000002, R10=0x00002b0d80661201, R11=0x00002b0d8066e6e0 R12=0x0000000056451280, R13=0x00002aaaaf332cb0, R14=0x00002aaaaf332cb0, .......后面省略N行  

         这里只要第一行即可，这一行指明了，当crash时，程序正在运行垃圾回收线程，所以有理由怀疑是垃圾回收出了问题，然后这个文件就指引我们来到了第三部分，dump出来的线程信息。

--------------- P R O C E S S --------------- Java Threads: ( => current thread ) 0x0000000056523000 JavaThread "Keep-Alive-Timer" daemon [_thread_blocked, id=12281, stack(0x00000000478cc000,0x00000000479cd000)] 0x0000000056a2e000 JavaThread "pool-7-thread-3" [_thread_blocked, id=8876, stack (0x0000000046fc3000,0x00000000470c4000)] 0x000000005687f800 JavaThread "ClientConnectionHandler" daemon [_thread_in_native, id=4786, stack(0x0000000044599000,0x000000004469a000)] 0x0000000056d0b000 JavaThread "MERGE2.FindSubgroups thread (channel=*******)" daemon [_thread_blocked, id=4710, stack(0x00000000472c6000,0x00000000473c7000)] 0x0000000056796800 JavaThread "pool-7-thread-2" [_thread_blocked, id=6325, stack (0x00000000477cb000,0x00000000478cc000)] ......以下省略N行 Heap PSYoungGen total 160448K, used 154320K [0x00002aaac8b60000, 0x00002aaad2fc0000, 0x00002aaad3600000) eden space 152448K, 100% used [0x00002aaac8b60000,0x00002aaad2040000,0x00002aaad2040000) from space 8000K, 23% used [0x00002aaad27f0000,0x00002aaad29c4018,0x00002aaad2fc0000) to space 7872K, 12% used [0x00002aaad2040000,0x00002aaad2134018,0x00002aaad27f0000) PSOldGen total 349568K, used 344605K [0x00002aaab3600000, 0x00002aaac8b60000, 0x00002aaac8b60000) object space 349568K, 98% used [0x00002aaab3600000,0x00002aaac8687690,0x00002aaac8b60000) PSPermGen total 65792K, used 48038K [0x00002aaaae200000, 0x00002aaab2240000, 0x00002aaab3600000) object space 65792K, 73% used [0x00002aaaae200000,0x00002aaab10e9bf8,0x00002aaab2240000) ......以下再省略N行 VM Arguments: jvm_args: -Xms128m -Xmx512m -XX:PermSize=64m -Djava.net.preferIPv4Stack=true -Drialto.command.port=6789 -Drialto.work.dir=/home/admin/output/work java_command: com.******.*****.*****.apptask.CheckTaskStart Launcher Type: SUN_STANDARD Environment Variables: JAVA_HOME=/usr/*****/java PATH=/usr/*****/java/bin:/usr/******/ant/bin:/usr/******/antx-2/bin:/usr/kerberos/bin:/usr/local/bin:/bin:/usr/bin:/usr/X11R6/bin:/home/admin/bin LD_LIBRARY_PATH=/usr/*******/install/jdk1.6.0_18/jre/lib/amd64/server:/usr/******/install/jdk1.6.0_18/jre/lib/amd64:/usr/******/install/jdk1.6.0_18/jre/../lib/amd64 SHELL=/bin/bash

       在略过上面N行的处于bolcked状态下的线程信息后，我们终于看到了此时的堆信息。由标红处我们发现，crash正处于eden区达到了100%要进行young gc的时候，因此我们有理由相信是由于young gc出了问题所致。但是什么问题呢？于是上google搜了一下“jvm crash young gc”。good luck!第一篇就找到了相应的解决方法，原来是这是jdk1.6u18的一个bug,官方文档介绍如下：

Card-Marking Optimization Issue A flaw in the implementation of a card-marking performance optimization in the JVM can cause heap corruption under some circumstances. This issue affects the CMS garbage collector prior to 6u18, and the CMS, G1 and Parallel Garbage Collectors in 6u18. The serial garbage collector is not affected. Applications most likely to be affected by this issue are those that allocate very large objects which would not normally fit in Eden, or those that make extensive use of JNI Critical Sections (JNI Get/Release*Critical). This issue will be fixed in the next Java SE 6 update. Meanwhile, as a workaround to the issue, users should disable this performance optimization by -XX:-ReduceInitialCardMarks. 

        这段话主要三个意思：一是指这个bug影响的GC类型为1.6u18前的CMS类GC以及1.6u18的CMS、G1和并行类GC，而串行GC不受影响;二是指哪些程序会受影响，主要是那些会分配大量的大对象而eden区过小或者对JNI使用比较敏感的程序;三是指明了处理方法

           那么此处是否符合前面的两个条件呢？通过JVM参数，我们发现本例中的GC类型未指定，也就是使用的是默认参数，那么默认的GC类型是什么呢？在JDK5.0之前默认的GC是串行GC,但是之后尤其是到了JDK6.0之后就更加智能化了，会依据机器的性能来进行指定，怎么个指定法呢？有以下三条原则：

           1、如果你是使用服务器类JVM的话，那么就会由并行GC来取代串行GC;

         2、当程序运行后，会首先去检查硬件环境，如果确定其性能满足服务器类机器的标准的话，就会运行服务器类JVM

            3、什么样的机器符合服务器类的标准呢？CPU至少要在2核以上，物理内存在2G以上。

           通过以上三条，可以确认任务机符合服务器类机器的标准，因此会使用并行GC，在这个bug的影响范围内。而对于第二点，JVM参数只指定了512M内存，除去永久区的64M，而新生代与老生代的默认分配比例是1：8，因此新生代大约是在50M左右，的确不是一个很大的数字。当初也许是由于担心任务和web跑在一台机器上吧，因此将JVM的堆参数设得这么小。

           后续的处理方法一是将任务的JVM参数标准化;二是使用-XX:-ReduceInitialCardMarks来解决这个bug！