JVM 统一的日志框架
引言
对于基于 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希望帮助到需要的人.
