引言

关于基于 Java 开发的运用程序而言, GC 日志是咱们了解 JVM 内存运用的状况的一个重要信息源, 所以咱们在出产环境都打开 GC 的日志. 在 JDK 8 之前, 咱们都运用诸如: -XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=5, 等这些 JVM 发动选项, 然而, 自从 JDK 9 开端, 咱们却开端运用另外一套 JVM 发动选项, 如: -Xlog:gc*=debug:file=/tmp/gc.log:uptime,tid:filecount=5,filesize=2m 来设置 GC 的日志相关的装备.

为什么同样是设置 GC 的日志装备, 却有了不同的 JVM 发动选项呢? 这是因为: 自从 JDK 9 开端, JVM 有了一套一致的日志结构(JVM Unified Logging Framework). GC 日志作为 JVM 输出的一种日志, 也能够经过这个一致的日志结构来装备. 虽然 JVM 还承受本来的发动选项, 可是持久来看, 一切的这些跟日志相关的选项, 终究都将只保存经过这个一致的日志结构来装备.

什么是 JVM 一致的日志结构

JVM 一致的日志结构(JVM Unified Logging Framework)是 JDK 9 引进的一个中心化的日志结构, 经过这个日志结构, 咱们能够观测 JVM 的类加载(class loading), 线程(thread), 垃圾收集(GC), 模块体系(Module System) 等相关信息. 咱们能够经过设置设置 JVM 发动参数 -Xlog 来与这个一致的日志结构交互, 然后让这个一致的日志结构输出不同组成的, 不同层级(level)的日志到咱们指定的日志文件.

除了经过 -Xlog 这个发动参数外, 咱们也能够在运行时实时修正一致日志结构的输出. 一种办法是经过 jcmd 指令的 VM.log 子指令来修正, 另外一种办法是经过修正对应的 MBean. -Xlog 是在运用发动运用时分修正, 后边2种都是运行时动态修正.

后边的比方中, 为了举例便利, 咱们都运用 jcmd VM.log 动态修正, 然后观察修正的成果.

简略的比方

假设咱们有一个正在运行的 Java 运用, 它的进程号(pid)是 3499:

$ jps
16527 Jps
3499 Pycharm

咱们把一切的日志都打印到 /tmp/my.log 文件去, 能够这么操作:

$ jcmd 3499 VM.log output="file=/tmp/my.log" what="all=trace"
3499:
Command executed successfully
$ tail -f /tmp/my.log
[238674.318s][debug][gc,task               ] G1 Service Thread (Remembered Set Sampling Task) (run) 0.330ms (cpu: 0.327ms)
[238674.318s][trace][gc,task               ] G1 Service Thread (wait) 0.300s
[238674.333s][trace][monitorinflation,owner] try_set_owner_from(): mid=0x000060000089e220, prev=0x0000000000000000, new=0x00007fc6860d8c00
[238674.333s][trace][monitorinflation,owner] release_clear_owner(): mid=0x000060000089e220, old_value=0x00007fc6860d8c00
[238675.209s][trace][monitorinflation,owner] try_set_owner_from(): mid=0x0000600014b634d0, prev=0x0000000000000000, new=0x00007fc607a54a00
[238675.209s][trace][monitorinflation,owner] release_clear_owner(): mid=0x0000600014b634d0, old_value=0x00007fc607a54a00

上面的代码中, 咱们先是把一切的日志都经过 jcmd VM.log 的方法输出到 /tmp/my.log 文件中, 然后经过 tail 指令查看最新的日志内容.

在jcmd的指令中, 3499 是 Java 运用进程号, VM.log 是 jcmd的子指令, 后边的是 VM.log 子指令的选项, 咱们的留意力首要集中在选项这一块.

日志输出到哪

在这个简略的比方中, 咱们设置了 output="file=/tmp/my.log", 首要用来设置输出到哪里, 咱们能够设置为一个文件, 或者 stdout, stderr:

$ jcmd 3499 VM.log output="stdout" what="all=trace"
$ jcmd 3499 VM.log output="stderr" what="all=trace"

当然, 这里的 stdout 和 stderr 都是进程 3499 对应的 stdout 和 stderr(Linux体系每个进程都有自己独自的stdout, stderr伪文件), 并不是当时的控制台.

所以, 总结一下 output, 它有3种可能, 别离是:

stdout
stderr
file=<file_name>
当使第三种 file=<file_name> 的时分, 咱们能够设置文件名里边包括%p, %t, 别离代表运用进程号和运用发动的时刻.

日志文件的巨细和多少

关于上面的第三种写到文件体系的, 一般都能设置rotate, 便是文件轮转. 比方最多写5个文件, 每个文件最大6M这种. JVM 一致的日志结构也支撑这些设置, 它经过选项 output_options 设置. 比方:

$ jcmd 3499 VM.log output="stdout" what="all=trace" output_options="filecount=5,filesize=6M"

能够看到, 咱们设置了文件最多是5个, 文件巨细最大是6M. 文件巨细的单位能够是 K, M, G.

那么假如设置 filecount=0 呢? 这就代表告知体系, 不要rotate 日志文件.

写哪些模块的日志到日志文件

其实一开端到现在, 咱们都没有聊选项中的 what="all=trace", 这部分选项告知日志体系, 什么东西要写到日志文件里边. 咱们给的内容是 all=trace, 那它表明什么呢?

日志的层级

一般咱们写日志的方法大概是这样的:

log.info("this is a info log");
log.error("this is an error log"

这里咱们别离写了一条 info level 和一条 error level 的日志. 这里的 info, error 都是日志的等级, 同样, JVM 一致的日志结构中, 也有几个等级: off, trace, debug, info, warning, error. 这其间 off 最特别, 它其实是告知日志结构, 全闭嘴, 相当于关掉一切层级的日志. 能够看到咱们上面的比方中都是运用的 trace level, 是等级最低的, 等于输出一切的层级的日志.

日志的标签(tag)

一开端的时分, 咱们说到这个一致的日志结构能够输出不同模块的日志,比方GC, 线程, classload等模块. 那么咱们怎么挑选那些日志咱们能输出, 那些不让它输出呢?

为了让咱们有挑选的输出, 需求一个挑选规范, 这里运用的便是标签. 日志结构在输出日志的时分, 给每一条日志都加了一个或多个标签, 咱们能够挑选不同的标签组合, 挑选不同的日志内容输出到日志文件.

JVM 一致的日志结构写日志的方法类似于这样, 每一行日志都包括一些标签:

log.info("this is a info log", ["tag1", "tag2"]);
log.error("this is an error log", ["tag2", "tag3"]);

那么咱们和一致的日志结构交互的时分, 就能够根据这些标签去挑选究竟哪些日志要输出. 咱们能够经过指令来看当时的 JVM 支撑哪些标签:

$ jcmd 3499 VM.log list
3499:
Available log levels: off, trace, debug, info, warning, error
Available log decorators: time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um), timenanos (tn), uptimenanos (un), hostname (hn), pid (p), tid (ti), level (l), tags (tg)
Available log tags: add, age, alloc, annotation, arguments, attach, barrier, biasedlocking, blocks, bot, breakpoint, bytecode, cds, census, class, classhisto, cleanup, codecache, compaction, compilation, condy, constantpool, constraints, container, coops, cpu, cset, data, datacreation, dcmd, decoder, defaultmethods, director, dump, dynamic, ergo, event, exceptions, exit, fingerprint, free, freelist, gc, handshake, hashtables, heap, humongous, ihop, iklass, indy, init, inlining, install, interpreter, itables, jfr, jit, jni, jvmci, jvmti, lambda, library, liveness, load, loader, logging, malloc, map, mark, marking, membername, memops, metadata, metaspace, methodcomparator, methodhandles, mirror, mmu, module, monitorinflation, monitormismatch, nestmates, nmethod, nmt, normalize, numa, objecttagging, obsolete, oldobject, oom, oopmap, oops, oopstorage, os, owner, pagesize, parser, patch, path, perf, periodic, phases, plab, placeholders, preorder, preview, promotion, protectiondomain, ptrqueue, purge, record, redefine, ref, refine, region, reloc, remset, resolve, safepoint, sampling, scavenge, sealed, setting, smr, stackbarrier, stackmap, stacktrace, stackwalk, start, startup, startuptime, state, stats, streaming, stringdedup, stringtable, subclass, survivor, suspend, sweep, symboltable, system, table, task, thread, throttle, time, timer, tlab, tracking, unload, unshareable, update, valuebasedclasses, verification, verify, vmmutex, vmoperation, vmthread, vtables, vtablestubs, workgang
Described tag sets:
 logging: Logging for the log framework itself
Log output configuration:
 #0: stdout all=trace uptime,level,tags (reconfigured)
 #1: stderr all=off uptime,level,tags
 #2: file=/tmp/gc.log all=trace time,level,tags filecount=5,filesize=10240K,async=false (reconfigured)
 #3: file=/tmp/my.log all=trace uptime,level,tags filecount=5,filesize=20480K,async=false (reconfigured)

其间 Available log tags 包括了一切支撑的tag. 而咱们上面运用的 all 则表明包括一切的tags.

所以这也是 what 所表达的意义, 它经过 tags 和日志 level 一起来挑选什么(what)日志应该被输出出来. 比方:
gc=debug, jfr=trace, init=info 等.

日志每行的格局

在一开端的比方中, 咱们看到了如下的日志行:

[238674.318s][trace][gc,task ] G1 Service Thread (wait) 0.300s

这跟咱们平常看到的日志很像, 第一个方括号里边的表明服务器从开端发动到打日志的时刻, 第二个方括号里边表明日志的层级, 第三个表明日志的tags, 最终是日志的内容.

上面的输出中是默许的日志每一行的格局, 其实咱们能够定制这个格局, 并且加减一些内容.

首先, 除了时刻,日志level, tags, 咱们还有哪些能够跟日志一块打印的东西呢? 这些能够和日志内容一块输出的叫: decorator, 从之前的jcmd <pid> VM.log list的输出中, 咱们能够看到有如下的 decorators:

Available log decorators: time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um), timenanos (tn), uptimenanos (un), hostname (hn), pid (p), tid (ti), level (l), tags (tg)

其间括号里边的是简写的方式. 首要是各种方式的时刻表明, 主机名, 进程号, 线程号, 日志层级, 标签.

所以, 到此咱们能够写一个完整的, 包括上面一切涉及到的jcmd VM.log的指令:

$ jcmd 3499 VM.log output="file=/tmp/my.log" what="class=debug" decorators="t,hn,p,ti,l,tg" output_options="filecount=5,filesize=2M"

选项的默许值

关于上面的选项output, output_options, what, decorators 咱们能够省掉, 假如省掉, 则运用的它们的默许值. 它们的默许值别离是:

what: “all=info”
output: “stdout”
output_options: “”
decorators: “uptime,level,tags”

留意上面的 what, 假如单单省掉 what, 默许值是 “all=info“, 假如是运用发动参数 -Xlog, 后边没有给任何选项, 那么等价于: -Xlog:all=warning:stdout:uptime,level,tags

略微复杂的比方

上面的选项的内容都比较简略, 要么是挑选一切的tag, 要么是挑选一个tag, 假如咱们要挑选多个tag 怎么办呢?

挑选多个tags

tag 之间能够运用逗号离隔, 这样就能挑选多个tags, 只需日志标签中包括任何一个这样的标签都会被输出, 比方:

$ jcmd 3499 VM.log what="gc,class,safepoint=debug"

tag 的模糊匹配

咱们能够运用*来模糊匹配标签(tag), 这样匹配任何故gc最初的标签, 比方:

$ jcmd 3499 VM.log what="gc*=debug"

tag 的叠加

咱们能够设置当一个日志行中包括一切咱们要求的标签才能输出, 比方:

$ jcmd 3499 VM.log what="gc+oom"

这样, 当一行日志即包括gc标签, 又包括oom标签, 一起日志的level是info及以上的时分, 才会打印出来.

这里要留意: 没有被显现指明的标签(tag), 只需是warning及以上, 同样会被输出到日志文件

只输出我挑选的标签

假如要关闭其它不想看到的标签日志, 则需求先运用disable=true, 然后在enable其它标签, 如下:

$ jcmd 3499 VM.log disable=true output="file=/tmp/my.log" what="gc=trace"

多个标签不同的日志层级

假如要给不同的标签不同的日志层级, 能够运用下面的方法:

$ jcmd 3499 VM.log what="gc=trace,class=error,threa*=info,class*=off"

总结

经过上面的比方, 咱们看到有3种办法与 JVM 一致的日志结构打交道:

发动参数 -Xlog 适用于发动时分设置
运用 jcmd <pid> VM.log 能够动态调整日志的输出
运用 MBean, 能够动态调整, 没有 jcmd 指令便利

打印日志的选项首要有4个:

what: 挑选标签(tags)和日志层级
output: 挑选输出到哪里 stdout, stderr 或者文件
output_options: 假如挑选输出到文件, 文件的一些选项, 比方巨细和rotate的多少
decorators: 日志行除了日志内容外, 还要加哪些信息.

假如想查看帮助和一切的选项内容, 能够测验下面的指令:

$ jcmd <pid> help VM.log
$ jcmd <pid> VM.log list

期望帮助到需求的人.

JVM 统一的日志框架

引言