您当前的位置: 首页 >  蔚1 jvm

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

蔚1 发布时间:2020-03-09 23:31:28 ,浏览量:6

在 OpenJDK 11 开始,JVM 日志配置有了很大改动,主要是规范化,统一化了。在 Java 8 中,日志配置有很多状态位,让人摸不着头脑,并且比较难以维护与进一步迭代。在 Java 11 终于将 JVM 日志相关的配置规范起来,统一配置。

本文会从以下三个方面去深入理解 OpenJDK 11 的日志配置:

  1. JVM 日志标签,主要会讨论 GC 相关标签,类加载与即时编译相关以及一些其他运行时相关标签
  2. JVM 日志配置与从老的参数迁移到新的配置,结合实例,理解配置
  3. 动态修改 JVM 日志级别,结合实例,利用 JCMD 修改日志配置

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:: (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-options:filecount=50,filesize=100M这个表示保留 50 个文件,每个文件 100M

3. decorators

可以使用的标记:

标记含义
time 或者 t当前时间,ISO-8601 格式
utctime 或者 utcUTC 时间
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

结果:

22Syntax : VM.log [options]Options: (options must be specified using the  or = syntax)        output : [optional] The name or 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 successfullyjcmd 22 VM.log list22: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 successfullyjcmd 22 VM.log list22: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 successfullyjcmd 22 VM.log list22: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 successfullyjcmd 22 VM.log list22: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 successfullyjcmd 22 VM.log list22: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 successfullyjcmd 22 VM.log list22: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

阅读全文: http://gitbook.cn/gitchat/activity/5e65b2a641e3957935f9c4b6

您还可以下载 CSDN 旗下精品原创内容社区 GitChat App ,阅读更多 GitChat 专享技术内容哦。

关注
打赏
查看更多评论

蔚1

暂无认证

  • 6浏览

    0关注

    4645博文

    0收益

  • 0浏览

    0点赞

    0打赏

    0留言

私信
关注
热门博文
立即登录/注册

微信扫码登录