想知道垃圾回收暂停的过程中发生了什么吗？查查垃圾回收日志就知道了！

关键点

• 垃圾回收日志中包括着一些关键性能指标；
• 要做一次正确的垃圾回收分析需要收集许多数据，所以好的工具是非常必要的；
• 除了垃圾回收之外还有很多事件都可能会让应用程序暂停；
• 让你的应用程序暂停的事件也会让垃圾回收器暂停；
• 要发现到底是什么原因导致了性能上的回退，需要有正确的分析方法；

我最近收到了一份非常难得一见的垃圾回收日志，其中包含了一次长达整整 23.785173 秒的垃圾回收暂停事件。发生很长时间的垃圾回收暂停事件并非罕见，但这一次的事件却与你常常可以看到的那些不同。与大多数日志不同的是，这份日志中包含了足够详细的信息，它足以让我确认是 JVM 外部的一些东西导致了这次暂停，如果我们真的要把它当作一次暂停事件的话。

我把这份日志给 Heinz Kabutz 博士看了，他问道：“这是不是在 386 上跑出来的？”当然了他是在和我开玩笑，但这个问题却很有意义。尽管有许多文章详细讨论过垃圾回收的原理，大多数却仅仅是在讨论一些最基础的分析方法而已，很少有能超过这个范畴很多的。

分析的方法可以让我们看得更深入，了解是什么出错了，以及我们该做些什么来保证它不再发生。咱们再一起深入地查看一下这份日志，看看为什么我说垃圾回收机制其实并不是这次“垃圾回收暂停”事件的起因。

在这个案例中，日志文件异乎寻常的小，里面包含了 22 次垃圾回收事件，却只有 678 行日志。大多数分析师在查看这么小的日志的时候都给不出什么有价值的分析结果。相反，另一份同一天收到的日志却更有代表性，它里面包含了 14110 次垃圾回收事件，藏在了 959962 行日志中。除了要处理的日志量带来的问题之外，还有大概 60 种不同的 JVM 参数会影响垃圾回收日志的格式，而且每种不同的参数组合都会产生各自不同的影响。除此之外，这些日志的格式还会不断地以各种意想不到的方式发生变化。

还有，在 Java 9 之前，垃圾回收日志并不是线程安全的，这意味着如果你使用了并发回收器的话，日志有可能是损坏的。把这些因素放在一起考虑，你就会发现你面前要分析的日志不管对于人类还是机器来说，都是不可读的。

我发起研发 jClarity 的 Censum 垃圾回收日志分析工具的初衷，就在于我希望可以尝试去做分析，还有我的确需要可以从尽可能多种不同的数据源中得到垃圾回收日志，并抽取到有用的信息。

在这个例子中我们用的是推荐参数的最小集合：

-Xloggc:gc.log
-XX:+PrintGCDetails
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCApplicationConcurrentTime
 

做分析最简单的方式就是直接把日志导入 Censum 之中。图一所展示的就是所有运行过的分析的总结。首先要注意的是，在各项分析中有两项是失败的，并用红色的打叉图标做出了标记。再看看这些分析结果，就会知道 Censum 已经对情况做出了判断。要把失败了的分析手动重做一次只要一分钟就可以了，但首先咱们还是先看看 Censum 的分析总结，以及“Heap after GC”图表。

(点击放大图像)

图一：分析总结

两个视图都可以帮我们了解两次失败了的分析的背景。从图二的总结页面可以看出这里使用了并发回收器。共有21 次年轻代回收和一次完全回收。这个视图中的其它指标都没有太多好说的，或者说是在可接受的范围之内。比如应用程序99.3% 的吞吐量是远高于要求的95% 的阈值的，而每秒1165KByte 的分配率也是远低于每秒1GByte 的阈值。如果超出了前一个阈值，就意味着垃圾回收机制配置得不够好（那种情况下会触发我们称之为垃圾回收器的“技术调节”的事件，但那是另一篇文章的主题），而如果超出了后面的阈值则意味着你的应用程序内存不足了，应该判断并优化内存分配的热点，当然这又是再一篇文章的主题了。

(点击放大图像)

图二：Censum 总结视图

这个例子中的“Heap after GC”页表明堆也成了完整的垃圾回收过程的一部分。别的回收过程看起来都没什么，堆的使用情况看起来也还很稳定。总的堆大小在700MB 到800MB 之间波动。Tenured 相关的大小也很平稳的保持在520MB。这表明年轻代的大小在200MB 到300MB 之间。按照现在的标准来看，这些内存池的大小都特别小，所以Heinz 才会开那个386 的玩笑。这份日志中没有任何东西提到“23 秒的暂停”。咱们再去看看那些失败了的分析，看看为什么会失败，看看这是不是导致长期暂停的原因。

第一个失败了的分析是简单的暂停时间分析。因为暂停的时间太长了，所以它才会失败。考虑到总的花费比较小（在这次分析中叫做“Time Paused”），这次长时间的暂停就表现得特别显眼，需要深入调查。

因为PrintGCDetails 被打开了，所以我们可以注意到一条有价值的信息，就是垃圾回收线程的CPU 利用率。这些总结包括垃圾回收线程在回收过程中消耗的用户态时间、内核态时间和实际时间等。这就是“High Kernel times”分析要使用的数据。图三显示了这个视图。

(点击放大图像)

图三：High Kernel times 视图

CPU 总结中的对高内核态时间的分析为解决问题提供了许多启示，可以鉴别出值超出了正常范围的用例。这些分析让开发者们可以以各种不同的专业水平去查看垃圾回收日志，看出那些他们可能遗漏了的问题。人们在查看这些图表时可能碰到的问题仅仅是不熟悉这些数据的展示方式而已。即使数据展示得很恰当，也有可能会包含一些让人困惑的信息，或者掩盖掉某些不同的条件。就算没有这些信息来打扰，我们人类也会带着偏见来看这些结果，总是想要看到些并不存在的东西。用启发式算法可以有助于克服主观的推断。回到我们的例子上来，通过查看用户态时间和实际时间的测量值，我们就可以估计出垃圾回收周期内的并行度。我们也可以判断出垃圾回收线程累积的内核态时间是什么时候超出正常范围的。

每个线程都维护着若干个性能计数器，用于跟进用户态和内核态时间等不同的指标。垃圾回收器会从各个不同的垃圾回收线程中收集这些计数器的值，并在垃圾回收日志记录的末尾打印总结信息。操作系统会维护这些性能计数器的值。它会在每个采样点进行采样，判断每个线程当前运行在什么模式下，进而相应地增加用户态或内核态计数器的值。一般来说垃圾回收线程会运行在用户态模式下，这意味着大多数的计数都应归于用户态模式下。然而，当垃圾回收线程执行系统调用时，它就会进行模式转换，成为一个内核态线程。当线程运行在这个保护模式之下时，所有的采样值都会属于内核态时间。这些系统调用正常情况下都会是在请求内存中的某个页面，或者将某些热点性能数据落盘。但因为请求一个新的页面本应很快，而写出的热点数据量也应该是极少的，所以垃圾回收线程的内核态时间计数值不应该很高。可是，如果出于某些原因，这些操作执行的时间超出了期望的时间，这些线程计数器就会计下更多的内核态时间值。

比如，一种常见的情况是当一台物理机上运行了多个 JVM 时，它们每一个都会打印出非常大量的日志。在这个案例中，IO 通道特别慢，它拖累了垃圾回收线程执行写系统调用的时间。在这期间进行的任何 CPU 采样都会归于内核态时间。而当内核在管理页面时，别的垃圾回收线程也会被记录进内核态模式。当然，这本不该导致垃圾回收线程积累太多的内核态时间，但在系统内存不足的时候，内核态时间就会增加了。这些问题都可能会干扰回收器的执行，但它们也会影响你的程序的整体执行性能。对内核态时间简单地查看一下，就可以帮助我们判断是否有什么干扰了回收器的执行，让它没办法在短时间内完成应该完成的任务。

在我们的案例中，Censum 也只在一个用例中报告了内核态时间高。另外，它还报告收集器曾有 18 次是单线程运行的。因为总共有 22 次回收任务，这就足以证明回收器不是导致这次长时间暂停的主要原因。

看看图四中的 CPU 总结视图，就可以很快地在左上角发现这次长时间暂停事件。回收发生在一堆事件的中间，因此很难把所有情况都了解明白。而且也很明显，实际执行时间远比用户态时间或内核态时间长，这很奇怪。

(点击放大图像)

图四：CPU 总结

当放大图四时我们可以看到，大概有0.08 秒的用户态时间和0.02 秒的内核态时间。现在的问题是，0.08 + 0.02 = 0.10 秒的用户态和内核态时间和怎么能对应上23 秒的实际时间，即使假设0.08 秒的用户态时间都是由单线程累积起来的也不行。（在多线程的情况下就会更混乱，因为这0.08 秒还要被多个线程去均分。）通常在多线程的情况下，多个线程积累的用户态时间会比实际时间更长，所以这个情况看起来非常混乱。很明显系统中发生了什么事，让垃圾回收线程无法运行完22 秒。换句话说，JVM 之外的某些东西导致了这次暂停，在这个案例中是操作系统维护，也就是说垃圾回收日志转移了我们的视线而已。

(点击放大图像)

图五：CPU 总结放大图

结论

Lawrence Kraus 曾经说过，“有两种我特别喜欢的状态，就是困惑和出错，因为只有在这些情况下才会有学习的机会”。在这个案例中，我们开始误以为是垃圾回收操作是这次长时间暂停的原因，但在我们认真查看了垃圾回收日志之后，我们才纠正了一出现长时间暂停就去埋怨垃圾回收器的偏见。在我们归咎于垃圾回收器时，最正常的反应就是上网搜贴子，查看是不是有哪个偏门的 JVM 参数可以帮忙解决这样莫名其妙的问题。在做这样的分析时，我们却直接发现垃圾回收器不是主因，那接下来要问的问题就是，排除了垃圾回收器之后，又该调查谁？

上面发现的证据表明，在出现暂停时的绝大部分时间内，垃圾回收线程并不活跃。如果暂停是后台的 IO 操作导致的，那由操作系统调用的垃圾回收线程就该累积起很长时间的内核态时间才对，但事实上并没有。这些都排除了垃圾回收线程的可能性，而且它们甚至长达 22 秒没被调用过。如果我们的程序不是被垃圾回收线程拖累的，那尽管看起来说不通，剩下唯一的可能性就是 JVM 是被操作系统暂停的。

事实是，操作系统时常也会自动做维护，在做维护时，表象和垃圾回收线程一样，操作系统也会将所有其它事务暂停。就像调校好的垃圾回收器也会出现暂停一样，操作系统暂停也必然会不定期地发生，而且几乎不会被注意到。有的时候暂停也会持续很久。比如，据说有一次一个垃圾回收器的页面分配请求等了几秒钟才被处理到。在这些案例中，通常原因都是操作系统正在将内存中的数据移来移去，以便得到足够的空闲内存去满足将来的请求。

尽管在这个案例中看起来不像，我们以前也有好几次发现网络时间协议（Network Time Protocol，NTP）在垃圾回收的过程中调整时钟。一般在时钟向前调整的时候我们才能确认是这种情况，日志会显示垃圾回收先结束后开始。如前所述，这在这个案例中也还是不太可能，因为时钟调整一般每次都只调整几微秒，不会一次调整几十秒。

总之，最重要的发现就是对垃圾回收过程的分析可以帮助我们避免直觉性地怪罪垃圾回收器，让我们可以视野更开阔些，发现些更重要的东西，帮助我们提升应用程序的性能和稳定性。

关于作者

Kirk Pepperdine是最早 Java 性能调校研讨会的发起者，他曾经分析过垃圾回收原理和许多其它的 Java 性能问题。他也与别人一起成立了 jClarity，这家公司研发的是用机器学习技术支撑的性能分析工具，以此来帮忙诊断复杂的性能回退问题。

阅读英文原文： Want to Know What’s in a GC Pause? Go Look at the GC Log!