转载

JVMTI对象标记对GC的影响

Published: 06 Feb 2015 Category: JVM

本文主要是想分析下为什么Plumbr代理在特定的场景下会对GC的暂停时间产生影响，以及影响究竟有多大。在排查这个故障的过程中，我们还发现，在GC暂停的时候，JVMTI（JVM Tool Interface）的打标记操作存在一些有趣的现象。

问题定位

我们的一位客户抱怨说当他们的应用程序连接上我们的Plumbr代理之后响应速度会明显变慢。在检查了GC日志之后，我们发现GC的时间存在异常。下面是没有使用Plumbr的情况下从JVM中提取出来的GC日志：

2015-01-30T17:19:08.965-0200: 182.816: [Full GC (Ergonomics)  [PSYoungGen: 524800K->0K(611840K)]  [ParOldGen: 1102620K->1103028K(1398272K)] 1627420K->1103028K(2010112K),  [Metaspace: 2797K->2797K(1056768K)], 0.9563188 secs]  [Times: user=7.32 sys=0.01, real=0.96 secs]

而下面是连接了Plumbr代理之后的日志：

2015-02-02T17:40:35.872-0200: 333.166: [Full GC (Ergonomics)  [PSYoungGen: 524800K->0K(611840K)]  [ParOldGen: 1194734K->1197253K(1398272K)] 1719534K->1197253K(2010112K),  [Metaspace: 17710K->17710K(1064960K)], 1.9900624 secs]  [Times: user=7.94 sys=0.01, real=1.99 secs]

异常就隐藏在这消逝的时间背后。实际时间（real time）指的是实际所消耗的时间。你可以看下你手上的腕表，实际时间对应的就是这个时间。而用户时间（user time，算上系统时间）指的是测量中消耗的总的CPU时间。如果有多个线程在多个核上同时工作的话，这个时间是要比实际时间长的。因此，对于Parallel GC而言，实际时间大约是等于（用户时间/线程数）。在我的机器上这个比率应该是接近7，而在没有使用Plumbr代理的情况下确实如此。但用了Plumbr之后，这个比率就明显下降了。看来确实是存在问题的！

初步调查

根据情况来看，我们很容易可以得出下面的推测：

Plumbr使得JVM在每次GC之后都做了一些比较重的单线程操作
Plumbr使得JVM用来进行GC的线程变少了

不过光看一行GC日志实在是很难得出什么结论，因此我们将前面提到的那个比率给可视化了一下：

link

当Plumbr发现内存泄露时，图中的比率便恰好出现了下跌。Plumbr进行根对象分析时的确是会给GC增加了一些额外的负担，但是对GC的暂停时间造成这种持续性的影响肯定不是我们设计这款代理工具的初衷。从现象来看，应该更倾向于第一种假设，因为我们这个代理应该不至于能影响到运行时的GC线程数。

要编写一个独立的测试用例还是挺费时间的。，不过如果增加了下面这些约束条件的话，倒也没那么困难：

应用程序必须能够产生Plumbr可以检测得到的内存泄露
应用程序必须频繁地中断来执行GC操作
。。还有就是，应用程序的存活对象集要足够大，也就是说能坚持过一轮Full GC的对象的数量必须得足够多。

开发完这个迷你的测试用例之后，现在我们可以开始排查问题了。将Plumbr代理的各个特性依次打开/关闭，然后再看一下问题是否能够重现，这听起来是个不错的主意。

通过这么一个简单的方法，我们最终将问题定位到了Plumbr代理所执行的一个操作上。在JVMTI的开关关掉之后，问题便消失了。我们在分析GC根对象及其引用的对象链的过程中，将堆中的每一个对象都打上了标记。显然，我们所打的这些标记或多或少地对GC产生了影响。

揪出问题的根源

但是，我们还是没搞清楚为什么GC的暂停时间会变长。垃圾回收已经足够快了，并且绝大多数标记过的对象也是符合回收的标准的。不过我们发现了一个问题，就是由于存活对象太多了(这也正是内存泄露的一个特征)，导致有许多不应该回收的都被打了标记。

不过，即便是存活对象集中的所有对象都打上了标记，也不应该会对GC时间产生线性的影响。GC完成之后，我们会收到关于这些打上标记且又被回收掉的对象的通知信息，不过存活对象并不在其列。这让我们不禁怀疑，Hotspot是否出于某种原因的考虑，在每次GC后都遍历了一次这些标记过的对象。

要想证实这一猜测可能你得读一下hotspot的源码。经过了一番钻研之后，我们最终在 JvmtiTagMap::do weak oops 中找到了这么一段代码，这里的确是遍历了所有的标记对象，并执行了许多并不是那么廉价的操作。更糟糕的是，这些操作还是顺序执行的，没有并行化。在GC完成后的调用链中发现的确是调用到了这一方法之后，最后的一个疑点也终于解开了。（至于JVM说什么要这么做，以及为什么要对弱引用进行这个操作已经超出了本文讲述的范围）。

在Parallel GC中居然有一个顺序执行的如此昂贵的操作看起来像是个设计缺陷。不过再仔细想一下，JVMTI的设计者估计也没想到有人会把堆中的所有对象都打上标记，因此他也没有想过要去优化这个操作，或者说将它作并行化。毕竟嘛，你永远也不可能知道用你这个特性的人是怎么使用它的，因此，检查下GC完成后的这些操作有没有必要进行并行化看来还是有点必要的。

那么为了解决这个问题，我们需要将那些不再需要的标记给清除掉。只要在我们的 JVMTI回调中加入三行代码就能解决这个问题了：

+  if(isGenerated(*tag_ptr)) { +    *tag_ptr = 0; +  }

还有你看，在完成一遍分析扫描后，我们的数据已经基本恢复正常了。正如下面这个截图所示，在检测内存泄露过程中有一个短暂的性能抖动，同时分析完成之后也有点轻微的性能下降：

link

结束语

这个补丁已经打出来了，Plumbr检测出内存泄露之后所导致的GC暂停时间增加的故障也得到了解决。现在你可以获取我们更新后的Plumbr代理来进行性能问题的追踪了。

顺便说一句，我建议在进行一些昂贵的标记操作时还是要谨慎一些，因为在某些个例中，“廉价”的标记累积起来所导致的性能损耗也是挺大的。如果想确认你自己是否滥用了这个标记特性，你可以打开-XX:+TraceJVMTIObjectTagging这个诊断开关。它会告诉你标记映射表到底消耗了多少本地内存以及遍历堆究竟花了多少时间。。。

正文到此结束