Java 垃圾收集日志记录是否会影响应用程序性能？

我们有时会遇到一些 Java 用户，他们认为启用垃圾收集日志记录会严重影响性能指标。让我们来看看事实和谬见……

关于垃圾收集器

Java 垃圾收集器是 Java 虚拟机 (JVM) 的重要组成部分，能够影响应用程序的性能和可靠性。如果您想深入了解 Java 运行时中不同类型的垃圾收集器及其工作原理，请查看之前的这篇博客文章：《作为 Java 开发人员，我应该了解垃圾收集的哪些知识？》。

GC 日志记录是什么？

垃圾收集 (GC) 日志记录是 JVM 的一项功能，可提供关于垃圾收集过程的信息。通过生成的日志文件，您可以深入了解 JVM 如何收集和处理程序不再需要的对象，从而在运行时对内存进行动态管理。当您想要监视 Java 应用程序的性能、诊断内存泄漏，以及调整 JVM 的垃圾收集配置时，这非常有用。

“我们的一些客户对应用程序性能提升的追求达到了微秒必争的地步，”Azul 销售工程师 Daniel Witkowki 说，“但他们仍然会启用 GC 日志记录！因为它对应用程序性能的影响微乎其微，并且为多种不同问题的调试提供了支持，对于这些公司来说，在问题发生后，确保始终能够检索 GC 日志至关重要。”

启用垃圾收集日志记录后，每当 JVM 执行垃圾收集时，都会在日志文件中存储以下信息：

• GC 事件的类型
  • 小型 GC：清理年轻代空间
  • 大型 GC：清理老年代空间
  • 全量 GC：清理整个堆空间
• GC 事件开始的时间。
• GC 事件的持续时间。
• 每个内存池在 GC 事件前后的内存量。
• 每个内存池的可用内存总量。

日志文件是人类可读的，内容如下所示：

[0.005s][info][gc] Using G1
[0.110s][info][safepoint] Safepoint "ICBufferFull", Time since last: 98355917 ns, Reaching safepoint: 2000 ns, Cleanup: 53416 ns, At safepoint: 7167 ns, Total: 62583 ns
[0.186s][info][safepoint] Safepoint "ICBufferFull", Time since last: 75998125 ns, Reaching safepoint: 1792 ns, Cleanup: 56000 ns, At safepoint: 4458 ns, Total: 62250 ns
[0.235s][info][safepoint] Safepoint "ICBufferFull", Time since last: 48961667 ns, Reaching safepoint: 2125 ns, Cleanup: 45208 ns, At safepoint: 4042 ns, Total: 51375 ns
[0.259s][info][gc       ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 49M->4M(1032M) 1.472ms
...
[2.290s][info][gc       ] GC(13) Pause Young (Concurrent Start) (Metadata GC Threshold) 120M->23M(560M) 2.647ms
[2.290s][info][gc       ] GC(14) Concurrent Mark Cycle
[2.290s][info][safepoint] Safepoint "CollectForMetadataAllocation", Time since last: 31224333 ns, Reaching safepoint: 1542 ns, Cleanup: 45042 ns, At safepoint: 2700833 ns, Total: 2747417 ns
[2.302s][info][gc       ] GC(14) Pause Remark 28M->28M(112M) 1.986ms
[2.302s][info][safepoint] Safepoint "G1PauseRemark", Time since last: 10354500 ns, Reaching safepoint: 1917 ns, Cleanup: 14125 ns, At safepoint: 2028625 ns, Total: 2044667 ns
[2.306s][info][gc       ] GC(14) Pause Cleanup 28M->28M(112M) 0.048ms
[2.306s][info][safepoint] Safepoint "G1PauseCleanup", Time since last: 3311666 ns, Reaching safepoint: 169500 ns, Cleanup: 11084 ns, At safepoint: 79583 ns, Total: 260167 ns
[2.306s][info][gc       ] GC(14) Concurrent Mark Cycle 16.086ms
...

存储的信息和格式可能因使用的 JVM 和 GC 算法而异。

启用 GC 日志记录

GC 日志记录通过 java 命令行参数 -Xlog. 启用。得益于 JEP 158“统一的 JVM 日志记录”，此功能从 Java 9 版本开始提供：

• -Xlog:gc,safepoint:gc.log 用于启用重要垃圾收集事件（包括所有安全点暂停）的默认日志记录。
• -Xlog:gc*,safepoint:gc.log 用于启用更详细的日志记录，包括所有安全点暂停，以及通常不记录的较小垃圾收集器事件和阶段。  对于 OpenJDK，这通常是必不可少的，否则某些 Java 堆内存指标将不会被记录，而且并非所有暂停都会被跟踪。在 Zing 上，它不是必需的，因为默认情况下，仅使用 gc 就能够记录所有必要的数据。 gc 和 gc* 之间的权衡通常意味着日志数据量将增加 10 倍，而这会缩减您的日志覆盖的时间跨度。
• -Xlog:gc,safepoint 用于将日志数据写入标准输出，在容器中有助于避免存储本地日志文件。
• -Xlog:gc,safepoint:gc.log::filecount=10,filesize=100M 用于将默认日志轮转设置从 5 个 20 MB 的文件更改为 10 个 100 MB 的文件。
• -Xlog:gc,safepoint:gc.log::filecount=0 用于禁用日志文件轮转，这对于快速测试运行或经常重启的进程很有用处。注意连用两个冒号的地方。

您甚至可以重复使用 -Xlog 同时指定不同的输出，例如，下面的命令会将日志同时写入标准输出和本地文件：

$ java -Xlog:gc,safepoint -Xlog:gc,safepoint:/opt/log/gc.log -jar myApp.jar

统一日志记录系统还提供了其他选项，运行以下命令，您就可以看到：

$ java -Xlog:logging=debug -version
 
[0.017s][info][logging] Log configuration fully initialized.
[0.017s][info][logging] Available log levels: off, trace, debug, info, warning, error
[0.017s][info][logging] Available log decorators: time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um),...
[0.017s][info][logging] Available log tags: add, age,... gc,...
[0.017s][info][logging] Described tag sets:
[0.017s][info][logging]  logging: Logging for the log framework itself
[0.019s][debug][logging] Available tag sets: , arguments, attach, cds, cds+class, cds+dynamic, cds+hashtables, cds+heap,...
[0.023s][info ][logging] Log output configuration:
[0.023s][info ][logging]  #0: stdout all=warning,logging=debug uptime,level,tags foldmultilines=false
[0.023s][info ][logging]  #1: stderr all=off uptime,level,tags foldmultilines=false
openjdk version "22" 2024-03-19
OpenJDK Runtime Environment Zulu22.28+91-CA (build 22+36)
OpenJDK 64-Bit Server VM Zulu22.28+91-CA (build 22+36, mixed mode, sharing)

GC 日志记录的影响

在 Java 应用程序中启用 GC 日志记录对性能的影响通常微乎其微，在现代 JVM 中更是如此。但是，具体影响可能会因 JVM 版本、使用的 GC 算法、GC 日志记录的设置，以及日志写入目标系统的 I/O 性能而异。以下是您需要考虑的一些事实：

• 填满文件系统的风险：日志记录对性能的最常见实际影响是填满（或几乎填满）整个文件系统，需要避免这种情况。Java 9 及更高版本默认启用日志文件轮转功能，并且只会写入 5 个日志片段，每个片段的大小为 20 MB。
• I/O 操作：GC 日志直接写入磁盘。这会产生 I/O 操作，因此，如果磁盘速度较慢或磁盘使用率较高，就会拖慢应用程序的运行速度。
• 内存缓冲：现代 JVM 通常会使用内存缓冲区存放 GC 日志。当缓冲区满时，日志会一次性写入磁盘，以降低对 I/O 的影响。但是，缓冲区会占用应用程序本来可以使用的内存。
• 详细 GC 日志：如果启用详细 GC 日志（例如，记录各线程的耗时，或对象的统计信息），对性能的影响可能会变得明显，因为需要对这些数据进行记录和处理，这可能会消耗 CPU 资源。
• 安全点：所有 GC 日志记录活动都在应用程序执行过程中的“安全点”上进行，因此，与 GC 活动本身自然引发的“全局暂停”次数相比，日志记录活动不会导致“全局暂停”次数的增多。

务必考虑文件系统中的数据量。文件系统满载所导致的系统停顿会带来严重的性能问题。当 Zing 仅使用 -Xlog:gc:gc.log  时，或 OpenJDK 仅使用 -Xlog:gc,safepoint:gc.log 时，您就能满足所有必要的性能指标，同时不会浪费太多空间。尤其是在 Zing 上 -XX:+PrintGCDetails, gc*, 和 safepoint 并不是必需的，因为它们不会在 GCLogAnalyzer 中添加更多图表。

“GC 日志任务主要是将数据保存到日志文件中，”Azul 首席软件工程师 Deepak Sreedhar 指出，“用于存储这些文件的 I/O 类型可能会影响日志记录的性能，但不会直接影响应用程序本身。因此，可能出现的一些问题与 GC 日志记录的性能无关，而是与 I/O 速度有关。如果无法足够快速地实时保存日志，OpenJDK 可以选择通过 Xlog:async 异步统一日志记录。”

Azul Zing 的 GC 日志记录

使用 Azul Zing 时，您只需添加 -Xlog:gc:gc.log 即可指示 Zing 存储垃圾收集器日志文件。 不需要使用e gc* 或 safepoint 等额外参数来提高详细程度，因为 Zing 始终会记录安全点暂停，甚至还会记录 OpenJDK GC 日志中默认不显示的其他信息，如 JIT 编译器活动、CPU 和内存使用情况、Linux 页面缓存指标，以及其他一些常用于系统性能分析的指标。

分析 GC 日志

有多种工具可用于分析 GC 日志文件的内容：

• JVM 内置的 jstat 命令：此实用程序可显示性能统计数据，也可用于输出垃圾收集器统计数据。
• VisualVM：此工具提供了 JVM 不同方面的多种视图，包括垃圾收集。它还提供实时指标，有助于实时分析问题。您可以从 GitHub 下载此工具。
• Azul GC 日志分析器：读取 GC 日志并将其可视化为一组随时间（实际时间和正常运行时间）变化的图表。它显示有关垃圾收集器、JIT 编译器、系统指标和 ReadyNow 统计数据的信息。此图形桌面应用程序在此处有文档说明，在此处提供视频演示。

结语

尽管使用垃圾收集日志会产生极低的性能成本，但这种交换通常是值得的，因为在调整垃圾收集和诊断内存问题时，日志往往不可或缺。如果不启用 GC 日志，您可能无法深入了解 JVM 如何在运行时动态管理内存。这些信息对于监视 Java 应用程序的性能、诊断内存泄漏和调整 JVM 的垃圾收集配置非常有用。