OpenJDK 11 JVM日志相关参数解析与使用

 

个人博客导航页（点击右侧链接即可打开个人博客）：大牛带你入门技术栈 

OpenJDK 11 是在 OpenJDK 8 之后的第一个长期支持版本，这一版本在JVM日志配置有了很大改动，主要是规范化，统一化了。在 OpenJDK 8 中，日志配置有很多状态位，让人摸不着头脑，并且比较难以维护与进一步迭代。在 OpenJDK 11终于将JVM日志相关的配置规范起来，统一配置。这篇文章会对于这些配置做一个基本的说明和解析。

一、JVM日志标签

JVM 日志和我们 java 代码中的日志，其实是类似。在 Java 代码中，我们一般使用 slf4j 记录日志，例如：

Logger logger = LogFactory.getLooger("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

包括时间戳，日志级别，日志标签（core-logger），日志内容这些信息。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 日志包括：

[启动经过时间][日志级别][日志标签，可能包含多个] 日志内容

其中一行日志，可能包含多个标签，之后关于JVM日志相关的配置，也是围绕着这些标签进行配置。大部分的标签是给JVM开发者用的，其中某些标签供我们使用 JVM 的人进行 JVM 参数调优以及代码调优。那么我们需要关心哪些标签呢？我个人按照功能，把我们需要关心的标签分为如下几大类

1. gc相关

gc日志有很多标签与组合，大部分以 gc 标签为开始，混合搭配其他一些标签。一般，有如下几个标签我们会经常用到：

标签gc

gc总体描述日志，一般设置info级别查看gc的发生时间，消耗时间还有内存大小。例如：Pause Young (Normal) (g1 Evacuation Pause) 3480M->1565M(5120M) 15.968ms 包含了gc类型，gc原因，收集内存大小，持续时间等信息

标签gc,age

gc 中 age 相关信息，age比较高的对象会进入老年代。如果是 trace 级别，会输出每一个 age 的所有对象占用总大小，以及比这个 age 低的所有 age 的大小，debug 级别只会输出最高级别的 age 以及期望大小，不是当前总大小，例如：

[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 在 gc 完成的时候，打印 trace 级别日志记录触发 gc 的线程是哪一个以及返回的 gc 结果地址;这个一般是在调试 gc 的时候才需要看这个日志。 gc,alloc,region 统计每次 gc 的 Regions 信息，打印 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 时间是从开始 schedule gc 就认为开始 gc ，而这里的时间是从开始标记开始。

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

这是 Adaptive Size Policy 相关的日志，如果想详细学习算法，可以用 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
[2020-02-28T01:59:46.389+0000][debug][gc,ergo                     ] gc(7841) Running g1 Clear Card Table Task using 4 workers for 7 units of work for 895 regions.
[2020-02-28T01:59:46.391+0000][debug][gc,ergo                     ] gc(7841) Running g1 Free Collection Set using 4 workers for collection set length 682
[2020-02-28T01:59:46.391+0000][trace][gc,ergo,refine              ] gc(7841) Updating Refinement Zones: update_rs time: 6.800ms, update_rs buffers: 397, update_rs goal time: 19.998ms
[2020-02-28T01:59:46.391+0000][debug][gc,ergo,refine              ] gc(7841) Updated Refinement Zones: green: 572, yellow: 1716, red: 2860
[2020-02-28T02:01:20.108+0000][trace][gc,ergo,cset                ] gc(7842) Start choosing CSet. pending cards: 25786 predicted base time: 12.87ms remaining time: 187.13ms target pause time: 200.00ms
[2020-02-28T02:01:20.108+0000][trace][gc,ergo,cset                ] gc(7842) Add young regions to CSet. eden: 677 regions, survivors: 5 regions, predicted young region time: 14.43ms, target pause time: 200.00ms
[2020-02-28T02:01:20.108+0000][debug][gc,ergo,cset                ] gc(7842) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 172.70
[2020-02-28T02:01:20.132+0000][debug][gc,ergo                     ] gc(7842) Running g1 Clear Card Table Task using 4 workers for 8 units of work for 903 regions.
[2020-02-28T02:01:20.133+0000][debug][gc,ergo                     ] gc(7842) Running g1 Free Collection Set using 4 workers for collection set length 682
[2020-02-28T02:01:20.133+0000][trace][gc,ergo,refine              ] gc(7842) Updating Refinement Zones: update_rs time: 6.303ms, update_rs buffers: 305, update_rs goal time: 19.997ms
[2020-02-28T02:01:20.133+0000][debug][gc,ergo,refine              ] gc(7842) Updated Refinement Zones: green: 572, yellow: 1716, red: 2860
[2020-02-28T02:04:36.095+0000][trace][gc,ergo,cset                ] gc(7843) Start choosing CSet. pending cards: 26115 predicted base time: 12.85ms remaining time: 187.15ms target pause time: 200.00ms
[2020-02-28T02:04:36.095+0000][trace][gc,ergo,cset