转载

深入JVM彻底剖析ygc越来越慢的原因（上）

今天一个同学问我：“我排查问题时总是遇到，jmap -heap或-histo 不能用，是不是我们机器配置有啥问题哇？ ”

分享下这个case的解决过程。

登上同学说的那台不能用的机器，执行jstack，报错： get_thread_regs failed for a lwp ，这个问题以前碰到过，但忘了当时是什么原因了，执行其他的 jmap -histo 什么也卡着不动。

既然jstack没法弄，就pstack看看进程到底什么状况吧，于是pstack [pid]看，发现有一个线程的堆栈信息有点奇怪：

/#0  0x00000038e720cd91 in sem_wait ()

对系统函数不太懂，但总觉得 sem_wait 这个有点奇怪，于是Google之，基本明白了这个是由于进程在等信号，这个时候通常会block住其他所有的线程，于是立刻ps看了下进程的状态，果然进程的状态变成了T，那上面碰到的所有现象都很容易解释了，于是执行： kill -CONT [pid] ，一切恢复正常。

继续查为什么进程状态会变成T，问问题的同学告诉了下我他在机器上执行过的一些命令，我看到其中一个很熟悉的命令： jmap -heap ，看过我之前文章的同学估计会记得我很早以前分享过，在用cms gc的情况下，执行 jmap -heap 有些时候会导致进程变T，因此强烈建议别执行这个命令，如果想获取内存目前每个区域的使用状况，可通过 jstat -gc 或 jstat -gccapacity 来拿到。

到此为止，问题终于搞定，以后碰到jstack/jmap等不能用的时候，可以先看看进程的状态，因此还是那句话，执行任何一句命令都要清楚它带来的影响。

手头还有另外一个case，折腾了一个多星期了还是没太有头绪，case的现象是ygc越来越慢，但可以肯定不是由于cms gc碎片问题造成的，感兴趣的同学可以拿这个case去玩玩，如果能告诉我原因就更好了:)，执行下面的代码，启动参数可以为“-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC：”

import com.thoughtworks.xstream.XStream;  public class XStreamTest {      public static void main(String[] args) throws Exception {         while(true){             XStream xs = new XStream();             xs.toString();             xs = null;         }     }  }

应该就可以看到ygc的速度从10+ms一直增长到100+ms之类的…

针对这个case，有位同学看到这个后周末时间折腾了下，把原因给分析出来了，分析过程很赞。非常感谢这位同学（阿里的一位同事，花名叫彦贝），在征求他的同意后，我把他写的整个问题的分析文章转载到这里。

上分析工具VisualVM

在解决很多问题的时候，工具起的作用往往是巨大，很多时候通过工具分析，很快便能找到原因，但是这次并没有，下图是VisualVM观察到Heap上的GC图表。

深入JVM彻底剖析ygc越来越慢的原因（上）

从图标中可以看出，Perm区空间基本水平，但是Old区空间成增长态势与YGCT时间增长的倍率基本一直。熟悉YGC的朋友都知道YGC主要分为标记和收回两个阶段，YGCT也是基于这2个阶段统计的。由于每次回收的空间大小差不多，所以怀疑是标记阶段使用的时间比较长，下面回顾一下JVM的垃圾标记方式。

JVM垃圾回收的标记方法：枚举根节点

在Java语言里面，可作为GC Roots的节点主要在全局性的引用（例如常量或类静态属性）与执行上下文（例如栈帧中的本地变量表）中。如果要使用可达性分析来判断内存是否可回收的，那分析工作必须在一个能保障一致性的快照中进行——这里“一致性”的意思是整个分析期间整个执行系统看起来就像被冻结在某个时间点上，不可以出现分析过程中，对象引用关系还在不断变化的情况，这点不满足的话分析结果准确性就无法保证。这点也是导致GC进行时必须“Stop The World”的其中一个重要原因，即使是号称（几乎）不会发生停顿的CMS收集器中，枚举根节点时也是必须要停顿的。

由于目前的主流JVM使用的都是准确式GC，所以当执行系统停顿下来之后，并不需要一个不漏地检查完所有执行上下文和全局的引用位置，虚拟机应当是有办法直接得到哪些地方存放着对象引用。在HotSpot的实现中，是使用一组成为OopMap的数据结构来达到这个目的，在类加载完成的时候，HotSpot就把对象内什么偏移量上是什么类型的数据计算出来，在JIT编译过程中，也会在特定的位置记录下栈里和寄存器里哪些位置是引用。这样GC在扫描时就就可以直接得知这些信息了。上面这段引用自《深入理解Java虚拟机》，用个图简单表示一下，当然图也是源于书中：

深入JVM彻底剖析ygc越来越慢的原因（上）

基于对GC Roots的怀疑，猜测Old区中存在越来越多的gc root节点，那什么样的对象是root节点呢？不懂的我赶紧google了一下。

深入JVM彻底剖析ygc越来越慢的原因（上）

（不要看我红色圈出来了，第一次看到这几个嫌疑犯时我也拿不准是哪个）

为了进一步验证是Old区的GC Roots造成YGCT 增加的，我们来做一次full gc，干掉Old区。代码如下：

public class SlowYGC {   public static void main(String[] args) throws Exception {   int i= 0;   while (true) {   XStream xs = new XStream();   xs.toString();   xs = null;   if(i++ % 10000 == 0)   {   System.gc();   }   }   }   }

可以看出Full GC后 YGCT锐减到初始状态。那是Full GC到底回收了哪些对象？进入到下一步，增加VM参数。

增加VM参数

为了看到Full GC前后对象的回收情况，我们增加下面2个VM参数

-XX:+PrintClassHistogramBeforeFullGC
-XX:+PrintClassHistogramAfterFullGC 。

重新运行上面的代码，可以观察到下面的日志：

(点击放大图像)

深入JVM彻底剖析ygc越来越慢的原因（上）

上图左边是FGC前的对象情况，右边是FGC后的情况，结合我之前给出的GC Root候选人中的Monitor锁，相信你很快就找到20026个 Ljava.util.concurrent.ConcurrentHashMap$Segment 对象几乎被全部回收了，ConcurrentHashMap中正是通过Segment来实现分段锁的。那什么逻辑会导致出现大量的Segment锁对象。继续看Full GC日志 com.thoughtworks.xstream.core.util.CompositeClassLoader 这个对象也差不多在FGC的时候全军覆没，所以怀疑是ClassLoader引起的锁竞争，下面在ClassLoader的源码中继续查找。

ClassLoader中的ConcurrentHashMap

深入JVM彻底剖析ygc越来越慢的原因（上）

这里有个拿锁的动作，跟进去看看呗。

深入JVM彻底剖析ygc越来越慢的原因（上）

为了验证走到这块逻辑下了一个断点。剩下的就是putIfAbsent方法（这里就不详细分析实现了）有兴趣的同学可以看看源码中CAS和tryLock的使用。

至此基本分析和定位出了YGCT原因，在去看看Xstream的构造函数。

深入JVM彻底剖析ygc越来越慢的原因（上）

可以看出每次 new XstreamI() 的同时会new一个新的ClassLoader，基本上证明了上述怀疑和猜测。

推导一下按照上述分析，应该是所有自定义的ClassLoader都会YGCT变长的时间问题，于是手写一个ClassLoader验证一下。Java代码如下：

public class TestClassLoader4YGCT {   public static void main(String[] args) throws Exception{   while(true)   {   Object obj = newObject();   obj.toString();   obj = null;   }   }  private static Object newObject() throws Exception   {   ClassLoader classLoader = new ClassLoader() {   @Override   public Class <!--?--> loadClass(String s) throws ClassNotFoundException {   try{   String fileName = s.substring(s.lastIndexOf(“.”) + 1)+ “.class”;   InputStream inputStream = getClass().getResourceAsStream(fileName);   if(inputStream == null){   return super.loadClass(s);   }   byte[] b = new byte[inputStream.available()];   inputStream.read(b);   return defineClass(s,b,0,b.length);   }catch (Exception e)   {   System.out.println(e);   return null;   }   }   };   Class <!--?--> obj = classLoader.loadClass(“jvmstudy.classload.TestClassLoader4YGCT”);   return obj.newInstance();   }   }   VM 参数-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC

GC日志

(点击放大图像)

深入JVM彻底剖析ygc越来越慢的原因（上）

结论

当大量new自定义的ClassLoader来加载时，会产生大量ClassLoader对象以及parallelLockMap（ConcurrentHashMap）对象，导致产生大量的Segment分段锁对象，大大增加了GC Roots的数量，导致YGC中的标记时间变长。如果能直接看到YGCT的详细使用情况，这个结论会显得更加严谨。这只是我自己的一个推导，并不一定是正确答案。

感谢魏星对本文的审校。

给InfoQ中文站投稿或者参与内容翻译工作，请邮件至editors@cn.infoq.com。也欢迎大家通过新浪微博（@InfoQ，@丁晓昀），微信（微信号： InfoQChina ）关注我们。

原文 http://www.infoq.com/cn/articles/thorough-jvm-thorough-analysis-ygc-part01

正文到此结束