OpenJDK 11 JVM 日志：新统一配置完整指南

#

你好，Java 爱好者们！🚀 让我们深入了解 OpenJDK 11 带来的最令人兴奋的改进之一 - 完全重新设计的 JVM 日志系统。如果你一直在与 OpenJDK 8 中分散且令人困惑的日志选项作斗争，那么你会喜欢的！

OpenJDK 11 标志着 OpenJDK 8 之后的第一个长期支持版本，天哪，它确实为 JVM 日志带来了一些惊人的变化！团队终于决定解决多年来让开发者头疼的混乱日志标志。告别处理数十个不同参数的日子 - 欢迎进入统一、标准化日志配置的时代！

理解 JVM 日志标签：你的新朋友

#

将 JVM 日志视为与 Java 代码中的应用日志非常相似。当你编写应用日志时，通常这样做：

Logger logger = LogFactory.getLogger("core-logger");
logger.info("this is core logger log");

产生如下输出：

2020-02-05 10:50:52.670  INFO [core-logger] [22] [pool-13-thread-1]: this is core logger log

JVM 日志遵循相同的原则！看看这个例子：

[0.182s][debug][jit,compilation]    1       3       java.lang.StringLatin1::hashCode (42 bytes)
[0.183s][debug][jit,compilation]    2       3       java.lang.Object::<init> (1 bytes)
[0.183s][debug][jit,compilation]    3       3       java.lang.String::hashCode (49 bytes)

默认的 JVM 日志格式包括：

[startup-time][log-level][log-tags-comma-separated] log-content

每个日志条目可以包含多个标签，所有 JVM 日志配置都围绕这些标签。虽然许多标签是为 JVM 开发者设计的，但有几个对性能调优和调试非常有用。让我按类别分解最重要的：

1. 垃圾收集相关标签

#

GC 日志提供大量标签组合，大多数以 gc 标签与其他标签混合开始。以下是重要的：

标签 gc

这提供高级 GC 信息。将其设置为 info 级别以查看 GC 时间、持续时间和内存使用。例如：Pause Young (Normal) (g1 Evacuation Pause) 3480M->1565M(5120M) 15.968ms 显示 GC 类型、原因、内存收集大小和持续时间。

标签 gc,age

显示 GC 期间与年龄相关的信息。年龄较高的对象移动到老年代。Trace 级别输出每个年龄的详细大小信息，而 debug 级别仅显示最高年龄和预期大小：

[2020-02-26T08:34:12.823+0000][debug][gc,age         ] gc(1661) Desired survivor size 167772160 bytes, new threshold 6 (max threshold 6)
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   1:   16125960 bytes,   16125960 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   2:   16259512 bytes,   32385472 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   3:    2435240 bytes,   34820712 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   4:   17179320 bytes,   52000032 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   5:   43986952 bytes,   95986984 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   6:   20858328 bytes,  116845312 total

标签 gc,alloc 和 gc,alloc,region

这些是 G1 GC 特定的！gc,alloc 在 trace 级别记录哪个线程触发了 GC 和返回的地址 - 对 GC 调试非常有用。gc,alloc,region 在 debug 级别提供区域统计：

[2020-02-28T02:14:02.694+0000][trace][gc,alloc                    ] sdk-27692-2-amqp-t-4: Successfully scheduled collection returning 0x00000007ffc00000
[2020-02-28T02:16:00.372+0000][debug][gc,alloc,region             ] gc(7848) Mutator Allocation stats, regions: 677, wasted size: 63832B ( 0.0%)

标签 gc,cpu

这是你进行 GC 性能分析的首选！Info 级别显示实际 GC 时间消耗：

[2020-02-28T01:59:46.406+0000][info ][gc,cpu                      ] gc(7841) User=0.10s Sys=0.00s Real=0.04s
[2020-02-28T02:01:20.148+0000][info ][gc,cpu                      ] gc(7842) User=0.04s Sys=0.06s Real=0.04s

注意：此时间可能与 JFR 统计不同，因为 JFR 从 GC 调度开始计数，而这是从实际标记开始测量。

标签 gc,ergo, gc,ergo,cset, gc,ergo,ihop, gc,ergo,refine

这些涵盖自适应大小策略详细信息。使用 trace 级别进行深入算法研究，debug 级别用于一般理解：

[2020-02-28T01:59:46.367+0000][trace][gc,ergo,cset                ] gc(7841) Start choosing CSet. pending cards: 26996 predicted base time: 13.34ms remaining time: 186.66ms target pause time: 200.00ms
[2020-02-28T01:59:46.367+0000][trace][gc,ergo,cset                ] gc(7841) Add young regions to CSet. eden: 676 regions, survivors: 6 regions, predicted young region time: 19.02ms, target pause time: 200.00ms
[2020-02-28T01:59:46.367+0000][debug][gc,ergo,cset                ] gc(7841) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 167.64

标签 gc,heap 和 gc,heap,region

gc,heap 在 debug 级别显示 GC 期间的堆概览。对于 G1 GC，gc,heap,region 在 trace 级别打印详细区域信息（主要用于调试）：

[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922) Heap before gc invocations=7922 (full 0): garbage-first heap   total 8388608K, used 4076387K [0x0000000600000000, 0x0000000800000000)
[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922)   region size 4096K, 682 young (2793472K), 5 survivors (20480K)
[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922)  Metaspace       used 163068K, capacity 166731K, committed 169728K, reserved 1198080K

标签 gc,humongous

非常适合遇到疏散失败或巨大分配问题的 G1 GC 用户：

[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 219 object size 2160888 start 0x0000000636c00000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0

标签 gc,metaspace, gc,metaspace,freelist, gc,metaspace,freelist,blocks

监控元空间 GC 活动。gc,metaspace 在 info 级别显示内存变化，而其他提供详细的 trace 级别信息：

[2020-02-28T04:32:13.123+0000][info ][gc,metaspace                ] gc(7896) Metaspace: 163062K->163062K(1198080K)

标签 gc,phases, gc,phases,ref, gc,phases,task, gc,ref, gc,start, gc,ref,start

这些对于详细理解 GC 算法和阶段非常有用。

标签 safepoint

由于 GC 只在 safepoint 发生，debug 级别的 safepoint 日志对 GC 分析非常有见地。

2. 类加载和运行时编译标签

#

标签 class,preorder, class,init, class,load, class,unload

不言自明！Info 级别为大多数用例提供足够的详细信息。使用 trace 级别深入 JVM 类加载：

[8.931s][debug][class,preorder  ] com.fasterxml.jackson.core.PrettyPrinter source: file:/D:/Repositories/maven/com/fasterxml/jackson/core/jackson-core/2.10.0/jackson-core-2.10.0.jar
[8.931s][info][class,init              ] 2740 Initializing 'com/fasterxml/jackson/core/PrettyPrinter' (0x0000000801399220)
[8.934s][info][class,load              ] com.fasterxml.jackson.core.PrettyPrinter source: file:/D:/Repositories/maven/com/fasterxml/jackson/core/jackson-core/2.10.0/jackson-core-2.10.0.jar

标签 jit,compilation

对于 JIT 编译优化，debug 级别的 jit,compilation 日志是你最好的朋友：

[2020-02-28T03:01:51.619+0000][debug][jit,compilation] 153756   !   4       jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes)   made zombie

3. 其他运行时相关标签

#

标签 monitorinflation

Debug 级别的同步锁日志 - 非常适合死锁调试：

[5.033s][debug][monitorinflation] Deflating object 0x0000000708310378 , mark 0x0000021cef446002 , type java.lang.ref.ReferenceQueue$Lock

标签 biasedlocking

偏向锁定信息。Info 级别用于一般监控，trace 级别用于实现详细信息：

[7.273s][info ][biasedlocking] Revoking bias by walking my own stack:
[7.273s][info ][biasedlocking] Revoking bias of object 0x0000000711b1ca40, mark 0x000001c6d0acc905, type sun.net.www.protocol.jar.URLJarFile

JVM 日志配置：让一切协同工作

#

配置格式遵循此模式：

-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]

没有任何配置时，默认是：

-Xlog:all=warning:stdout:uptime,level,tags

这个冒号分隔的配置分解为：what:output:decorators:output-options。任何缺失的部分使用上面的默认值。这些配置是等价的：

• -Xlog:all=warning ≡ -Xlog::stdout ≡ -Xlog::::uptime,level,tags ≡ -Xlog:all=warning:stdout:uptime,level,tags
• -Xlog:gc*=info ≡ -Xlog:gc*=info:stdout:uptime,level,tags

1. “What” 参数

#

这结合了标签和日志级别：

• -Xlog:gc=info - 仅在 info 级别记录恰好带有 gc 标签的日志
• -Xlog:gc*=info - 在 info 级别记录所有包含 gc 标签的日志
• -Xlog:gc+age=debug - 在 debug 级别记录恰好带有 gc 和 age 标签的日志
• -Xlog:gc*=info,gc+heap=debug,gc+heap+region=debug - 多个配置组合

由于 age 只与 gc 配对，这些是等价的：

• -Xlog:gc*=info,age*=debug ≡ -Xlog:gc*=info,gc+age=debug

日志级别包括：

• off: 禁用
• trace: 所有级别（trace, debug, info, warning, error）
• debug: debug, info, warning, error
• info: info, warning, error
• warning: warning, error
• error: 仅 error

未指定级别默认为 info！ 所以 -Xlog:gc* ≡ -Xlog:gc*=info

2. 输出选项

#

三种输出类型可用：

• stdout: 标准输出
• stderr: 标准错误
• file=filename: 文件输出，带有 filecount=50,filesize=100M 等选项

3. 装饰器：让日志更美观

#

4. 转换遗留参数

#

GC 相关转换：

其他转换：

动态 JVM 日志配置：实时调整

#

这就是真正酷的地方！你可以使用 jcmd 和 VM.log 命令实时修改 JVM 日志。对于 PID 为 22 的进程：

jcmd 22 VM.log

查看当前配置

#

jcmd 22 VM.log list

示例输出：

Log output configuration:
 #0: stdout all=warning uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/log/gc.log all=off,gc*=debug utctime,level,tags filecount=50,filesize=100M
 #3: file=/project/log/jit_compile.log all=off,jit+compilation=debug utctime,level,tags filecount=10,filesize=100M

轮转日志文件

#

jcmd 22 VM.log rotate

添加新日志配置

#

jcmd 22 VM.log output=/project/core/log/gc.log output_options="filecount=50,filesize=100M" decorators="utctime,level,tags" what="gc*=debug"

修改现有配置

#

配置由其 output 参数标识。相同的输出 = 修改：

jcmd 22 VM.log output=/project/core/log/gc.log what="gc*=info"

重要：每个 what 设置是累加的，不是替换！系统智能地合并相关标签。

禁用所有日志

#

jcmd 22 VM.log disable

这完全清除所有日志配置，包括启动参数！

就是这样！OpenJDK 11 中的新统一日志系统起初可能看起来很复杂，但一旦你掌握了它，它就非常强大和灵活。不再需要处理数十个不同的标志 - 只需一个干净、一致的接口来满足你所有的 JVM 日志需求！🎉

祝你日志记录愉快，愿你的性能调优冒险永远成功！🚀