怎么看gc日志
重要要点
- 垃圾收集日志包含关键性能指标。
- 您将需要大量数据来执行适当的GC分析； 好的工具至关重要。
- 除了GC外，还有许多其他事情可以使应用程序暂停。
- 无论暂停什么，应用程序都会暂停垃圾回收器。
- 分析对于揭示导致性能下降的因素至关重要
我最近收到了您很少见到的那种垃圾收集（GC）日志，其中包含一个GC暂停，总共需要23.785173秒。 尽管遇到GC长时间停顿的情况并不罕见，但这种特殊停顿并不是您花园中的长时间停顿。 与大多数日志不同，该日志包含足够的详细信息，可以让我确定JVM之外的某个因素导致了此暂停，即使实际上确实是暂停。
我与Heinz Kabutz博士共享了日志，他评论说：“这是在386上运行吗？” 尽管他的评论只是开个玩笑，但这确实引起了一个真正的问题。 在所有有关垃圾回收的文献中，几乎没有什么比最基本的分析技术涵盖得多。
这是不幸的，因为分析可以使我们更深入地了解发生了什么问题以及应该采取什么措施以确保不会再次发生。 让我们更深入地研究此GC日志，看看它如何告诉我GC不会造成如此长的“ GC暂停”。
在这种情况下，日志非常小，因为它包含以678条日志行表示的22个GC事件。 在这样小的日志上，分析很少会产生有意义的结果。 相比之下，同一天发布的更典型的日志包含被埋在959,962行中的14,110个GC事件。 除了能够处理此数据量的问题外，还有大约60种不同的JVM标志会影响GC日志的格式，并且每种标志组合都会以不规则的方式进行处理。 如果那还不够，记录格式可以并且确实以任意方式定期更改。
同样，在Java 9之前，GC日志记录也不是线程安全的，这意味着当您使用并发收集器时，日志将被破坏。 将所有这些加在一起，最终将不得不对既不是人类也不是机器可读的日志进行分析。
我想尝试分析，激发了我编写jClarity的Censum GC日志分析工具的动力，并且我需要能够从尽可能多的实际来源中从GC日志中提取有用的信息。
在这种情况下，使用了最少的推荐标志集： -Xloggc:gc.log
-XX:+PrintGCDetails
-XX:+PrintGCApplicationStoppedTime-XX:+PrintGCApplicationConcurrentTime
执行分析的最简单方法是将日志加载到Censum中。 呈现的第一个视图（图1）是已运行的所有分析的概述。 首先要注意的是，其中两个标记为红色x的分析失败了。 如果我们查看这些分析，就会发现Censum已经诊断出该病。 我们将在一分钟内手动处理失败的分析的细节，但首先让我们看一下Censum的摘要视图以及“ GC之后的堆”图表。
（点击图片放大）
图1.分析摘要
这两个视图都可以帮助将上下文带入失败的分析中。 摘要页面（图2）显示正在使用并行收集器。 有21个年轻的世代收藏和一个完整的收藏。 此视图中的其他指标没有什么变化，也未超出可接受的公差范围。 例如，99.3％的应用程序吞吐量远高于所需的95％阈值，而1165 KBytes / sec的分配速率远低于不可思议的1 GB / sec阈值。 超过前一个阈值表示GC配置不是最佳（它会触发我们所谓的垃圾收集器的“技术调整”，但这是另一篇文章的主题），而超过后者则表明您的应用程序是内存效率低下的问题，它应该提示分配热点的识别和破坏，这也是另一篇文章的主题。
（点击图片放大）
图2. Censum摘要视图
在这种情况下，“ GC之后的堆”图表显示该堆已作为完整GC的一部分进行了扩展。 到目前为止，所有其他集合看起来都很普通，堆占用率看起来很稳定。 此外，总堆大小在700到800兆字节之间波动。 使用权的观点认为它的大小相当稳定，为520兆字节。 这意味着年轻一代的大小在200到300兆字节之间。 按照今天的标准，这些内存池的大小异常小，这引起了亨氏386的笑话。 该日志中没有任何内容会跳出您并说“ 23秒暂停”。 让我们返回失败的分析，以查看失败的原因以及该原因是否可以解决长时间的停顿。
我们两个失败的分析中的第一个是简单的暂停时间分析。 它失败了，因为它检测到长时间的停顿。 考虑到总体上较低的开销（在此分析中表示为“暂停时间”），这种长时间的停顿似乎是一个离群值，需要进一步研究。
打开PrintGCDetails时发出的信息之一是GC线程的CPU使用率摘要。 这些摘要包含收集期间GC线程累积的用户时间，内核时间和实时时间。 “高内核时间”分析使用的就是此数据。 图3捕获了此GC日志的视图。
（点击图片放大）
图3.高内核时间
高内核时间分析将许多启发式方法应用于CPU摘要，可以识别值与预期规范不符的情况。 这样的分析功能使开发人员在熟练掌握GC日志的任何水平上，都可以查看他们可能会遗漏的问题。 人们在查看图表时遇到的一些困难可能仅仅是由于数据绘制方式造成的。 即使正确绘制，结果也可能包含视觉失真，可能会混淆或隐藏不同的条件。 即使没有这些扭曲，我们人类也会遭受偏见，并且我们倾向于看到不存在模式的模式。 使用启发式算法可以帮助克服这些主观推论。 回到我们的示例，通过查看用户和实时测量，我们可以估计GC周期中的并行度。 我们还可以确定GC线程何时累积了比正常情况更多的内核时间。
每个线程维护一组性能计数器，以使其能够跟踪不同的指标，包括用户和内核时间。 垃圾收集器将从每个GC线程中收集这些计数器，并在GC日志记录的末尾打印摘要。 操作系统要维护这些性能计数器。 通过对运行时间进行采样并在每个采样点进行采样，确定线程以哪种模式运行，然后相应地增加用户或内核计数器。 通常，GC线程在用户模式下运行，这意味着大多数计数应归因于该模式。 但是，GC线程确实会进行系统调用，并且在这种情况下，该线程会经历模式切换而成为内核线程。 当线程在此保护模式下运行时，所有样本都将归因于内核时间。 通常，这些系统调用是收集器请求内存中的页面或写入热点性能数据的结果。 但是由于请求新页面应该很快，并且写入磁盘的perf数据量很小，因此GC线程不应累积任何可测量的内核时间。 但是，如果由于任何原因操作所需的时间比预期的要长，则将为线程计数器分配更多的内核时间。
例如，常见的情况是在同一硬件上运行多个JVM，每个JVM记录大量数据。 在这种情况下，I / O通道可能会备份到一定程度，以至于它会使执行写系统调用的GC线程停顿下来。 在此停顿期间收集的任何CPU样本都将归因于内核时间。 另外，当内核管理页面时，GC线程也可以用内核时间标记。 同样，这不应导致GC线程累积内核时间，但是如果系统本身内存不足，它将导致累积。 这些问题中的任何一个都会干扰收集器，但也会干扰应用程序的整体性能。 对内核时间的简单检查可以帮助我们确定这是否干扰了收集器在最短时间内完成工作的能力。
在我们的案例中，Censum仅报告了内核时间较长的一种情况。 此外，它发现收集器似乎运行单线程18次。 鉴于总共有22个收藏，这充分表明收藏家对长时间的停顿不承担责任。
查看CPU Summary视图（图4），我们可以快速在左上角发现长时间的停顿。 收集发生在一系列事件的中间，这使得很难清楚地看到所有内容。 但是，很明显，实时时间比用户时间或内核时间长得多，这很奇怪。
（点击图片放大）
图4. CPU摘要
当我们放大时（图4），我们可以看到大约有0.08秒的用户时间和0.02秒的内核时间。 最大的问题是； 0.08 + 0.02 = 0.10秒的用户和内核时间如何转换为近23秒的实时时间； 即使假设0.080秒的用户时间是由一个线程累积的。 （如果涉及更多线程，则不一致甚至更大，因为将在这些线程之间分配0.08秒。）通常，多个线程将比实时积累更多的用户时间，因此这种情况完全是混乱的。 显然，系统中发生了一些事情，导致GC线程无法运行22秒。 换句话说，JVM外部的某种原因造成了这种暂停，在这种情况下，是操作系统维护，这意味着GC日志暂停时间报告是一团糟。
（点击图片放大）
图5.放大的CPU摘要
结论
用劳伦斯·克劳斯的话来说； “有两个好状态，混乱或错误，因为这些状态代表了学习的机会”。 在这种情况下，我们误以为GC导致了长时间的停顿，只有当我们仔细查看GC中的数据时，我们才摆脱了偏见，这种根深蒂固的趋势将这种长时间的停顿归咎于垃圾收集器。 当我们指责收集器时，最常见的React是在Web上搜索解决方案，仅最终使用随机模糊的JVM标志结束，希望它们中的一个可能是解决未知问题的解决方案。 通过执行分析，我们设法发现我们直接责怪收集器是错误的，而错误则自然导致我们提出问题，例如垃圾收集器是否不引起暂停，那又是什么？
这里提供的证据表明，在绝大部分暂停中，垃圾线程均未处于活动状态。 如果暂停是由于后台I / O引起的，那么OS捕获的GC线程应该已经积累了过多的内核时间，但实际上并没有。 所有这些都表明，GC线程已换出，而且不可思议的是，超过22秒未重新安排！ 如果我们的应用程序没有被垃圾收集器暂停，那么唯一的可能性就是JVM被操作系统暂停了，即使这似乎没有任何意义。
实际上，操作系统有时确实需要执行维护，并且在发生这种情况时，就像GC一样，操作系统可能需要暂停其他所有操作。 就像GC暂停来自一个经过良好调整的收集器一样，OS暂停被设计为不经常发生，并且非常简短，以至于几乎不被注意到。 但是有些停顿可能会持续很长时间。 例如，垃圾收集器必须等待几秒钟才能满足页面分配请求，这并非闻所未闻。 在这些情况下，通常发生的情况是系统在内存中移动数据以获取足够的连续可用RAM来满足该请求。
尽管在这种情况下不太可能，但有时我们有时会在集合中间看到网络时间协议（NTP）调整时钟。 通常，只有在时钟向后滚动时，我们才会认识到这种情况，并且日志将在开始收集之前报告收集已结束。 如前所述，在这种情况下这不太可能，因为通常一次只能将时钟值调整为毫秒，而不是几十秒。
在所有情况下，最重要的认识是GC分析可以带领我们走过“怪罪收藏家”游戏，这使我们能够做出一些惊人的发现，这些发现可以帮助改善应用程序的性能和稳定性。
关于作者
是原始的Java Performance Tuning Workshop的作者，在其中他讲授了垃圾回收分析和许多其他Java性能主题。 他还与人共同创立了jClarity，这是一家开发机器学习辅助性能诊断工具的公司，旨在帮助诊断复杂的性能退化。
怎么看gc日志