JDK 11+ Logging mechanism with -Xlog Option
Environment
- OpenJDK 11+ (11, 17, 21)
- Red Hat Enterprise Linux (RHEL) 7, 8, 9
Issue
- How to configure the logging mechanism for JDK 11+?
- How to configure the heap data for JDK 11+ logging?
- How to get more information about the JDK 11+ logging mechanism?
- How to export the logging information to a file?
Resolution
With Content from openjdk.org is not included.JEP-158 Unified JVM Logging, JDK 11 Logging mechanism unifies the logging to be all below the -Xlog flag and no additional flags are required. This flag will be then appended with options, called selectors (which are pairs <tag-set>=<level>) and decorators.
This is Xlog syntax:
-Xlog:<selectors>:<output>:<decorators>:<output-options>
To define a selector, select a tag, then a level (e.g. gc=debug). To select all tags, use all tag, to combine tags use the + operator (e.g. gc+heap=level). The messages must match exactly the tag, so use the wildcard * to get all messages with a certain tag (e.g. gc*=debug).
Examples:
# To display all messages with tag gc level debug or lower:
./java -Xlog:gc*=debug
# To display only messages with tag gc level trace:
./java -Xlog:gc=trace
To export the log information to a file, like gc.log file, use the file
-Xlog:all=debug:file=gc.log -version
# To get all tags messages, show up to the debug level, output will be on file gc.log on current directory
-Xlog:all=debug:file=gc.log -version
# All the tags with gc and safepoint (ApplicationStoppedTime) to file gc.txt and time
-Xlog:gc*:file=/path/gc.txt:time -version
For log messages tagged with gc tag up to debug level to file gc.txt with
-Xlog:gc=debug:file=gc.txt:none
Decorators are optional so one can set as none
java -Xlog:gc,safepoint=debug:file=gc.txt:none -version
Migrating Java 8 flags to Java 11
| Java 8 | Java 11 equivalent |
|---|---|
| -verbose:gc | -Xlog:gc |
| PrintGCDetails | replaced with -Xlog:gc*, |
| PrintGCApplicationStoppedTime | replaced with -Xlog:safepoint |
| PrintGCTimeStamps | use an uptime decorators: -Xlog:::uptime or Xlog:::uptimemillis or Xlog:::uptimenanos |
| PrintGCDateStamps | use a time decorators: -Xlog:::time or Xlog:::timemillis or Xlog:::timenanos |
| NumberOfGCLogFiles | use filecount output-options |
| GCLogFileSize | use filesize output-options |
Additionally, one can use the level,tags decorators to the see level,tags of each operation.
Example, the following JDK 8 flags:
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=4 -XX:GCLogFileSize=100M -Xloggc:/path/gc.log
And its equivalent on JDK 11 flags (that includes level and tags decorators)
java -Xlog:gc*:file=/path/gc.log:time,uptime,level,tags:filecount=4,filesize=100M -version
Output (that includes level - [info] - and tags - [gc,heap] - decorators output):
[2021-06-04T17:34:25.790-0400][0.003s][info][gc,heap] Heap region size: 1M
[2021-06-04T17:34:25.794-0400][0.007s][info][gc ] Using G1
[2021-06-04T17:34:25.794-0400][0.007s][info][gc,heap,coops] Heap address: 0x000000070d400000, size: 3884 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[2021-06-04T17:34:25.831-0400][0.043s][info][safepoint ] Entering safepoint region: EnableBiasedLocking
[2021-06-04T17:34:25.831-0400][0.044s][info][safepoint ] Leaving safepoint region
[2021-06-04T17:34:25.831-0400][0.044s][info][safepoint ] Total time for which application threads were stopped: 0.0001311 seconds, Stopping threads took: 0.0000253 seconds
Root Cause
After Java 9, there were some changes in the logging mechanism.
JDK 11 logging mechanism changed considerably from the previously supported version since it unified all the information.
The new mechanism, using Xlog is the only flag required so no other flag is necessary for the logging mechanism and the options that come with it all are appended on top of it.
Each message has a tag, and the gc output will only show messages that match exactly the selector that has that tag. Therefore, case of doubt use the all for selecting all tags, and use the * operator as wildcard.
Selectors:
The selectors are based on combinations of tags and levels,
| Tag OR level | Valid options |
|---|---|
| tags-set | class, exceptions, os, gc, heap, module, ref (replaces TraceReferenceGC) |
| level | off, trace, debug, info, warning, error |
Decorators
| Decorator | meaning |
|---|---|
| time | current time and date |
| uptime | time since the start of the JVM |
| pid | process identifier |
| level | level of the message |
| tags | tag associate to the message |
Outputs
| Flag | Output |
|---|---|
| stdout | default output |
| stderr | default error output |
| file | file to be written |
Example: -Xlog:gc*=debug:stdout:time,uptime,level,tags - this sends the output for the pod logs for instance.
Xlog Help
For more information regarding the logging mechanism, including all the log tags and decorators. As below:
java -Xlog:help
Diagnostic Steps
Simple example:
-Xlog:gc*,safepoint=info:file=/desired/path/gc.log:time,uptime:filecount=5,filesize=3M
Above is from here.
Example G1GC with -Xlog:gc* vs -Xlog:gc*=debug vs -Xlog:gc*=trace levels:
Default level - -Xlog:gc*:
It will show the phases and time used on them:
[0.003s][info][gc,heap] Heap region size: 1M
[0.005s][info][gc ] Using G1
[0.005s][info][gc,heap,coops] Heap address: 0x000000070d400000, size: 3884 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[0.101s][info][gc,task ] GC(0) Using 5 workers of 8 for full compaction
[0.101s][info][gc,start ] GC(0) Pause Full (System.gc())
[0.101s][info][gc,phases,start] GC(0) Phase 1: Mark live objects
[0.103s][info][gc,stringtable ] GC(0) Cleaned string and symbol table, strings: 1802 processed, 1 removed, symbols: 22597 processed, 0 removed
[0.103s][info][gc,phases ] GC(0) Phase 1: Mark live objects 1.481ms
[0.103s][info][gc,phases,start] GC(0) Phase 2: Prepare for compaction
[0.103s][info][gc,phases ] GC(0) Phase 2: Prepare for compaction 0.228ms
[0.103s][info][gc,phases,start] GC(0) Phase 3: Adjust pointers
[0.103s][info][gc,phases ] GC(0) Phase 3: Adjust pointers 0.360ms
[0.103s][info][gc,phases,start] GC(0) Phase 4: Compact heap
[0.104s][info][gc,phases ] GC(0) Phase 4: Compact heap 0.420ms
[0.104s][info][gc,heap ] GC(0) Eden regions: 2->0(2)
[0.104s][info][gc,heap ] GC(0) Survivor regions: 0->0(0)
[0.104s][info][gc,heap ] GC(0) Old regions: 0->2
[0.104s][info][gc,heap ] GC(0) Humongous regions: 0->0
[0.104s][info][gc,metaspace ] GC(0) Metaspace: 5526K->5526K(1056768K)
[0.104s][info][gc ] GC(0) Pause Full (System.gc()) 1M->0M(8M) 3.500ms
[0.105s][info][gc,cpu ] GC(0) User=0.01s Sys=0.00s Real=0.01s
[0.105s][info][gc,task ] GC(1) Using 1 workers of 8 for full compaction
[0.105s][info][gc,start ] GC(1) Pause Full (System.gc())
[0.105s][info][gc,phases,start] GC(1) Phase 1: Mark live objects
[0.107s][info][gc,stringtable ] GC(1) Cleaned string and symbol table, strings: 1801 processed, 0 removed, symbols: 22597 processed, 0 removed
[0.107s][info][gc,phases ] GC(1) Phase 1: Mark live objects 1.700ms
[0.107s][info][gc,phases,start] GC(1) Phase 2: Prepare for compaction
[0.107s][info][gc,phases ] GC(1) Phase 2: Prepare for compaction 0.195ms
[0.107s][info][gc,phases,start] GC(1) Phase 3: Adjust pointers
[0.107s][info][gc,phases ] GC(1) Phase 3: Adjust pointers 0.768ms
[0.108s][info][gc,phases,start] GC(1) Phase 4: Compact heap
[0.108s][info][gc,phases ] GC(1) Phase 4: Compact heap 0.213ms
[0.108s][info][gc,heap ] GC(1) Eden regions: 1->0(3)
[0.108s][info][gc,heap ] GC(1) Survivor regions: 0->0(0)
[0.108s][info][gc,heap ] GC(1) Old regions: 2->1
[0.108s][info][gc,heap ] GC(1) Humongous regions: 0->0
[0.108s][info][gc,metaspace ] GC(1) Metaspace: 5527K->5527K(1056768K)
[0.108s][info][gc ] GC(1) Pause Full (System.gc()) 0M->0M(8M) 3.142ms
[0.108s][info][gc,cpu ] GC(1) User=0.00s Sys=0.00s Real=0.00s
[0.109s][info][gc,heap,exit ] Heap
[0.109s][info][gc,heap,exit ] garbage-first heap total 8192K, used 692K [0x000000070d400000, 0x0000000800000000)
[0.109s][info][gc,heap,exit ] region size 1024K, 1 young (1024K), 0 survivors (0K)
[0.109s][info][gc,heap,exit ] Metaspace used 5535K, capacity 5646K, committed 6016K, reserved 1056768K
[0.109s][info][gc,heap,exit ] class space used 473K, capacity 517K, committed 640K, reserved 1048576K
Debug level - -Xlog:gc*=debug:
There will be all the above, i.e. the phases and times, plus details on the metaspace and references usage:
[0.003s][info][gc,heap] Heap region size: 1M
[0.003s][debug][gc,heap] Minimum heap 8388608 Initial heap 255852544 Maximum heap 4072669184
[0.003s][debug][gc ] ConcGCThreads: 2 offset 16
...
[0.095s][debug][gc,phases,ref ] GC(0) Reconsider SoftReferences: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(0) SoftRef (ms): skipped
[0.095s][debug][gc,phases,ref ] GC(0) Notify Soft/WeakReferences: 0.1ms
[0.095s][debug][gc,phases,ref ] GC(0) SoftRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(0) WeakRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(0) FinalRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(0) Total (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(0) Notify and keep alive finalizable: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(0) FinalRef (ms): skipped
[0.095s][debug][gc,phases,ref ] GC(0) Notify PhantomReferences: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(0) PhantomRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(0) SoftReference:
[0.095s][debug][gc,phases,ref ] GC(0) Discovered: 0
[0.095s][debug][gc,phases,ref ] GC(0) Cleared: 0
[0.095s][debug][gc,phases,ref ] GC(0) WeakReference:
[0.095s][debug][gc,phases,ref ] GC(0) Discovered: 92
[0.095s][debug][gc,phases,ref ] GC(0) Cleared: 51
[0.095s][debug][gc,phases,ref ] GC(0) FinalReference:
[0.095s][debug][gc,phases,ref ] GC(0) Discovered: 0
[0.095s][debug][gc,phases,ref ] GC(0) Cleared: 0
[0.095s][debug][gc,phases,ref ] GC(0) PhantomReference:
[0.095s][debug][gc,phases,ref ] GC(0) Discovered: 4
[0.095s][debug][gc,phases,ref ] GC(0) Cleared: 1
...
[0.095s][debug][gc,phases,start] GC(0) ClassLoaderData
[0.095s][debug][gc,phases ] GC(0) ClassLoaderData 0.018ms
[0.095s][debug][gc,phases,start] GC(0) ProtectionDomainCacheTable
[0.095s][debug][gc,phases ] GC(0) ProtectionDomainCacheTable 0.006ms
[0.095s][debug][gc,phases,start] GC(0) ResolvedMethodTable
[0.095s][debug][gc,phases ] GC(0) ResolvedMethodTable 0.007ms
[0.095s][info ][gc,stringtable ] GC(0) Cleaned string and symbol table, strings: 1805 processed, 1 removed, symbols: 22597 processed, 0 removed
[0.095s][debug][gc,phases ] GC(0) Phase 1: Class Unloading and Cleanup 0.300ms
[0.095s][info ][gc,phases ] GC(0) Phase 1: Mark live objects 1.435ms
[0.095s][info ][gc,phases,start] GC(0) Phase 2: Prepare for compaction
[0.095s][info ][gc,phases ] GC(0) Phase 2: Prepare for compaction 0.316ms
[0.095s][info ][gc,phases,start] GC(0) Phase 3: Adjust pointers
[0.096s][info ][gc,phases ] GC(0) Phase 3: Adjust pointers 0.505ms
[0.096s][info ][gc,phases,start] GC(0) Phase 4: Compact heap
[0.096s][info ][gc,phases ] GC(0) Phase 4: Compact heap 0.469ms
[0.097s][debug][gc,ergo,heap ] GC(0) Attempt heap shrinking (capacity higher than max desired capacity after Full GC). Capacity: 255852544B occupancy: 2097152B live: 709384B maximum_desired_capacity: 8388608B (70 %)
[0.097s][debug][gc,ergo,heap ] GC(0) Shrink the heap. requested shrinking amount: 247463936B aligned shrinking amount: 247463936B attempted shrinking amount: 247463936B
[0.097s][debug][gc,ihop ] GC(0) Target occupancy update: old: 255852544B, new: 8388608B
[0.097s][info ][gc,heap ] GC(0) Eden regions: 2->0(2)
[0.097s][info ][gc,heap ] GC(0) Survivor regions: 0->0(0)
[0.097s][info ][gc,heap ] GC(0) Old regions: 0->2
[0.097s][info ][gc,heap ] GC(0) Humongous regions: 0->0
[0.097s][info ][gc,metaspace ] GC(0) Metaspace: 5547K->5547K(1056768K)
[0.097s][debug][gc,heap ] GC(0) Heap after GC invocations=1 (full 1): garbage-first heap total 8192K, used 692K [0x000000070d400000, 0x0000000800000000)
[0.097s][debug][gc,heap ] GC(0) region size 1024K, 0 young (0K), 0 survivors (0K)
[0.097s][debug][gc,heap ] GC(0) Metaspace used 5547K, capacity 5646K, committed 6016K, reserved 1056768K
[0.097s][debug][gc,heap ] GC(0) class space used 471K, capacity 517K, committed 640K, reserved 1048576K
[0.097s][info ][gc ] GC(0) Pause Full (System.gc()) 1M->0M(8M) 3.872ms
[0.098s][info ][gc,cpu ] GC(0) User=0.00s Sys=0.01s Real=0.00s
[0.098s][debug][gc,task ] GC(1) Requesting 1 active workers for full compaction (waste limited workers: 1, adaptive workers: 3)
[0.098s][info ][gc,task ] GC(1) Using 1 workers of 8 for full compaction
[0.098s][info ][gc,start ] GC(1) Pause Full (System.gc())
[0.098s][debug][gc,heap ] GC(1) Heap before GC invocations=1 (full 1): garbage-first heap total 8192K, used 692K [0x000000070d400000, 0x0000000800000000)
[0.098s][debug][gc,heap ] GC(1) region size 1024K, 1 young (1024K), 0 survivors (0K)
[0.098s][debug][gc,heap ] GC(1) Metaspace used 5548K, capacity 5646K, committed 6016K, reserved 1056768K
[0.098s][debug][gc,heap ] GC(1) class space used 471K, capacity 517K, committed 640K, reserved 1048576K
[0.098s][debug][gc,tlab ] GC(1) TLAB totals: thrds: 1 refills: 1 max: 1 slow allocs: 0 max 0 waste: 98.9% gc: 41488B max: 41488B slow: 0B max: 0B fast: 0B max: 0B
[0.098s][debug][gc,alloc,region] GC(1) Mutator Allocation stats, regions: 1, wasted size: 0B ( 0.0%)
[0.098s][info ][gc,phases,start] GC(1) Phase 1: Mark live objects
[0.099s][debug][gc,phases,start] GC(1) Phase 1: Reference Processing
[0.099s][debug][gc,ref ] GC(1) Skipped phase1 of Reference Processing due to unavailable references
[0.099s][debug][gc,ref ] GC(1) Skipped phase3 of Reference Processing due to unavailable references
[0.099s][debug][gc,phases,ref ] GC(1) Reference Processing: 0.1ms
[0.099s][debug][gc,phases,ref ] GC(1) Reconsider SoftReferences: 0.0ms
[0.099s][debug][gc,phases,ref ] GC(1) SoftRef (ms): skipped
[0.099s][debug][gc,phases,ref ] GC(1) Notify Soft/WeakReferences: 0.1ms
[0.099s][debug][gc,phases,ref ] GC(1) SoftRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.099s][debug][gc,phases,ref ] GC(1) WeakRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.099s][debug][gc,phases,ref ] GC(1) FinalRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.099s][debug][gc,phases,ref ] GC(1) Total (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.099s][debug][gc,phases,ref ] GC(1) Notify and keep alive finalizable: 0.0ms
[0.099s][debug][gc,phases,ref ] GC(1) FinalRef (ms): skipped
[0.099s][debug][gc,phases,ref ] GC(1) Notify PhantomReferences: 0.0ms
[0.099s][debug][gc,phases,ref ] GC(1) PhantomRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.099s][debug][gc,phases,ref ] GC(1) SoftReference:
[0.099s][debug][gc,phases,ref ] GC(1) Discovered: 0
[0.099s][debug][gc,phases,ref ] GC(1) Cleared: 0
[0.099s][debug][gc,phases,ref ] GC(1) WeakReference:
[0.099s][debug][gc,phases,ref ] GC(1) Discovered: 7
[0.099s][debug][gc,phases,ref ] GC(1) Cleared: 7
...
[0.101s][info ][gc,heap ] GC(1) Eden regions: 1->0(3)
[0.101s][info ][gc,heap ] GC(1) Survivor regions: 0->0(0)
[0.101s][info ][gc,heap ] GC(1) Old regions: 2->1
[0.101s][info ][gc,heap ] GC(1) Humongous regions: 0->0
[0.101s][info ][gc,metaspace ] GC(1) Metaspace: 5548K->5548K(1056768K)
[0.101s][debug][gc,heap ] GC(1) Heap after GC invocations=2 (full 2): garbage-first heap total 8192K, used 692K [0x000000070d400000, 0x0000000800000000)
[0.101s][debug][gc,heap ] GC(1) region size 1024K, 0 young (0K), 0 survivors (0K)
[0.101s][debug][gc,heap ] GC(1) Metaspace used 5548K, capacity 5646K, committed 6016K, reserved 1056768K
[0.101s][debug][gc,heap ] GC(1) class space used 471K, capacity 517K, committed 640K, reserved 1048576K
[0.101s][info ][gc ] GC(1) Pause Full (System.gc()) 0M->0M(8M) 3.562ms
[0.101s][info ][gc,cpu ] GC(1) User=0.01s Sys=0.00s Real=0.01s
[0.102s][debug][gc,refine ] Stopping 0
[0.102s][info ][gc,heap,exit ] Heap
[0.102s][info ][gc,heap,exit ] garbage-first heap total 8192K, used 692K [0x000000070d400000, 0x0000000800000000)
[0.102s][info ][gc,heap,exit ] region size 1024K, 1 young (1024K), 0 survivors (0K)
[0.102s][info ][gc,heap,exit ] Metaspace used 5557K, capacity 5646K, committed 6016K, reserved 1056768K
[0.102s][info ][gc,heap,exit ] class space used 473K, capacity 517K, committed 640K, reserved 1048576K
Trace level - -Xlog:gc*=trace:
-Xlog:gc*=trace: Trace level will have everything above plus the references on chunk and metachunk creation, and Class Histogram (before and after full gcs):
[0.001s][trace][gc,heap] Maximum heap size 4072516608
[0.002s][trace][gc,heap] Initial heap size 254532288
[0.002s][trace][gc,heap] Minimum heap size 6815736
[0.002s][trace][gc ] MarkStackSize: 4096k MarkStackSizeMax: 16384k
[0.003s][info ][gc,heap] Heap region size: 1M
[0.003s][debug][gc,heap] Minimum heap 8388608 Initial heap 255852544 Maximum heap 4072669184
[0.003s][trace][gc,task] WorkerManager::add_workers() : created_workers: 1
[0.003s][trace][gc,task] Adding initial GC Thread(s) previously created workers 0 active workers 1 total created workers 1
[0.003s][trace][gc,heap,coops] Trying to allocate at address 0x000000070d400000 heap of size 0xf2c00000
[0.003s][trace][gc,barrier ] G1CardTable::G1CardTable:
[0.003s][trace][gc,barrier ] &_byte_map[0]: 0x00007f7f0049e000 &_byte_map[_last_valid_index]: 0x00007f7f00c33fff
[0.003s][trace][gc,barrier ] _byte_map_base: 0x00007f7efcc34000
[0.003s][trace][gc,bot ] G1BlockOffsetTable::G1BlockOffsetTable:
[0.003s][trace][gc,bot ] rs.base(): 0x00007f7f00c34000 rs.size(): 7954432 rs end(): 0x00007f7f013ca000
[0.003s][debug][gc ] ConcGCThreads: 2 offset 16
[0.003s][debug][gc ] ParallelGCThreads: 8
[0.004s][trace][gc,task ] WorkerManager::add_workers() : created_workers: 1
[0.004s][trace][gc,task ] Adding initial G1 Conc(s) previously created workers 0 active workers 1 total created workers 1
[0.004s][debug][gc ] Initialize mark stack with 4096 chunks, maximum 16384
[0.004s][debug][gc,ergo,heap ] Expand the heap. requested expansion amount: 255852544B expansion amount: 255852544B
[0.005s][trace][gc,region ] G1HR COMMIT(FREE) [0x000000070d400000, 0x000000070d400000, 0x000000070d500000]
[0.005s][trace][gc,region ] G1HR COMMIT(FREE) [0x000000070d500000, 0x000000070d500000, 0x000000070d600000]
[0.005s][trace][gc,region ] G1HR COMMIT(FREE) [0x000000070d600000, 0x000000070d600000, 0x000000070d700000]
[0.005s][trace][gc,region ] G1HR COMMIT(FREE) [0x000000070d700000, 0x000000070d700000, 0x000000070d800000]
[0.005s][trace][gc,region ] G1HR COMMIT(FREE) [0x000000070d800000, 0x000000070d800000, 0x000000070d900000]
[0.005s][trace][gc,region ] G1HR COMMIT(FREE) [0x000000070d900000, 0x000000070d900000, 0x000000070da00000]
...
[0.068s][trace][gc,metaspace,freelist ] Metachunk: bottom 0x0000000800061c00 top 0x0000000800061c40 end 0x0000000800062000 size 128 (specialized)
[0.068s][trace][gc,metaspace,freelist ] Free chunk total 0 count 0
[0.068s][trace][gc,metaspace,freelist ] SpaceManager::grow_and_allocate for 29 words 104 words used 24 words left
[0.068s][trace][gc,metaspace,freelist ] ChunkManager::free_chunks_get: free_list: 0x00007f7efc192b30 chunks left: 1.
[0.068s][trace][gc,metaspace,freelist ] ChunkManager::chunk_freelist_allocate: 0x00007f7efc192b30 chunk 0x00007f7ed19ff800 size 128 count 1 Free chunk total 128 count 1
[0.068s][trace][gc,metaspace,freelist,blocks] returning block at 0x00007f7ed19fff40 size = 24
[0.068s][trace][gc,metaspace,freelist ] SpaceManager::added chunk:
[0.068s][trace][gc,metaspace,freelist ] Metachunk: bottom 0x00007f7ed19ff800 top 0x00007f7ed19ff840 end 0x00007f7ed19ffc00 size 128 (specialized)
[0.068s][trace][gc,metaspace,freelist ] Free chunk total 128 count 1
...
Class loading logging:
Using -Xlog:exceptions+info,verification=debug,class+loader+data=trace - also exceptions can help:
[0.027s][info ][class,load] java.io.BufferedOutputStream source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x0000000800023170 super: 0x0000000800022b40 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 1541 checksum: 78b5a34a
[0.027s][info ][class,load] java.io.Writer source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x00000008000233f8 super: 0x0000000800001000 interfaces: 0x000000080000d9a8 0x000000080000eec0 0x0000000800021ee8 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 2925 checksum: d4b3be36
[0.027s][info ][class,load] java.io.OutputStreamWriter source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x00000008000236e0 super: 0x00000008000233f8 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 3677 checksum: f38d8161
[0.027s][info ][class,load] java.nio.charset.Charset source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x00000008000239d8 super: 0x0000000800001000 interfaces: 0x0000000800001408 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 8998 checksum: 6f0faffd
[0.027s][info ][class,load] java.nio.charset.spi.CharsetProvider source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x0000000800023c38 super: 0x0000000800001000 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 1092 checksum: 6fc0e8f0
[0.027s][info ][class,load] sun.nio.cs.StandardCharsets source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x0000000800023e50 super: 0x0000000800023c38 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 16983 checksum: 8573f2e6
[0.027s][info ][class,load] java.lang.ThreadLocal source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x0000000800024460 super: 0x0000000800001000 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 4078 checksum: d1cd7dc2
[0.027s][info ][class,load] java.util.concurrent.atomic.AtomicInteger source: jrt:/java.base
[0.027s][debug][class,load] klass: 0x00000008000246a8 super: 0x0000000800012178 interfaces: 0x0000000800001208 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 5774 checksum: 40a1edb3
[0.028s][info ][class,load] sun.security.action.GetPropertyAction source: jrt:/java.base
[0.028s][debug][class,load] klass: 0x00000008000248e0 super: 0x0000000800001000 interfaces: 0x0000000800017618 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 1875 checksum: dc763f7e
[0.028s][info ][class,load] sun.nio.cs.HistoricallyNamedCharset source: jrt:/java.base <-----
[0.028s][debug][class,load] klass: 0x0000000800024b18 super: 0x0000000800001000 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 188 checksum: be314abc
[0.028s][info ][class,load] sun.nio.cs.Unicode source: jrt:/java.base
[0.028s][debug][class,load] klass: 0x0000000800024d18 super: 0x00000008000239d8 interfaces: 0x0000000800024b18 loader: [loader data: 0x00007f70901d3ef0 of 'bootstrap'] bytes: 2446 checksum: b907b992
Safepoints
Example: -Xlog:gc*=debug,safepoint below - more information on JDK 11 safepoint usage.
[2022-10-20T07:32:47.287+0000][539506.672s][info ][safepoint ] Application time: 1.0000685 seconds
[2022-10-20T07:32:47.288+0000][539506.673s][info ][safepoint ] Entering safepoint region: Cleanup
[2022-10-20T07:32:47.289+0000][539506.673s][info ][safepoint ] Leaving safepoint region
[2022-10-20T07:32:47.289+0000][539506.673s][info ][safepoint ] Total time for which application threads were stopped: 0.0002266 seconds, Stopping threads took: 0.0000506 seconds
Product(s)
Components
Category
Tags
This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.