Java 查看虚拟机日志

Java JVM About 15,044 words

默认日志

不配置启动参数，默认是warning级别，输出uptime、level、tags三个标识符。

-Xlog:all=warning:stdout:uptime,level,tags

jcmd

使用jcmd的VM.log配置日志级别、输出标签等

❯ jcmd 1 help VM.log

1:
VM.log
Lists current log configuration, enables/disables/configures a log output, or rotates all logs.

Impact: Low: No impact

Permission: java.lang.management.ManagementPermission(control)

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)

查看当前日志设置

❯ jcmd 1 VM.log list

1:
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, aot, arguments, attach, barrier, biasedlocking, blocks, bot, breakpoint, bytecode, cds, census, class, classhisto, cleanup, codecache, compaction, compilation, constantpool, constraints, container, coops, cpu, cset, data, datacreation, dcmd, decoder, defaultmethods, director, dump, ergo, event, exceptions, exit, fingerprint, free, freelist, gc, handshake, hashtables, heap, humongous, ihop, iklass, init, inlining, interpreter, itables, jfr, jit, jni, jvmti, liveness, load, loader, logging, malloc, mark, marking, membername, memops, metadata, metaspace, methodcomparator, mirror, mmu, module, monitorinflation, monitormismatch, nestmates, nmethod, normalize, objecttagging, obsolete, oldobject, oom, oopmap, oops, oopstorage, os, pagesize, parser, patch, path, perf, phases, plab, preorder, preview, promotion, protectiondomain, purge, redefine, ref, refine, region, reloc, remset, resolve, safepoint, sampling, scavenge, setting, smr, stackmap, stacktrace, stackwalk, start, startuptime, state, stats, stringdedup, stringtable, subclass, survivor, sweep, system, table, task, thread, time, timer, tlab, tracking, unload, unshareable, update, verification, verify, vmoperation, vmthread, vtables, vtablestubs, workgang
Described tag sets:
 logging: Logging for the log framework itself
Log output configuration:
 #0: stdout all=warning uptime,level,tags
 #1: stderr all=off uptime,level,tags

动态调整

日志都是标准输出，如配置了控制台输出，文件输出，都会统一输出在一起。

可以调整输出文件及路径。

设置 gc 级别

jcmd 1 VM.log output=#0 what="gc*=debug" decorators="utctime,level,tags"

默认是info级别

jcmd 1 VM.log output=#0 what="gc*" decorators="time,level,tags"

设置 safepoint

同时设置了gc和safepoint。

jcmd 1 VM.log output=#0 what="gc*=trace,safepoint=trace"

不添加标签

decorators设置为"none"即可。

jcmd 1 VM.log output=#0 what="gc*=trace" decorators="none"

启动参数

可以设置JVM的启动参数。

GC

-Xlog:gc*=debug:file=/tmp/gc%t.log:utctime,level,tags:filecount=50,filesize=100M

jit+compilation

-Xlog:jit+compilation=info:file=/tmp/jit_compile%t.log:utctime,level,tags:filecount=10,filesize=10M

Safepoint

-Xlog:safepoint=debug:file=/tmp/safepoint%t.log:utctime,level,tags:filecount=10,filesize=10M

日志示例

[2023-08-02T02:54:15.033+0000][debug][gc,task] GC(7) Requesting 9 active workers for full compaction (waste limited workers: 9, adaptive workers: 9)
[2023-08-02T02:54:15.034+0000][info ][gc,task] GC(7) Using 9 workers of 9 for full compaction
[2023-08-02T02:54:15.034+0000][info ][gc,start] GC(7) Pause Full (Diagnostic Command)
[2023-08-02T02:54:15.034+0000][debug][gc,heap ] GC(7) Heap before GC invocations=7 (full 0): garbage-first heap   total 516096K, used 23014K [0x00000007a0800000, 0x00000007c0000000)
[2023-08-02T02:54:15.034+0000][debug][gc,heap ] GC(7)   region size 1024K, 18 young (18432K), 14 survivors (14336K)
[2023-08-02T02:54:15.034+0000][debug][gc,heap ] GC(7)  Metaspace       used 43132K, capacity 44905K, committed 44928K, reserved 1087488K
[2023-08-02T02:54:15.034+0000][debug][gc,heap ] GC(7)   class space    used 5754K, capacity 6522K, committed 6528K, reserved 1048576K
[2023-08-02T02:54:15.035+0000][debug][gc,tlab ] GC(7) TLAB totals: thrds: 7  refills: 12 max: 4 slow allocs: 0 max 0 waste: 59.1% gc: 1854360B max: 480200B slow: 5392B max: 3296B fast: 0B max: 0B
[2023-08-02T02:54:15.035+0000][debug][gc,alloc,region] GC(7) Mutator Allocation stats, regions: 4, wasted size: 0B ( 0.0%)
[2023-08-02T02:54:15.035+0000][info ][gc,phases,start] GC(7) Phase 1: Mark live objects
[2023-08-02T02:54:15.054+0000][debug][gc,phases,start] GC(7) Phase 1: Reference Processing
[2023-08-02T02:54:15.054+0000][debug][gc,ref         ] GC(7) Skipped phase1 of Reference Processing due to unavailable references
[2023-08-02T02:54:15.055+0000][debug][gc,ref         ] GC(7) Skipped phase3 of Reference Processing due to unavailable references
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7) Reference Processing: 0.1ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   Reconsider SoftReferences: 0.0ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     SoftRef (ms):             skipped
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   Notify Soft/WeakReferences: 0.1ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Balance queues: 0.1ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     SoftRef (ms):             Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 2
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     WeakRef (ms):             Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 2
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     FinalRef (ms):            Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 2
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Total (ms):               Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 2
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   Notify and keep alive finalizable: 0.0ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     FinalRef (ms):            skipped
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   Notify PhantomReferences: 0.0ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     PhantomRef (ms):          Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   SoftReference:
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Discovered: 0
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Cleared: 0
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   WeakReference:
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Discovered: 1740
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Cleared: 1675
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   FinalReference:
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Discovered: 16
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Cleared: 16
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)   PhantomReference:
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Discovered: 328
[2023-08-02T02:54:15.055+0000][debug][gc,phases,ref  ] GC(7)     Cleared: 309
[2023-08-02T02:54:15.055+0000][debug][gc,phases      ] GC(7) Phase 1: Reference Processing 0.263ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,start] GC(7) Phase 1: Weak Processing
[2023-08-02T02:54:15.055+0000][debug][gc,phases      ] GC(7) Phase 1: Weak Processing 0.035ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,start] GC(7) Phase 1: Class Unloading and Cleanup
[2023-08-02T02:54:15.055+0000][debug][gc,phases,start] GC(7) ClassLoaderData
[2023-08-02T02:54:15.055+0000][debug][gc,phases      ] GC(7) ClassLoaderData 0.759ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,start] GC(7) Dictionary
[2023-08-02T02:54:15.055+0000][debug][gc,phases      ] GC(7) Dictionary 0.007ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,start] GC(7) ProtectionDomainCacheTable
[2023-08-02T02:54:15.055+0000][debug][gc,phases      ] GC(7) ProtectionDomainCacheTable 0.004ms
[2023-08-02T02:54:15.055+0000][debug][gc,phases,start] GC(7) ResolvedMethodTable
[2023-08-02T02:54:15.055+0000][debug][gc,phases      ] GC(7) ResolvedMethodTable 0.029ms
[2023-08-02T02:54:15.060+0000][info ][gc,stringtable ] GC(7) Cleaned string and symbol table, strings: 23723 processed, 98 removed, symbols: 139316 processed, 411 removed
[2023-08-02T02:54:15.060+0000][debug][gc,phases      ] GC(7) Phase 1: Class Unloading and Cleanup 5.379ms
[2023-08-02T02:54:15.060+0000][info ][gc,phases      ] GC(7) Phase 1: Mark live objects 25.298ms
[2023-08-02T02:54:15.060+0000][info ][gc,phases,start] GC(7) Phase 2: Prepare for compaction
[2023-08-02T02:54:15.061+0000][info ][gc,phases      ] GC(7) Phase 2: Prepare for compaction 1.013ms
[2023-08-02T02:54:15.061+0000][info ][gc,phases,start] GC(7) Phase 3: Adjust pointers
[2023-08-02T02:54:15.064+0000][info ][gc,phases      ] GC(7) Phase 3: Adjust pointers 2.706ms
[2023-08-02T02:54:15.064+0000][info ][gc,phases,start] GC(7) Phase 4: Compact heap
[2023-08-02T02:54:15.065+0000][info ][gc,phases      ] GC(7) Phase 4: Compact heap 0.955ms
[2023-08-02T02:54:15.066+0000][debug][gc,alloc,stats ] Old generation allocation in the last mutator period, old gen allocated: 0B, humongous allocated: 0B,old gen growth: 0B.
[2023-08-02T02:54:15.066+0000][info ][gc,heap        ] GC(7) Eden regions: 4->0(302)
[2023-08-02T02:54:15.066+0000][info ][gc,heap        ] GC(7) Survivor regions: 14->0(24)
[2023-08-02T02:54:15.066+0000][info ][gc,heap        ] GC(7) Old regions: 7->20
[2023-08-02T02:54:15.066+0000][info ][gc,heap        ] GC(7) Humongous regions: 0->0
[2023-08-02T02:54:15.066+0000][info ][gc,metaspace   ] GC(7) Metaspace: 43132K(44928K)->43114K(44928K) NonClass: 37378K(38400K)->37365K(38400K) Class: 5754K(6528K)->5749K(6528K)
[2023-08-02T02:54:15.066+0000][debug][gc,heap        ] GC(7) Heap after GC invocations=8 (full 1): garbage-first heap   total 516096K, used 18736K [0x00000007a0800000, 0x00000007c0000000)
[2023-08-02T02:54:15.066+0000][debug][gc,heap        ] GC(7)   region size 1024K, 0 young (0K), 0 survivors (0K)
[2023-08-02T02:54:15.066+0000][debug][gc,heap        ] GC(7)  Metaspace       used 43114K, capacity 44876K, committed 44928K, reserved 1087488K
[2023-08-02T02:54:15.066+0000][debug][gc,heap        ] GC(7)   class space    used 5749K, capacity 6512K, committed 6528K, reserved 1048576K
[2023-08-02T02:54:15.066+0000][info ][gc             ] GC(7) Pause Full (Diagnostic Command) 22M->18M(504M) 31.595ms
[2023-08-02T02:54:15.066+0000][info ][gc,cpu         ] GC(7) User=0.11s Sys=0.01s Real=0.03s
[2023-08-02T02:54:15.066+0000][info ][gc,stringdedup ] Concurrent String Deduplication (41.960s)
[2023-08-02T02:54:15.070+0000][debug][gc,refine      ] Activated worker 0, on threshold: 16, current: 16
[2023-08-02T02:54:15.071+0000][debug][gc,refine      ] Deactivated worker 0, off threshold: 13, current: 13, processed: 5
[2023-08-02T02:54:15.071+0000][debug][gc,refine      ] Activated worker 0, on threshold: 16, current: 16
[2023-08-02T02:54:15.072+0000][info ][gc,stringdedup ] Concurrent String Deduplication 1538.4K->743.0K(795.4K) avg 49.3% (41.960s, 41.965s) 5.592ms
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]   Last Exec: 5.592ms, Idle: 26469.845ms, Blocked: 0/0.000ms
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Inspected:           35607
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Skipped:               0(  0.0%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Hashed:             8767( 24.6%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Known:             13789( 38.7%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       New:               21818( 61.3%)   1538.4K
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Deduplicated:        12807( 58.7%)    795.4K( 51.7%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Young:                 0(  0.0%)      0.0B(  0.0%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Old:               12807(100.0%)    795.4K(100.0%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]   Total Exec: 5/8.002ms, Idle: 5/41914.170ms, Blocked: 0/0.000ms
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Inspected:           55450
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Skipped:               0(  0.0%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Hashed:            11730( 21.2%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Known:             23664( 42.7%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       New:               31786( 57.3%)   2077.2K
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Deduplicated:        18447( 58.0%)   1024.6K( 49.3%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Young:              2434( 13.2%)    107.2K( 10.5%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]       Old:               16013( 86.8%)    917.4K( 89.5%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]   Table
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Memory Usage: 976.3K
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Size: 16384, Min: 1024, Max: 16777216
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Entries: 36196, Load: 220.9%, Cached: 0, Added: 36320, Removed: 124
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Resize Count: 4, Shrink Threshold: 10922(66.7%), Grow Threshold: 32768(200.0%)
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Age Threshold: 3
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]   Queue
[2023-08-02T02:54:15.072+0000][debug][gc,stringdedup ]     Dropped: 0
[2023-08-02T02:54:15.072+0000][debug][gc,refine      ] Deactivated worker 0, off threshold: 13, current: 13, processed: 8
[2023-08-02T02:55:08.512+0000][debug][gc,refine      ] Activated worker 0, on threshold: 16, current: 16
[2023-08-02T02:55:08.516+0000][debug][gc,refine      ] Deactivated worker 0, off threshold: 13, current: 13, processed: 3

Java 11 JVM 日志框架

https://docs.oracle.com/en/java/javase/17/docs/specs/man/java.html#enable-logging-with-the-jvm-unified-logging-framework

参考

https://juejin.cn/post/6873020339752796167

https://zhuanlan.zhihu.com/p/528949267

Views: 753 · Posted: 2023-12-12

————        END        ————

Give me a Star, Thanks:)

https://github.com/fendoudebb/LiteNote

扫描下方二维码关注公众号和小程序↓↓↓

扫描下方二维码关注公众号和小程序↓↓↓
Today On History
Browsing Refresh