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

原创
2020/03/09 11:35
阅读数 1.3W

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,allocgc,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,ergogc,ergo,csetgc,ergo,ihopgc,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                ] gc(7843) Add young regions to CSet. eden: 676 regions, survivors: 6 regions, predicted young region time: 69.11ms, target pause time: 200.00ms
[2020-02-28T02:04:36.095+0000][debug][gc,ergo,cset                ] gc(7843) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 118.04
[2020-02-28T02:04:36.118+0000][debug][gc,ergo                     ] gc(7843) Running g1 Clear Card Table Task using 4 workers for 7 units of work for 894 regions.
[2020-02-28T02:04:36.120+0000][debug][gc,ergo                     ] gc(7843) Running g1 Free Collection Set using 4 workers for collection set length 682
[2020-02-28T02:04:36.121+0000][trace][gc,ergo,refine              ] gc(7843) Updating Refinement Zones: update_rs time: 6.929ms, update_rs buffers: 364, update_rs goal time: 19.997ms
[2020-02-28T02:04:36.121+0000][debug][gc,ergo,refine              ] gc(7843) Updated Refinement Zones: green: 572, yellow: 1716, red: 2860

标签gc,heapgc,heap,region

gc,heap的 debug 级别会显示 gc 的时候堆的概况,对于 g1 gc gc,heap,region的 trace 级别,会打印每一个 region 的详细情况,这个一般供 gc 调试使用。

我们一般只需要关心gc,heap的日志就行了

这些标签是在

[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[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922)   class space    used 18180K, capacity 19580K, committed 20480K, reserved 1048576K
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) Heap Regions: E=young(eden), S=young(survivor), O=old, HS=humongous(starts), HC=humongous(continues), CS=collection set, F=free, A=archive, TAMS=top-at-mark-start (previous, next)[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   0|0x0000000600000000, 0x0000000600400000, 0x0000000600400000|100%| O|  |TAMS 0x0000000600400000, 0x0000000600000000| Untracked
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   1|0x0000000600400000, 0x0000000600800000, 0x0000000600800000|100%| O|  |TAMS 0x0000000600800000, 0x0000000600400000| Untracked
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   2|0x0000000600800000, 0x0000000600c00000, 0x0000000600c00000|100%| O|  |TAMS 0x0000000600c00000, 0x0000000600800000| Untracked
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   3|0x0000000600c00000, 0x0000000601000000, 0x0000000601000000|100%| O|  |TAMS 0x0000000601000000, 0x0000000600c00000| Untracked
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   4|0x0000000601000000, 0x0000000601400000, 0x0000000601400000|100%| O|  |TAMS 0x0000000601400000, 0x0000000601000000| Untracked
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   5|0x0000000601400000, 0x0000000601800000, 0x0000000601800000|100%| O|  |TAMS 0x0000000601800000, 0x0000000601400000| Untracked
[2020-02-28T06:01:20.787+0000][trace][gc,heap,region              ] gc(7922) |   6|0x0000000601800000, 0x0000000601c00000, 0x0000000601c00000|100%| O|  |TAMS 0x0000000601c00000, 0x0000000601800000| Untracked

标签gc,humongous 如果你使用的是g1 gc,并且经常出现 Evacuation Failure 或者 Humongous Allocation ,并且不知道是什么原因的话,可以考虑看看这个标签相关的日志:

[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
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 412 object size 2160888 start 0x0000000667000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 443 object size 3241320 start 0x000000066ec00000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 489 object size 2160888 start 0x000000067a400000  with remset 2 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 490 object size 2160888 start 0x000000067a800000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 499 object size 7292936 start 0x000000067cc00000  with remset 2 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 536 object size 2160888 start 0x0000000686000000  with remset 2 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 656 object size 2160888 start 0x00000006a4000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 768 object size 2160888 start 0x00000006c0000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 786 object size 2160888 start 0x00000006c4800000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0

标签gc,metaspacegc,metaspace,freelistgc,metaspace,freelist,blocks 查看 metaspace 相关的 gc 日志,gc,metaspace的 info 级别会输出每次 gc 涉及的 metaspace 内存变化,如果有变化,详细变化会通过gc,metaspace,freelistgc,metaspace,freelist,blocks的 trace 级别输出。

[2020-02-28T04:32:13.123+0000][info ][gc,metaspace                ] gc(7896) Metaspace: 163062K->163062K(1198080K)
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist       ] SpaceManager::grow_and_allocate for 49 words 109 words used 19 words left
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist       ] ChunkManager::free_chunks_get: free_list: 0x00007fddccb89770 chunks left: 433.
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist       ] ChunkManager::chunk_freelist_allocate: 0x00007fddccb89770 chunk 0x00007fdc74221000  size 128 count 433 Free chunk total 255616  count 824
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist,blocks] returning block at 0x00007fdd95575b68 size = 19
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist       ] SpaceManager::added chunk: 
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist       ] Metachunk: bottom 0x00007fdc74221000 top 0x00007fdc74221040 end 0x00007fdc74221400 size 128 (specialized)
[2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist       ] Free chunk total 255616  count 824
[2020-02-28T04:36:35.367+0000][info ][gc,metaspace                ] gc(7897) Metaspace: 163065K->163065K(1198080K)

标签gc,phasesgc,phases,refgc,phases,taskgc,refgc,start,gc,ref,start 这些标签与 gc 步骤相关,如果想学习 gc 算法,可以查看这些标签的日志,来了解 gc 的步骤以及原理

标签safepoint

我们知道只有到达 safepoint,我们才可以进行 gc,如果我们对这些 safepoint 感兴趣,可以查看这个标签的 debug 级别的日志

2. 类加载与运行时编译相关

标签class,preorderclass,initclass,load, class,unload 顾名思义,这是类初始化,类加载与类卸载的日志,info 级别的信息就以足够。 如果你想学习 JVM 类加载过程,可以查看 class 标签的 trace 级别日志。

[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 编译日志即可,对应的标签是jit,compilation,日志级别是 debug

[2020-02-28T03:01:51.619+0000][debug][jit,compilation] 153756   !   4       jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes)   made zombie
[2020-02-28T03:01:51.620+0000][debug][jit,compilation] 153219       4       io.lettuce.core.protocol.CommandArgs$IntegerArgument::encode (12 bytes)   made zombie
[2020-02-28T03:01:51.623+0000][debug][jit,compilation] 153192       4       io.lettuce.core.protocol.CommandArgs$StringArgument::writeString (60 bytes)   made zombie
[2020-02-28T03:01:54.911+0000][debug][jit,compilation] 157252   !   4       jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes)

3. 其他运行时相关

标签monitorinflation 同步锁相关日志, 一般查看 debug 级别的,可以用于定位死锁

[5.033s][debug][monitorinflation] Deflating object 0x0000000708310378 , mark 0x0000021cef446002 , type java.lang.ref.ReferenceQueue$Lock
[5.033s][debug][monitorinflation] Inflating object 0x0000000708310378 , mark 0x0000021cf085c002 , type java.lang.ref.ReferenceQueue$Lock
[5.035s][debug][monitorinflation] Deflating object 0x0000000708310378 , mark 0x0000021cf085c002 , type java.lang.ref.ReferenceQueue$Lock
[5.035s][debug][monitorinflation] Inflating object 0x0000000708310378 , mark 0x0000021cef445e02 , 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, prototype header 0x0000000000000105, allow rebias 0, requesting thread 0x000001c6d0acc800
[7.273s][info ][biasedlocking]   Revoked bias of object biased toward live thread (0x000001c6d0acc800)
[7.273s][trace][biasedlocking]    mon_info->owner (0x00000007022634d8) != obj (0x0000000711b1ca40)
[7.273s][trace][biasedlocking]    mon_info->owner (0x0000000711b200d8) != obj (0x0000000711b1ca40)
[7.273s][trace][biasedlocking]    mon_info->owner (0x0000000711b200d8) != obj (0x0000000711b1ca40)
[7.273s][trace][biasedlocking]    mon_info->owner (0x0000000702970260) != obj (0x0000000711b1ca40)
[7.273s][info ][biasedlocking]   Revoked bias of currently-unlocked object

二、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-Xlog::stdout:uptime,level,tags-Xlog:all=warning:stdout:uptime,level,tags
  • -Xlog:gc*=info-Xlog:gc*=info:stdout:uptime,level,tags
  • -Xlog::file=/project/log/app.log::filecount=50,filesize=100M-Xlog:all=warning:file=/project/log/app.log:uptime,level,tags:filecount=50,filesize=100M

1. what

what包含标签还有日志级别,例如你可以配置:

  • -Xlog:gc=info,表示仅包含 gc 一个标签的所有日志,info 级别的都会输出。
  • -Xlog:gc*=info,表示包含 gc 标签的所有日志,info 级别的都会输出,就是上面说的 gc 相关的所有标签
  • -Xlog:gc+age=debug,表示同时包含且仅包含 gc 和 age 这两个标签的,debug 级别的才会输出。
  • -Xlog:gc*=info,gc+heap=debug,gc+heap+region=debug,同时设置包含且仅包含 gc 和 heap 这两个标签的为 debug,包含且仅包含 gc 和 heap 和 region 这三个标签的设置为 debug ,剩下的包含 gc 标签的日志级别为 info 而且由于我们知道age标签只和gc标签搭配,所以还可以这么写:
  • -Xlog:gc*=info,age*=debug-Xlog:gc*=info,gc+age=debug是等价的 对于这种可以合并的标签,可以参考后面的动态修改JVM日志级别章节来通过修改日志参数看JVM是如何合并的。

日志级别包括:

  • 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是等价的

标签如果打错了,就会报错并退出:

[0.005s][error][logging] Invalid tag 'phase' in log selection. Did you mean 'phases'?
Invalid -Xlog option '-Xlog:gc+phase=debug', see error log for details.

如果没有这种标签的组合(或者这个标签不能单独出现),则会报警,但是继续运行:

[0.006s][warning][logging] No tag set matches selection: gc+add. Did you mean any of the following? gc* gc+metaspace* gc+ref* gc+stringtable gc+compaction
[0.007s][warning][logging] No tag set matches selection: phases. Did you mean any of the following? phases* gc+phases* gc+phases+start* gc+phases+task gc+phases+ref

2. output

包含三种输出:

  • stdout: 标准输出

  • stderr: 标准错误输出

  • file=filename 输出到文件

对于输出到文件可以配置output-optionsfilecount=50,filesize=100M这个表示保留50个文件,每个文件100M

3. decorators

可以使用的标记:

标记 含义
time 或者 t 当前时间,ISO-8601格式
utctime 或者 utc UTC时间
uptime 或者 u 启动到现在经过的时间,精确到毫秒
timemillis 或者 tm 毫秒时间戳,相当于System.currentTimeMillis().
uptimemillis 或者 um 启动到现在的毫秒时间
timenanos 或者 tn 纳秒时间戳,相当于System.nanoTime()
uptimenanos 或者 un 启动到现在的纳秒时间
hostname 或者 hn 主机名称
pid 或者 p 进程号
tid 或者 ti 线程号
level 或者 l 日志级别
tags 或者 tg 日志标签,参考前面提到的日志标签章节

假设我们配置了uptime,level,tags,那么日志就会像这个样子:

[2020-02-26T08:34:12.823+0000][debug][gc,age         ] gc(1661) Desired survivor size 167772160 bytes, new threshold 6 (max threshold 6)

4. 将老版本的日志配置转换为新版本的日志配置

gc相关:

原始参数 等价新参数以及说明
g1PrintHeapRegions -Xlog:gc+region=trace
gcLogFileSize 和 NumberOfgcLogFiles还有UsegcLogFileRotation 通过上面提到的 output 和 output-option 来实现
PrintTenuringDistribution -Xlog:gc+age*=level,参考上面的 gc,age 标签确定你想要查看的级别
PrintAdaptiveSizePolicy -Xlog:gc+ergo*=level, 参考上面的 gc,ergo 标签章节来决定你想看的日志级别
Printgc -Xlog:gc=info或者-Xlog:gc, 打印所有只包含gc标签的日志
PrintgcDetails -Xlog:gc*=info或者-Xlog:gc*
PrintgcApplicationConcurrentTime和PrintgcApplicationStoppedTime -Xlog:safepoint=log或者-Xlog:safepoint,原来是分开的,在新的日志参数下,标签都是 safepoint
PrintgcTaskTimeStamps -Xlog:gc+task*=debug
PrintHeapAtgc -Xlog:gc+heap=trace
PrintReferencegc -Xlog:gc+ref*=debug
PrintStringDeduplicationStatistics -Xlog:gc+stringdedup*=debug
PrintgcDateStamps 这个目前通过上面的 decorators 部分配置,对应的是 time 或 t
PrintgcCause和PrintgcID 目前 gc 的 ID 还有 gc 原因默认就会打出来,不用配置这个了

其他参数:

原始参数 等价新参数以及说明
TraceExceptions -Xlog:exceptions=info 打印 JVM 遇到的任何错误异常日志,默认只打印 error 级别的
TraceClassLoadingPreorder -Xlog:class+preorder=debug
TraceClassLoading -Xlog:class+load=info 打印类加载日志,info 级别就很足够
TraceClassUnloading -Xlog:class+unload=info 打印类卸载日志,info 级别就很足够
TraceClassLoadingPreorder -Xlog:class+preorder=debug
TraceClassInitialization -Xlog:class+init=info
TraceClassResolution -Xlog:class+resolve=debug
TraceClassPaths -Xlog:class+path=info
TraceLoaderConstraints -Xlog:class+loader+constraints=info
VerboseVerification -Xlog:verification=info
TraceSafepoint -Xlog:safepoint=debug
TraceSafepointCleanupTime -Xlog:safepoint+cleanup=info
TraceMonitorInflation -Xlog:monitorinflation=debug
TraceBiasedLocking -Xlog:biasedlocking=level 可以参考上面提到的 biasedlocking 标签,根据你想看的信息来配置级别
TraceRedefineClasses -Xlog:redefine+class*=level

三、动态修改JVM日志级别

可以通过 jcmd 动态修改 JVM 日志配置, 主要命令是VM.log, 假设我们的 JVM 进程是22,则可以通过这个命令查看格式:

jcmd 22  VM.log

结果:

22
Syntax : VM.log [options]

Options: (options must be specified using the <key> or <key>=<value> syntax)
        output : [optional] The name or index (#<index>) of output to configure. (STRING, no default value)
        output_options : [optional] Options for the output. (STRING, no default value)
        what : [optional] Configures what tags to log. (STRING, no default value)
        decorators : [optional] Configures which decorators to use. Use 'none' or an empty value to remove all. (STRING, no default value)
        disable : [optional] Turns off all logging and clears the log configuration. (BOOLEAN, no default value)
        list : [optional] Lists current log configuration. (BOOLEAN, no default value)
        rotate : [optional] Rotates all logs. (BOOLEAN, no default value)

查看当前日志参数配置

假设我们22的进程,启动参数中日志相关的参数是这么配置的:

-Xlog:gc*=debug:file=/project/log/gc.log:utctime,level,tags:filecount=50,filesize=100M 
-Xlog:jit+compilation=debug:file=/project/log/jit_compile.log:utctime,level,tags:filecount=10,filesize=100M

执行list命令:

jcmd 22 VM.log list

结果:

22:

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

里面的#0还有#1是我们之前说的默认JVM日志配置:

 #0: stdout all=warning uptime,level,tags //代表标准输出中输出所有标签的warn级别日志,格式为[uptime][level][tags]日志内容
 #1: stderr all=off uptime,level,tags //代表标准错误输出中,不输出任何日志

我们在启动参数中配置的日志参数对应的是#2#3

让日志另起一个文件输出

jcmd 22 VM.log rotate
22:
Command executed successfully

可以看到#2#3对应的日志都另起一个文件继续输出

关闭所有日志,并清理日志相关参数

jcmd 22 VM.log disable
22:
Command executed successfully
jcmd 22 VM.log list
22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags

可以看出,执行这个命令后,所有的日志都被关闭,并且参数被清理掉了(连启动参数配置的日志参数都不例外)

新增日志配置输出

以下参数和我们启动参数的-Xlog:gc*=debug:file=/project/log/gc.log:utctime,level,tags:filecount=50,filesize=100M保持一致。

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

结果:

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=debug utctime,level,tags filecount=50,filesize=100M (reconfigured)

由于之前配置过一次所以这里有(reconfigured)

修改日志配置输出

怎么区分日志呢?是通过 output 来唯一区分的(不指定就是stdout)。保持与现有的某个output一致,就是修改配置,但是 output_options 只要设定了,就不能改,只能通过 disable 关闭所有日志之后重新设置。

例如我们来修改刚刚的配置级别为info:

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

结果:

22:
Command executed successfully

jcmd 22 VM.log list
22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info uptime,level,tags filecount=50,filesize=100M (reconfigured)

其中,标签为包含关系的会自动合并,每次设置是增量设置,而不是全量设置也就是每次配置的what会附加到现有的输出当中,从下面几个例子就能看出来

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

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info uptime,level,tags filecount=50,filesize=100M (reconfigured)

由于gc+age其实属于gc*,所以被合并到了gc*

jcmd 22 VM.log output=/project/core/log/gc.log what="gc+age=debug"

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info,age*=debug uptime,level,tags filecount=50,filesize=100M (reconfigured)
 

gc+age设置为 debug 级别,合并变成了gc*=info,age*=debug,可以推测出,age 只能和 gc 搭配使用

jcmd 22 VM.log output=/project/core/log/gc.log what="gc+alloc+region=debug"

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info,age*=debug,alloc+region*=debug uptime,level,tags filecount=50,filesize=100M (reconfigured)
 
jcmd 22 VM.log output=/project/core/log/gc.log what="gc+heap=debug,gc+heap+region=debug"

22:

Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info,age*=debug,region*=debug,gc+heap=debug,gc+region=info uptime,level,tags filecount=50,filesize=100M (reconfigured)

gc+alloc+region设置为 debug ,合并变成了gc*=info,age*=debug;再加上gc+heap=debug,gc+heap+region=debug,合并变成了gc*=info,age*=debug,region*=debug,gc+heap=debug,gc+region=info,可以看出,region 只有两种搭配gc+alloc+regiongc+heap+region

展开阅读全文
打赏
0
9 收藏
分享
加载中
更多评论
打赏
0 评论
9 收藏
0
分享
返回顶部
顶部