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

本文介绍了OpenJDK 11中JVM日志配置的改动,包括JVM日志标签分类,如gc、类加载和运行时相关日志。详细解析了JVM日志配置的格式,如'what'、'output'和'decorators',并展示了如何动态修改JVM日志级别,如查看、新增和修改日志配置。此外,还提供了一些常用日志标签的实例和其作用。

摘要生成于 C知道 ,由 DeepSeek-R1 满血版支持, 前往体验 >

 

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

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,loadclass,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 或者 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

结果:

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

附Java/C/C++/机器学习/算法与数据结构/前端/安卓/Python/程序员必读/书籍书单大全:

(点击右侧 即可打开个人博客内有干货):技术干货小栈
=====>>①【Java大牛带你入门到进阶之路】<<====
=====>>②【算法数据结构+acm大牛带你入门到进阶之路】<<===
=====>>③【数据库大牛带你入门到进阶之路】<<=====
=====>>④【Web前端大牛带你入门到进阶之路】<<====
=====>>⑤【机器学习和python大牛带你入门到进阶之路】<<====
=====>>⑥【架构师大牛带你入门到进阶之路】<<=====
=====>>⑦【C++大牛带你入门到进阶之路】<<====
=====>>⑧【ios大牛带你入门到进阶之路】<<====
=====>>⑨【Web安全大牛带你入门到进阶之路】<<=====
=====>>⑩【Linux和操作系统大牛带你入门到进阶之路】<<=====

天下没有不劳而获的果实,望各位年轻的朋友,想学技术的朋友,在决心扎入技术道路的路上披荆斩棘,把书弄懂了,再去敲代码,把原理弄懂了,再去实践,将会带给你的人生,你的工作,你的未来一个美梦。

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值