はじめに
今更な話ですが、JDK 9 JEP 158: Unified JVM Logging にて Java の内部のロギングの仕組みが統一され、統合ログフレームワークが導入されました。
GC ログについても JEP 271: Unified GC Logging により、統合ログフレームワークから出力されるようになり、旧来からの GC ログオプションが利用できなくなりました。
-XX:+PrintGC や -XX:+PrintGCTimeStamps といった GC ログオプションを指定した場合、以下のようなエラーとなり JVM は起動できません。
Unrecognized VM option 'PrintGCTimeStamps' Error: Could not create the Java Virtual Machine. Error: A fatal exception has occurred. Program will exit.
Unified JVM Logging
JVM のログは -Xlog オプションを使い、例えば GC ログの場合、以下のように指定します。
java -jar -Xlog:gc::uptime,tid app.jar
-Xlog:gc::uptime,tid は、gc タグのメッセージを、デフォルトの info レベルで、uptimeとtid を付けて stdout(デフォルト) に出力するという意味になります。
標準出力には以下のようなログが出力されることになります。
[0.023s][22596] Using G1 [2.458s][15736] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 38M->13M(252M) 3.615ms [2.930s][15736] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 37M->18M(252M) 4.711ms [3.871s][15736] GC(2) Pause Young (Concurrent Start) (Metadata GC Threshold) 72M->23M(252M) 6.782ms [3.871s][2780 ] GC(3) Concurrent Mark Cycle [3.881s][15736] GC(3) Pause Remark 25M->25M(94M) 1.896ms [3.885s][15736] GC(3) Pause Cleanup 25M->25M(94M) 0.156ms [3.886s][2780 ] GC(3) Concurrent Mark Cycle 14.530ms ...
-Xlog オプションは、以下のコマンドでヘルプを見ることができます。
java -Xlog:help
-Xlog Usage: -Xlog[:[selections][:[output][:[decorators][:output-options]]]]
where 'selections' are combinations of tags and levels of the form tag1[+tag2...][*][=level][,...]
NOTE: Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.
...
-Xlog[:[selections][:[output][:[decorators][:output-options]]]] の記載にある通り、: で区切り、以下のブロックを指定します。
| ブロック | 説明 |
|---|---|
| selections | タグとログレベルを指定することで対象とするログを指定 |
| output | stdout/stderr/file=<filename> のいずれかでログの出力先を指定 |
| decorators | uptime や tid など、ログを装飾するオプションを指定(カンマ区切りで複数) |
| output-options | filecount=5,filesize=10M のようなログファイルのローテーションなどの出力オプションを指定 |
ログレベルは off, trace, debug, info, warning, error を指定できます。
ログの装飾(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) を指定できます。
none を指定すると装飾なしとなります。
旧来オプションとの相対
| JDK8 オプション | Xlog 構成 |
|---|---|
-XX:+PrintGC or -verbose:gc |
-Xlog:gc |
-XX:+PrintGCDetails |
-Xlog:gc* |
-XX:+PrintHeapAtGC |
-Xlog:gc+heap=debug |
-XX:+PrintAdaptiveSizePolicy |
-Xlog:gc+ergo*=trace |
-XX:+PrintClassHistogramAfterFullGC |
-Xlog:gc+classhisto=trace |
-XX:+PrintClassHistogramBeforeFullGC |
-Xlog:gc+classhisto=trace |
-XX:+PrintGCApplicationConcurrentTime |
-Xlog:safepoint |
-XX:+PrintGCApplicationStoppedTime |
-Xlog:safepoint |
-XX:+PrintGCCause |
常に出力 |
-XX:+PrintGCID |
常に出力 |
-XX:+PrintGCDateStamps |
-Xlog:gc*:file=gc.log:time |
-XX:+PrintGCTimeStamps |
-Xlog:gc*:file=gc.log:uptime |
-XX:+PrintGCTaskTimeStamps |
-Xlog:gc+task+time=debug |
-XX:+PrintHeapAtGCExtended |
-Xlog:gc+heap=trace |
-XX:+PrintJNIGCStalls |
-Xlog:gc+jni=debug |
-XX:+PrintOldPLAB |
-Xlog:gc+plab=trace |
-XX:+PrintParallelOldGCPhaseTimes |
-Xlog:gc+phases=trace |
-XX:+PrintPLAB |
-Xlog:gc+plab=trace |
-XX:+PrintPromotionFailure |
-Xlog:gc+promotion=debug |
-XX:+PrintReferenceGC |
-Xlog:gc+ref=debug |
-XX:+PrintStringDeduplicationStatistics |
-Xlog:gc+stringdedup |
-XX:+PrintTenuringDistribution |
-Xlog:gc+age=trace |
-XX:+PrintTLAB |
-Xlog:gc+tlab=trace |
-XX:+TraceDynamicGCThreads |
-Xlog:gc+task=trace |
-XX:+G1PrintHeapRegions |
-Xlog:gc+region=trace |
-XX:+G1PrintRegionLivenessInfo |
-Xlog:gc+liveness=trace |
-XX:+G1SummarizeConcMark |
-Xlog:gc+marking=trace |
-XX:+G1SummarizeRSetStats |
-Xlog:gc+remset+exit=trace |
-XX:+G1TraceConcRefinement |
-Xlog:gc+refine=debug |
ログファイルとローテーション関連のオプション -Xloggc:gc.log, GCLogFileSize, NumberOfGCLogFiles, UseGCLogFileRotation は以下のように読み替えできます。
-Xlog:gc:file=gc.log::filecount=20,filesize=10M
なお、ファイル名に %p や %t が含まれている場合は、JVMのPIDと起動タイムスタンプに展開されます。
例えば以下のようなオプションを指定していた場合、
-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20 -XX:GCLogFileSize=10M
以下のように書き換えることができるでしょう。
-Xlog:gc*:file=/logs/gc.log:time,uptime:filecount=20,filesize=10M
Xlog ヘルプ全文
手元の JDK22 時点におけるヘルプを乗せておきます。
% java -Xlog:help
-Xlog Usage: -Xlog[:[selections][:[output][:[decorators][:output-options]]]]
where 'selections' are combinations of tags and levels of the form tag1[+tag2...][*][=level][,...]
NOTE: Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.
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)
Decorators can also be specified as 'none' for no decoration.
Available log tags:
add, age, alloc, annotation, arguments, array, attach, barrier, blocks, bot, breakpoint, bytecode, cause, cds, census, class, classhisto, cleanup, codecache, compaction, compilation, condy, constantpool, constraints, container, continuations, coops, cpu, cset, data, datacreation, dcmd, decoder, defaultmethods, deoptimization, dependencies, director, dump, dynamic, ergo, event, exceptions, exit, fastlock, finalizer, fingerprint, free, freelist, gc, handshake, hashtables, heap, heapdump, 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, native, nestmates, nmethod, nmt, normalize, numa, objecttagging, obsolete, oldobject, oom, oopmap, oops, oopstorage, os, owner, page, pagesize, parser, patch, path, perf, periodic, phases, plab, placeholders, preempt, 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, stubs, subclass, survivor, suspend, sweep, symboltable, system, table, task, thread, throttle, timer, tlab, tracking, trimnative, unload, unmap, unshareable, update, valuebasedclasses, verification, verify, vmmutex, vmoperation, vmthread, vtables, vtablestubs
Specifying 'all' instead of a tag combination matches all tag combinations.
Described tag sets:
logging: Logging for the log framework itself
Available log outputs:
stdout/stderr
file=<filename>
If the filename contains %p and/or %t, they will expand to the JVM's PID and startup timestamp, respectively.
Available log output options:
foldmultilines=.. - If set to true, a log event that consists of multiple lines will be folded into a single line by replacing newline characters with the sequence '\' and 'n' in the output. Existing single backslash characters will also be replaced with a sequence of two backslashes so that the conversion can be reversed. This option is safe to use with UTF-8 character encodings, but other encodings may not work.
Additional file output options:
filesize=.. - Target byte size for log rotation (supports K/M/G suffix). If set to 0, log rotation will not trigger automatically, but can be performed manually (see the VM.log DCMD).
filecount=.. - Number of files to keep in rotation (not counting the active file). If set to 0, log rotation is disabled. This will cause existing log files to be overwritten.
Asynchronous logging (off by default):
-Xlog:async
All log messages are written to an intermediate buffer first and will then be flushed to the corresponding log outputs by a standalone thread. Write operations at logsites are guaranteed non-blocking.
Some examples:
-Xlog
Log all messages up to 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.
(Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).
-Xlog:gc
Log messages tagged with 'gc' tag up to 'info' level to stdout, with default decorations.
-Xlog:gc,safepoint
Log messages tagged either with 'gc' or 'safepoint' tags, both up to 'info' level, to stdout, with default decorations.
(Messages tagged with both 'gc' and 'safepoint' will not be logged.)
-Xlog:gc+ref=debug
Log messages tagged with both 'gc' and 'ref' tags, up to 'debug' level, to stdout, with default decorations.
(Messages tagged only with one of the two tags will not be logged.)
-Xlog:gc=debug:file=gc.txt:none
Log messages tagged with 'gc' tag up to 'debug' level to file 'gc.txt' with no decorations.
-Xlog:gc=trace:file=gctrace.txt:uptimemillis,pid:filecount=5,filesize=1m
Log messages tagged with 'gc' tag up to 'trace' level to a rotating fileset of 5 files of size 1MB,
using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.
-Xlog:gc::uptime,tid
Log messages tagged with 'gc' tag up to 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.
-Xlog:gc*=info,safepoint*=off
Log messages tagged with at least 'gc' up to 'info' level, but turn off logging of messages tagged with 'safepoint'.
(Messages tagged with both 'gc' and 'safepoint' will not be logged.)
-Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt
Turn off all logging, including warnings and errors,
and then enable messages tagged with 'safepoint' up to 'trace' level to file 'safepointtrace.txt'.
-Xlog:async -Xlog:gc=debug:file=gc.log -Xlog:safepoint=trace
Write logs asynchronously. Enable messages tagged with 'safepoint' up to 'trace' level to stdout
and messages tagged with 'gc' up to 'debug' level to file 'gc.log'.
