追查JVM崩溃

 

JDK升级到1.6后，服务器集群经常崩溃，后来把VM的参数调整为如下：

-Xmx2g -Xms2g -Xmn512m -XX:PermSize=196m -Xss256k -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+UseCMSCompactAtFullCollection -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70

指明了最大内存是2G，新生代为512M，年老区196M，内存占用率在达到70%的时候要执行GC，同时要使用CMS方式收集。

 

在增加内存后还是经常挂掉，又不知道具体由什么原因引起，很苦恼。后来就收集fatal log,经过统计，超过90%都是由于同一个因素引起。

 

JVM退出时的错误日志hs_err*.log通常是：

# An unexpected error has been detected by Java Runtime Environment:

#

#  SIGSEGV (0xb) at pc=0x00002ad49843ae5d, pid=986, tid=1102739776

#

# Java VM: Java HotSpot(TM) 64-Bit Server VM (11.0-b16 mixed mode linux-amd64)

# Problematic frame:

# V  [libjvm.so+0x25ee5d]

 

…

 

Heap

 par new generation   total 471872K, used 166068K [0x00002aaaae200000, 0x00002aaace200000, 0x00002aaace200000)

  eden space 419456K,  33% used [0x00002aaaae200000, 0x00002aaab6bbd590, 0x00002aaac7ba0000)

  from space 52416K,  48% used [0x00002aaac7ba0000, 0x00002aaac9442200, 0x00002aaacaed0000)

  to   space 52416K,   0% used [0x00002aaacaed0000, 0x00002aaacaed0000, 0x00002aaace200000)

 concurrent mark-sweep generation total 1572864K, used 1105061K [0x00002aaace200000, 0x00002aab2e200000, 0x00002aab2e200000)

 concurrent-mark-sweep perm gen total 200704K, used 124029K [0x00002aab2e200000, 0x00002aab3a600000, 0x00002aab3a600000)

 

 

可以看到年老区占用率刚好是1103473/1572864=70%，这个时刻，eden,from和to区都有一个不小的数值，这个说明这个时刻处于GC开始的阶段。后来把libjvm.so反汇编后，得到引起崩溃的执行代码，印证了这个想法。

V  [libjvm.so+0x25ee5d]:       41 ff 95 50 02 00 00    callq  *0x250(%r13)

V  [libjvm.so+0x25ec73]:       e9 7b ff ff ff          jmpq   25ebf3 <_ZN24Par_MarkFromRootsClosure6do_bitEm+0x23>

V  [libjvm.so+0x1cee10]:       49 8b 16                mov    (%r14),%rdx

V  [libjvm.so+0x256209]:       e9 d2 fd ff ff          jmpq   255fe0 <_ZN18CMSConcMarkingTask16do_scan_and_markEiP24CompactibleFreeListSpace+0x60>

V  [libjvm.so+0x255d19]:       4c 89 ef                mov    %r13,%rdi

V  [libjvm.so+0x611f57]:       80 7d a8 01             cmpb   $0x1,-0x58(%rbp)

V  [libjvm.so+0x60f5d4]:       48 8b 5d f8             mov    -0x8(%rbp),%rbx

V  [libjvm.so+0x4e2f6a]:       e9 63 ff ff ff          jmpq   4e2ed2 <_Z10java_startP6Thread+0xb2>

 

 

看得出，在GC线程要标志活的根对象的代码时，退出了。但是我们不知道它具体在做什么。

 

CMS做GC的过程：

1）  挂起JVM，这个过程非常短暂，标志所有的从全局变量，堆栈和寄存器可以访问到的对象，这些对象将作为根对象。

2）  恢复JVM的执行后，进行并行多CPU的标志被根对象间接引用到的对象，这个过程不能保证最后得到的结果是正确的，因为同时还有可能有创建新对象或者更新了Java引用了。这些变化同时也被记录下来了。

3）  如果最终可被标志的对象不超过98%，那么再次挂起JVM做最后一次标志。从根对象开始，根据2）记录的变化再次标志。这样就保证不会有对象漏掉了。

4）  恢复JVM，做扫除，把无法访问到对象占用有内存回收。

还有可能做内存整理，把空的内存统一到一块。

 

到了这里，应该可以确定十成九是JVM自身的BUG引起的了。除了自己要尝试升级JDK，还有就是向SUN提BUG了。

 

 

参考：

http://java.sun.com/javase/6/webnotes/trouble/TSG-Desktop/html/felog.html

评论

4 楼 gogole_09 2010-09-06  

好，很好，见到这篇文章更好！

3 楼 ginge 2010-03-21  

更新一下目前状况：
在JDK 6U18 还没出来前，我从https://jdk6.dev.java.net/留意到6U18 b05修复了一个严重的GC Bug，可是大家都没办法完全确定这个是否可以解决我们的问题。于是申请在线上做并行的测试，批准的是做6u17的。不过偷偷加入了6U18，这样测试了两周，结果是6U17挂了N次，6U18都没有挂过一次！

后来刚好6u18最终可以从SUN的正式渠道下载了，它是B07版本。看了它的RELEASE NOTE，发现它里面对于GC的更新非常重大，于是又把它加入进来测试。结果也比较稳定。


最后我们把线上的机器全部更换过来，现在中文站没有挂机器的情况出现了。

这次的升级是比较运气的，没有找到根本原因，通过升级JDK解决了问题。不过有些中文站以外的机器的崩溃升级没有解决问题，最终定位到Velocity的BUG导致。

这也说明JVM的崩溃一方面有可能是JDK本身的原因造成，另一方面也会因程序或者第三方组件造成。

2 楼 ginge 2009-12-31  

目前掌握的信息不能不让我得到这样的分析结果……或者还有其他真正因素或者数据有待发掘

1 楼 laurence_cao 2009-12-31  

追踪精神可嘉，分析结果未必正确！