警惕使用jvm参数CMSRefProcTaskProxy

标签： jvm 参数 cmsrefproctaskproxy | 发表时间：2014-01-05 12:37 | 作者：zhoushijun
出处：http://www.iteye.com

    昨天中午的时候, 团队的兄弟找我看一个现象: 原先因为堆外内存使用过多会crash掉的java应用, 设置了最大堆外内存量(MaxDirectMemorySize)后jvm不会crash, 但出现了机器的两颗CPU全部被占满, 而且java程序没有响应的情况.
    我用jstat -gc/-gcutil/-gccause查了一下当时gc的情况, 发现出现过CMS GC, 最后一次导致GC的原因是CMS final remark, 没有什么异常. 新生代和旧生代占用量都比较少, survior的from与to区域都正常. 这就比较诡异了, 如果因为堆外内存超出了MaxDirectMemorySize设置的值, 那会抛出OOM, 但这个没有抛出.
    检查了DisableExplicitGC参数,是否关闭了显式GC, 结果没有关闭. 这就更说不通了.
    于是我转向调查CPU使用率为什么这么高. 用top查了一下CPU有几个jvm的线程(top运行后, 用shift + h开启线程观察)占着CPU, 线程的ID分别是: 38024, 38025, 38026, 38027.
然后采用pstack查看这几个线程究竟在干什么. pstack了好几次, 每次这些线程的stack都差不多, 如下:

引用
Thread 220 (Thread 0x40b4c940 (LWP 38024)):
#0  0x00007f1444751b60 in SpinPause@plt () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#1  0x00007f14447fbf09 in ParallelTaskTerminator::offer_termination() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#2  0x00007f1444c7fa87 in CMSRefProcTaskProxy::do_work_steal(int, CMSParDrainMarkingStackClosure*, CMSParKeepAliveClosure*, int*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#3  0x00007f1444c776e5 in CMSRefProcTaskProxy::work(int) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#4  0x00007f1444b40e2a in GangWorker::loop() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#5  0x00007f1444af8e98 in GangWorker::run() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#6  0x00007f1444af8278 in java_start(Thread*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#7  0x000000375560677d in start_thread () from /lib64/libpthread.so.0
#8  0x0000003754ed49ad in clone () from /lib64/libc.so.6
Thread 219 (Thread 0x40708940 (LWP 38025)):
#0  0x0000003754ebb5a7 in sched_yield () from /lib64/libc.so.6
#1  0x00007f1444a267e9 in ParallelTaskTerminator::yield() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#2  0x00007f14447fbfc9 in ParallelTaskTerminator::offer_termination() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#3  0x00007f1444c7fa87 in CMSRefProcTaskProxy::do_work_steal(int, CMSParDrainMarkingStackClosure*, CMSParKeepAliveClosure*, int*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#4  0x00007f1444c776e5 in CMSRefProcTaskProxy::work(int) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#5  0x00007f1444b40e2a in GangWorker::loop() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#6  0x00007f1444af8e98 in GangWorker::run() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#7  0x00007f1444af8278 in java_start(Thread*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#8  0x000000375560677d in start_thread () from /lib64/libpthread.so.0
#9  0x0000003754ed49ad in clone () from /lib64/libc.so.6
Thread 218 (Thread 0x40a3c940 (LWP 38026)):
#0  0x00007f1444751b60 in SpinPause@plt () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#1  0x00007f14447fbf09 in ParallelTaskTerminator::offer_termination() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#2  0x00007f1444c7fa87 in CMSRefProcTaskProxy::do_work_steal(int, CMSParDrainMarkingStackClosure*, CMSParKeepAliveClosure*, int*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#3  0x00007f1444c776e5 in CMSRefProcTaskProxy::work(int)() from /opt/taobao/install
/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#4  0x00007f1444b40e2a in GangWorker::loop() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#5  0x00007f1444af8e98 in GangWorker::run() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#6  0x00007f1444af8278 in java_start(Thread*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#7  0x000000375560677d in start_thread () from /lib64/libpthread.so.0
#8  0x0000003754ed49ad in clone () from /lib64/libc.so.6
Thread 217 (Thread 0x40277940 (LWP 38027)):
#0  0x00007f1444871b29 in SpinPause () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#1  0x00007f14447fbf09 in ParallelTaskTerminator::offer_termination() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#2  0x00007f1444c7fa87 in CMSRefProcTaskProxy::do_work_steal(int, CMSParDrainMarkingStackClosure*, CMSParKeepAliveClosure*, int*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#3  0x00007f1444c776e5 in CMSRefProcTaskProxy::work(int) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#4  0x00007f1444b40e2a in GangWorker::loop() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#5  0x00007f1444af8e98 in GangWorker::run() () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#6  0x00007f1444af8278 in java_start(Thread*) () from /opt/taobao/install/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#7  0x000000375560677d in start_thread () from /lib64/libpthread.so.0
#8  0x0000003754ed49ad in clone () from /lib64/libc.so.6



一眼就可以看出这些都是CMS GC的线程. 他们都停留在CMSRefProcTaskProxy::work下, GC的stack看上去还正常.奇怪的是为什么这么占CPU, 看样子一直在自旋(spin)或yield, 貌似在等待啥状态完成. 自旋锁是占CPU的利器.
要了一份gc log后,  看看gc log是否有啥线索. 发现一个非常诡异的地方:

引用
2012-10-30T11:44:56.808+0800: 2603.044: [CMS-concurrent-mark: 0.314/0.374 secs] [Times: user=0.45 sys=0.02, real=0.37 secs]
2012-10-30T11:44:56.808+0800: 2603.044: [CMS-concurrent-preclean-start]
2012-10-30T11:44:56.811+0800: 2603.047: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2012-10-30T11:44:56.811+0800: 2603.047: [GC[YG occupancy: 13211 K (917504 K)]2603.047: [Rescan (parallel) , 0.0113650 secs]2603.059: [weak refs processing



    GC log没有remark, 更没有sweep阶段, 停留在了weak refs processing. 这一阶段正在回收弱引用, 属于remark阶段的一部分, 所以会暂停java应用(stop the world)的. 日志与pstack正好吻合, 正在做处理引用 (CMSRefProcTaskProxy)．但处理引用, 为什么会使jvm hang住, 并且不停地自旋等待某状态完成呢?
    我用google查了一下, OTN上有两个人碰到了相同的问题: 链接一 链接二

    从上面的两个链接上看, 没有人能解释这个现象. 但有一个线索, 可以解决这个问题:

引用
Thank you for the advice. Unfortunatly, we are tied to old UTF behaviour which has been changed since 6u11. But, we have turned off ParallelRefProcEnabled and it looks like it helps. So, we are staing with it.



把ParallelRefProcEnabled参数给关闭就可以解决这个问题. 这是并行处理引用的参数,可以使用多GC线程处理引用. 我用

Shell代码 复制代码  收藏代码
  1. java -XX:+PrintFlagsFinal | grep ParallelRefProcEnabled  
java -XX:+PrintFlagsFinal | grep ParallelRefProcEnabled


查看了一下, 它的默认值是false, 也就是默认关闭了. 向应用方要了一份JVM参数后发现, 线上这个参数是开着的.

    开启这个参数为什么会使CMSRefProcTaskProxy一直在自旋, 从而停止Java应用, 并用占用所有的CPU资源呢? 再次请教google大神, 用”ParallelRefProcEnabled hang”发现了这个 jvm的bug, 上面写着

引用
The CMSRefProcTaskProxy object needs its terminator object to be initialized to the correct number of threads. Otherwise, you get a hang or crash.


    reference processing线程个数与ParallelGCThreads参数来一样, 刚好此应用将ParallelGCThreads设为了4, 所以对应了pstack看到4个线程在处理引用的情况.  再次咨询了JVM团队,理解那句话的意思. 以上的terminator object是用来同步和管理gc线程的对象. 它会记录到目前为止已经完成的线程数_complete_threads , 当一个gc线程干完活后，他会把数_complete_threads+1，当terminator object确定已经完成的线程数_complete_threads==预先设置的所有的gc线程数_n_thread，所有的gc线程就会退出，否则其他的gc线程就会等待. 悲剧的是_n_thread在构造时为0, 后面一直没有被重设过. 所以只需要开启ParallelRefProcEnabled就会出问题. 现在能解释通了, 并且从刚才的pstack我们还可以发现停留在ParallelTaskTerminator::offer_termination()方法, 是这表示当前的gc线程没事干, 一直等待GC Terminator通知它结束, 所以它一直处于自旋锁的状态, 所以CPU才会这么高.
简单地关闭掉了ParallelRefProcEnabled之后, 以上这个现象就不会出现了. 这个bug在JDK7中已经解决, 根据应用团队的反馈, 线上此应用的机器有部分是JDK6u26,还有JDK6u30都出现过相同的现象. 官方说明JDK6u32已经fix掉这个bug, patch中显示_n_thread已经被正确地设为ygc的线程数,所以直到6u32的版本才能放心使用这个参数.



已有 0 人发表留言，猛击->> 这里<<-参与讨论


ITeye推荐



相关 [jvm 参数 cmsrefproctaskproxy] 推荐：

警惕使用jvm参数CMSRefProcTaskProxy

- - Java - 编程语言 - ITeye博客
    昨天中午的时候, 团队的兄弟找我看一个现象: 原先因为堆外内存使用过多会crash掉的java应用, 设置了最大堆外内存量(MaxDirectMemorySize)后jvm不会crash, 但出现了机器的两颗CPU全部被占满, 而且java程序没有响应的情况.     我用jstat -gc/-gcutil/-gccause查了一下当时gc的情况, 发现出现过CMS GC, 最后一次导致GC的原因是CMS final remark, 没有什么异常.

JVM参数设置

- - 企业架构 - ITeye博客
-Xms768m -Xmx1280m  jvm堆的最小值和最大值设置，一般设成相同值，避免频繁分配堆空间. -XX:NewSize=128m -XX:MaxNewSize=128m  年轻代最小值和最大值设置（年轻代设定了，年老代也就定了），也可以用参数-XX:NewRatio=4，年老代和年轻代的大小比，这里128m有点小了，官方建议的是heap的3/8，差不多280m.

JVM内核参数说明

- - 编程语言 - ITeye博客
java虽然是自动回收内存，但是应用程序，尤其服务器程序最好根据业务情况指明内存分配限制. 表示JVM Heap(堆内存)最小尺寸128MB，初始分配. 表示JVM Heap(堆内存)最大允许的尺寸256MB，按需分配. 说明：如果-Xmx不指定或者指定偏小，应用可能会导致java.lang.OutOfMemory错误，此错误来自JVM不是Throwable的，无法用try...catch捕捉.

HotSpot JVM 触发 OutOfMemoryError 参数

- - 编程语言 - ITeye博客
正好今天是愚人节，就来说点骗子的东西吧~. 时不时的我就会听见有人抱怨说，他的HotSpot JVM不停的在垃圾回收，可是每次回收完后堆却还是满的. 当他们发现这是因为JVM的内存已经不够了之后，通常会问这么个问题，为什么JVM不抛一个OutOfMemoryError(OOME)呢. 毕竟来说，由于内存不足，我的程序都已经没法继续跑了，对吧.

JVM理论与实践【JVM参数调优】

- - ITeye博客
         在生产环境下对Java虚拟机JVM进行参数调优是必不可少的. 作为普通的开发人员，如果对JVM的参数优化有一定的了解，即使是从知识体系的完整性来考虑也是大有裨益的. 另外，了解JVM的运行原理也有助于编写性能良好的程序，而不是让代码成为服务器CPU和内存的杀手. 【Windows平台的参数调优】.

JVM系列三:JVM参数设置、分析

- - zzm
 不管是YGC还是Full GC,GC过程中都会对导致程序运行中中断,正确的选择 不同的GC策略,调整JVM、GC的参数，可以极大的减少由于GC工作，而导致的程序运行中断方面的问题，进而适当的提高Java程序的工作效率. 但是调整GC是以个极为复杂的过程，由于各个程序具备不同的特点，如：web和GUI程序就有很大区别（Web可以适当的停顿，但GUI停顿是客户无法接受的），而且由于跑在各个机器上的配置不同（主要cup个数，内存不同），所以使用的GC种类也会不同(如何选择见 GC种类及如何选择).

jinfo 查看、设置JVM参数

- - ITeye博客
 请确认当前执行jinfo的命令的用户有 /tmp/hsperfdata_$USER/$PID 文件的权限.  另外，jinfo可能在未来的jvm中移除. 已有 0 人发表留言，猛击->> 这里<<-参与讨论. —软件人才免语言低担保 赴美带薪读研.

Java虚拟机（JVM）参数简介

- - ITeye博客
Java虚拟机（JVM）参数简介. 在Java、J2EE大型应用中，JVM非标准参数的配置直接关系到整个系统的性能. JVM非标准参数指的是JVM底层的一些配置参数，这些参数在一般开发中默认即可，不需要任何配置. 但是在生产环境中，为了提高性能，往往需要调整这些参数，以求系统达到最佳新能. 另外这些参数的配置也是影响系统稳定性的一个重要因素，相信大多数Java开发人员都见过“OutOfMemory”类型的错误.

Java 6 JVM参数配置说明

- - Java - 编程语言 - ITeye博客
-XX:+

tomcat下jvm参数配置详解

- - 博客园_首页
在解释下面知识之前，一个很重要的知识点必须了解，那就是tomcat本身是不能直接运行在计算机上的，必须依赖硬件基础上的计算机和一个java虚拟机，这也就解释了为什么在安装运行tomcat前必须要安装jvm的原因了. 所以说如果运行一个比较大的应用程序的话，一个性能高的jvm和合适的参数配置对程序的性能影响很大，因为Sun公司和其它一些公司一直在为提高性能而对java虚拟机做一些升级改进.