一次线上GC故障解决过程记录

排查了三四个小时，终于解决了这个GC问题，记录解决过程于此，但愿对你们有所帮助。本文假定读者已具有基本的GC常识和JVM调优知识，关于JVM调优工具使用能够查看我在同一分类下的另外一篇文章：

    http://my.oschina.net/feichexia/blog/196575

 

背景说明

    发生问题的系统部署在Unix上，发生问题前已经跑了两周多了。

    其中我用到了Hadoop源码中的CountingBloomFilter，并将其修改为了线程安全的实现（详情见：AdjustedCountingBloomFilter），主要利用了AtomicLong的CAS乐观锁，将long[]替换成了AtomicLong[]。这样致使系统中有5个巨大的AtomicLong数组（每一个数组大概占50MB），每一个数组包含大量AtomicLong对象（全部AtomicLong对象占据大概1.2G内存）。并且这些AtomicLong数组的存活时间都至少为一天。

    服务端已先于手机客户端上线，客户端原本计划本周四上线（写这篇文章时是周一），因此我还打算在接下来的几天继续观察下系统的运行情况，开启的仍然是Debug级别日志。

    部分JVM参数摘抄以下（JVM参数配置在项目部署的tomcat服务器的根目录下的bin目录下的setenv.sh中，能够经过ps -ef | grep xxx | grep -v grep查看到）：

-XX:PermSize=256M -XX:MaxPermSize=256M -Xms6000M -Xmx6000M -Xmn1500M -Xss256k -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+DisableExplicitGC -XX:+CMSParallelRemarkEnabled -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:CMSFullGCsBeforeCompaction=5 -XX:+UseCMSCompactAtFullCollection -XX:+CMSScavengeBeforeRemark -XX:+HeapDumpOnOutOfMemoryError -Xloggc:/usr/local/webserver/point/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime-XX:PermSize=256M -XX:MaxPermSize=256M -Xms6000M -Xmx6000M -Xmn1500M -Xss256k -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+DisableExplicitGC -XX:+CMSParallelRemarkEnabled -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:CMSFullGCsBeforeCompaction=5 -XX:+UseCMSCompactAtFullCollection -XX:+CMSScavengeBeforeRemark -XX:+HeapDumpOnOutOfMemoryError -Xloggc:/usr/local/webserver/point/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

    能够看到持久代被设置为256M，堆内存被设置为6000M（-Xms和--Xmx设为相等避免了“堆震荡”，能在必定程度减小GC次数，但会增长平均每次GC消耗的时间），年轻代被设置为1500M。

    -XX:+UseConcMarkSweepGC设置老年代使用CMS（Concurrent Mark-Sweep）收集器。 -XX:+UseParNewGC设置新生代使用并行收集器，-XX:ParallelGCThreads参数指定并行收集器工做线程数，在CPU核数小于等于8时通常推荐与CPU数目一致，但当CPU核数大于8时推荐设置为：3 + [(5*CPU_COUNT) / 8]。其余参数略去不提。

 

问题发现与解决过程

    早上测试找到我说线上系统忽然挂了，报访问超时异常。

    首先我第一反应是系统内存溢出或者进程被操做系统杀死了。用ps -ef | grep xxx | grep -v grep命令查看进程还在。而后看tomcat的catlalina.out日志和系统gc日志，也未发现有内存溢出。

    接下来用jstat -gcutil pid 1000看了下堆中各代的占用状况和GC状况，发现了一个挺恐怖的现象：Eden区占用77%多，S0占用100%，Old和Perm区都有很大空间剩余。

    怀疑是新生代空间不足，但没有确凿证据，只好用jstack获取线程Dump信息，不看不知道，一看就发现了一个问题（没有发现线程死锁，这里应该是“活锁”问题）：

    从上面第一段可看到有一个Low Memory Detector系统内部线程（JVM启动的监测和报告低内存的守护线程）一直占着锁0x00....00，而下面的C2 CompilerThread一、C2 CompilerThread0、Signal Dispatcher和Surrogate Locker线程都在等待这个锁，致使整个JVM进程都hang住了。

    在网上搜索一圈，发现大部分都建议调大堆内存，因而根据建议打算调大整个堆内存大小、调大新生代大小（-Xmn参数）、调大新生代中Survivor区占的比例（-XX:SurvivorRatio参数）。而且因为存在AtomicLong数组大对象，因此设置-XX:PretenureThreshold=10000000，即若是某个对象超过10M（单位为字节，因此换算后为10M）则直接进入老年代，注意这个参数只在Serial收集器和ParNew收集器中有效。另外但愿大量的长生命周期AtomicLong小对象可以尽快进入老年代，避免老年代的AtomicLong数组对象大量引用新生代的AtomicLong对象，我调小了-XX:MaxTenuringThreshold（这个参数的默认值为15），即如今年轻代中的对象至多能在年轻代中存活8代，若是超过8代还活着，即便那时年轻代内存足够也会被Promote到老年代。有修改或增长的JVM GC参数以下：

-Xms9000M -Xmx9000M -Xmn1500M -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=8 -XX:PretenureSizeThreshold=10000000-Xms9000M -Xmx9000M -Xmn1500M -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=8 -XX:PretenureSizeThreshold=10000000

    重启系统后用jstat -gcutil pid 1000命令发现一个更恐怖的现象，以下图：Eden区内存持续快速增加，Survivor占用依然很高，大概每两分钟就Young GC一次，而且每次Young GC后年老代内存占用都会增长很多，这样致使能够预测每三四个小时就会发生一次Full GC，这是很不合理的。

    第二列是S1，占用高达87.45%，第三列是Eden区内存占用变化状况，能够看到增加很是快。

    因而我用jmap -histo:live（注意jmap命令会触发Full GC，并发访问量较大的线上环境慎用）查看了下活对象，发现有一些Integer数组和一些Character数组占用内存在持续增加，而且占了大概好几百M的内存，而后通过Young GC又降低，而后再次快速增加，再Young GC降低，周而复始。 

    至此，我推测多是大量的Integer数组对象和Character数组对象基本占满了Survivor，致使在Eden满了以后，新产生的Integer数组对象和Character数组对象不足以放入Survivor，而后对象被直接被Promote到了年老代，这种推测部分正确，它解释了S1占用那么高的缘由，但不能解释上面的Eden区内存占用持续上升。

    因而继续查看了下接口调用日志，不看不知道，一看吓一跳：日志刷新很是之快（99%是DEBUG日志）。原来运营和测试在未通知咱们服务端的状况下已经于昨天在某个渠道发布了一个Android线上版本（难怪今天就暴露问题了），再看了下使用该系统的用户已经有6400多个了，不折不扣被他们坑了一把。这就能解释为何上面有一个Integer数组和Character数组占用内存持续增加了，缘由就在于大量的系统接口调用触发了大量DEBUG日志刷新，写日志对于线上系统是一个重量级操做，不管是对CPU占用仍是对内存占用，因此高并发线上系统必定要记得调高日志级别为INFO甚至ERROR。

    因而修改log4j.properties中的日志级别为INFO，而后用jmap -histo:live pid命令查看活对象，发现Integer数组对象和Character[]数组对象明显降低，而且占用内存也由前面的几百M降到几M。

    以后再用jstat -gcutil pid 1000查看了下GC状况，以下：

    很明显Survivor占用没这么高了，最重要的Young GC后年老代内存占用不会增长了，此处Eden区增加貌似仍是挺快，由于此时用户数比前面多了不少。至此出现的问题基本搞定，但还有待后续观察。

 

总结

    总的来讲本系统中存在一个违背GC假设的东西，那就是在JVM堆中存在着海量生命周期较长的小对象（AtomicLong对象）。这无疑会给系统埋坑。

    GC分代基本假设是：

JVM堆中存在的大部分对象都是短生命周期小对象。JVM堆中存在的大部分对象都是短生命周期小对象。

    这也是为何Hotspot JVM的年轻代采用复制算法的缘由。

 

    其余推荐一些很是不错的GC方面的参考文章（前两篇都来自《深刻理解Java虚拟机》一书，参考连接大部分是我今天查阅的资料，你们选择性看就好）：

    JVM内存管理：深刻Java内存区域与OOM http://www.iteye.com/topic/802573

    JVM内存管理：深刻垃圾收集器与内存分配策略 http://www.iteye.com/topic/802638

    Oracle GC Tuning http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html

    Java 6 JVM参数选项大全 http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm

    Java HotSpot VM Options http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html

    CMS GC实践总结 http://www.iteye.com/topic/473874

    JVM内存的分配及回收 http://blog.csdn.net/eric_sunah/article/details/7893310

    一步一步优化JVM系列 http://blog.csdn.net/zhoutao198712/article/category/1194642

    Java线程Dump分析 http://www.linuxidc.com/Linux/2009-01/18171.htm http://jameswxx.iteye.com/blog/1041173

    利用Java Dump进行JVM故障诊断 http://www.ibm.com/developerworks/cn/websphere/library/techarticles/0903_suipf_javadump/

    Detecting Low Memory in Java https://techblug.wordpress.com/2011/07/16/detecting-low-memory-in-java/

    Detecting Low Memory in Java Part 2 http://techblug.wordpress.com/2011/07/21/detecting-low-memory-in-java-part-2/

    http://blog.sina.com.cn/s/blog_56d8ea9001014de3.html

    http://stackoverflow.com/questions/2101518/difference-between-xxuseparallelgc-and-xxuseparnewgc

    http://stackoverflow.com/questions/220388/java-concurrent-and-parallel-gc

    http://j2eedebug.blogspot.com/2008/12/what-to-look-for-in-java-thread-dumps.html

    https://devcenter.heroku.com/articles/java-memory-issues

    http://blog.csdn.net/sun7545526/article/category/1193563

    http://java.dzone.com/articles/how-tame-java-gc-pauses

原文连接：https://my.oschina.net/feichexia/blog/277391