![](https://www.azul.com/wp-content/uploads/2024-06-11-garbage-collection.jpg)
我们有时会遇到一些 Java 用户,他们认为启用垃圾收集日志记录会严重影响性能指标。让我们来看看事实和谬见……
关于垃圾收集器
Java 垃圾收集器是 Java 虚拟机 (JVM) 的重要组成部分,能够影响应用程序的性能和可靠性。如果您想深入了解 Java 运行时中不同类型的垃圾收集器及其工作原理,请查看之前的这篇博客文章:《作为 Java 开发人员,我应该了解垃圾收集的哪些知识?》。
GC 日志记录是什么?
垃圾收集 (GC) 日志记录是 JVM 的一项功能,可提供关于垃圾收集过程的信息。通过生成的日志文件,您可以深入了解 JVM 如何收集和处理程序不再需要的对象,从而在运行时对内存进行动态管理。当您想要监视 Java 应用程序的性能、诊断内存泄漏,以及调整 JVM 的垃圾收集配置时,这非常有用。
“我们的一些客户对应用程序性能提升的追求达到了微秒必争的地步,”Azul 销售工程师 Daniel Witkowki 说,“但他们仍然会启用 GC 日志记录!因为它对应用程序性能的影响微乎其微,并且为多种不同问题的调试提供了支持,对于这些公司来说,在问题发生后,确保始终能够检索 GC 日志至关重要。”
![](https://www.azul.com/wp-content/uploads/Witkowski-quote-June-2024-1024x341.jpg)
启用垃圾收集日志记录后,每当 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
异步统一日志记录。”
![](https://www.azul.com/wp-content/uploads/Sreedhar-quote-June-2024-1024x341.jpg)
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 的垃圾收集配置非常有用。