OpenJDK 11 JVM Logging: A Comprehensive Guide to the New Unified Configuration

#

Hey there, Java enthusiasts! 🚀 Let’s dive into one of the most exciting improvements that came with OpenJDK 11 - the completely revamped JVM logging system. If you’ve been wrestling with the scattered and confusing logging options in OpenJDK 8, you’re in for a treat!

OpenJDK 11 marked the first long-term support release after OpenJDK 8, and boy, did it bring some fantastic changes to JVM logging! The team finally decided to tackle the chaotic mess of logging flags that had developers scratching their heads for years. Gone are the days of juggling dozens of different parameters - welcome to the era of unified, standardized logging configuration!

Understanding JVM Log Tags: Your New Best Friends

#

Think of JVM logging as being remarkably similar to application logging in your Java code. When you write application logs, you typically do something like this:

Logger logger = LogFactory.getLogger("core-logger");
logger.info("this is core logger log");

Which produces output like:

2020-02-05 10:50:52.670  INFO [core-logger] [22] [pool-13-thread-1]: this is core logger log

JVM logs follow the same principle! Check out this example:

[0.182s][debug][jit,compilation]    1       3       java.lang.StringLatin1::hashCode (42 bytes)
[0.183s][debug][jit,compilation]    2       3       java.lang.Object::<init> (1 bytes)
[0.183s][debug][jit,compilation]    3       3       java.lang.String::hashCode (49 bytes)

The default JVM log format includes:

[startup-time][log-level][log-tags-comma-separated] log-content

Each log entry can contain multiple tags, and all JVM logging configuration revolves around these tags. While many tags are designed for JVM developers, several are incredibly useful for performance tuning and debugging. Let me break down the most important ones by category:

1. Garbage Collection Related Tags

#

GC logging offers numerous tag combinations, most starting with the gc tag mixed with others. Here are the essential ones:

Tag gc

This provides high-level GC information. Set it to info level to see GC timing, duration, and memory usage. For example: Pause Young (Normal) (g1 Evacuation Pause) 3480M->1565M(5120M) 15.968ms shows GC type, cause, memory collection size, and duration.

Tag gc,age

Shows age-related information during GC. Objects with higher ages move to the old generation. Trace level outputs detailed size information for each age, while debug level shows only the highest age and expected size:

[2020-02-26T08:34:12.823+0000][debug][gc,age         ] gc(1661) Desired survivor size 167772160 bytes, new threshold 6 (max threshold 6)
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   1:   16125960 bytes,   16125960 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   2:   16259512 bytes,   32385472 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   3:    2435240 bytes,   34820712 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   4:   17179320 bytes,   52000032 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   5:   43986952 bytes,   95986984 total
[2020-02-26T08:34:12.823+0000][trace][gc,age         ] age   6:   20858328 bytes,  116845312 total

Tags gc,alloc and gc,alloc,region

These are G1 GC specific! gc,alloc logs which thread triggered GC and the returned address at trace level - super useful for GC debugging. gc,alloc,region provides region statistics at debug level:

[2020-02-28T02:14:02.694+0000][trace][gc,alloc                    ] sdk-27692-2-amqp-t-4: Successfully scheduled collection returning 0x00000007ffc00000
[2020-02-28T02:16:00.372+0000][debug][gc,alloc,region             ] gc(7848) Mutator Allocation stats, regions: 677, wasted size: 63832B ( 0.0%)

Tag gc,cpu

This is your go-to for GC performance analysis! Info level shows actual GC time consumption:

[2020-02-28T01:59:46.406+0000][info ][gc,cpu                      ] gc(7841) User=0.10s Sys=0.00s Real=0.04s
[2020-02-28T02:01:20.148+0000][info ][gc,cpu                      ] gc(7842) User=0.04s Sys=0.06s Real=0.04s

Note: This timing might differ from JFR statistics since JFR starts counting from GC scheduling, while this measures from actual marking start.

Tags gc,ergo, gc,ergo,cset, gc,ergo,ihop, gc,ergo,refine

These cover Adaptive Size Policy details. Use trace level for deep algorithm study, debug level for general understanding:

[2020-02-28T01:59:46.367+0000][trace][gc,ergo,cset                ] gc(7841) Start choosing CSet. pending cards: 26996 predicted base time: 13.34ms remaining time: 186.66ms target pause time: 200.00ms
[2020-02-28T01:59:46.367+0000][trace][gc,ergo,cset                ] gc(7841) Add young regions to CSet. eden: 676 regions, survivors: 6 regions, predicted young region time: 19.02ms, target pause time: 200.00ms
[2020-02-28T01:59:46.367+0000][debug][gc,ergo,cset                ] gc(7841) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 167.64

Tags gc,heap and gc,heap,region

gc,heap at debug level shows heap overview during GC. For G1 GC, gc,heap,region at trace level prints detailed region information (mainly for debugging):

[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922) Heap before gc invocations=7922 (full 0): garbage-first heap   total 8388608K, used 4076387K [0x0000000600000000, 0x0000000800000000)
[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922)   region size 4096K, 682 young (2793472K), 5 survivors (20480K)
[2020-02-28T06:01:20.787+0000][debug][gc,heap                     ] gc(7922)  Metaspace       used 163068K, capacity 166731K, committed 169728K, reserved 1198080K

Tag gc,humongous

Perfect for G1 GC users experiencing Evacuation Failure or Humongous Allocation issues:

[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 219 object size 2160888 start 0x0000000636c00000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0

Tags gc,metaspace, gc,metaspace,freelist, gc,metaspace,freelist,blocks

Monitor metaspace GC activity. gc,metaspace at info level shows memory changes, while the others provide detailed trace-level information:

[2020-02-28T04:32:13.123+0000][info ][gc,metaspace                ] gc(7896) Metaspace: 163062K->163062K(1198080K)

Tags gc,phases, gc,phases,ref, gc,phases,task, gc,ref, gc,start, gc,ref,start

These are fantastic for understanding GC algorithms and phases in detail.

Tag safepoint

Since GC only happens at safepoints, debug level safepoint logs can be incredibly insightful for GC analysis.

2. Class Loading and Runtime Compilation Tags

#

Tags class,preorder, class,init, class,load, class,unload

Self-explanatory! Info level provides sufficient detail for most use cases. Use trace level for deep-diving into JVM class loading:

[8.931s][debug][class,preorder  ] com.fasterxml.jackson.core.PrettyPrinter source: file:/D:/Repositories/maven/com/fasterxml/jackson/core/jackson-core/2.10.0/jackson-core-2.10.0.jar
[8.931s][info][class,init              ] 2740 Initializing 'com/fasterxml/jackson/core/PrettyPrinter' (0x0000000801399220)
[8.934s][info][class,load              ] com.fasterxml.jackson.core.PrettyPrinter source: file:/D:/Repositories/maven/com/fasterxml/jackson/core/jackson-core/2.10.0/jackson-core-2.10.0.jar

Tag jit,compilation

For JIT compilation optimization, debug level jit,compilation logs are your best friend:

[2020-02-28T03:01:51.619+0000][debug][jit,compilation] 153756   !   4       jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes)   made zombie

3. Other Runtime Related Tags

#

Tag monitorinflation

Synchronization lock logs at debug level - perfect for deadlock debugging:

[5.033s][debug][monitorinflation] Deflating object 0x0000000708310378 , mark 0x0000021cef446002 , type java.lang.ref.ReferenceQueue$Lock

Tag biasedlocking

Biased locking information. Info level for general monitoring, trace level for implementation details:

[7.273s][info ][biasedlocking] Revoking bias by walking my own stack:
[7.273s][info ][biasedlocking] Revoking bias of object 0x0000000711b1ca40, mark 0x000001c6d0acc905, type sun.net.www.protocol.jar.URLJarFile

JVM Log Configuration: Making It All Work Together

#

The configuration format follows this pattern:

-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]

Without any configuration, the default is:

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

This colon-separated configuration breaks down as: what:output:decorators:output-options. Any missing parts use the default values above. These configurations are equivalent:

• -Xlog:all=warning ≡ -Xlog::stdout ≡ -Xlog::::uptime,level,tags ≡ -Xlog:all=warning:stdout:uptime,level,tags
• -Xlog:gc*=info ≡ -Xlog:gc*=info:stdout:uptime,level,tags

1. The “What” Parameter

#

This combines tags and log levels:

• -Xlog:gc=info - Only logs with exactly the gc tag at info level
• -Xlog:gc*=info - All logs containing the gc tag at info level
• -Xlog:gc+age=debug - Logs with exactly gc AND age tags at debug level
• -Xlog:gc*=info,gc+heap=debug,gc+heap+region=debug - Multiple configurations combined

Since age only pairs with gc, these are equivalent:

• -Xlog:gc*=info,age*=debug ≡ -Xlog:gc*=info,gc+age=debug

Log levels include:

• off: Disabled
• trace: All levels (trace, debug, info, warning, error)
• debug: debug, info, warning, error
• info: info, warning, error
• warning: warning, error
• error: error only

No level specified defaults to info! So -Xlog:gc* ≡ -Xlog:gc*=info

2. Output Options

#

Three output types available:

• stdout: Standard output
• stderr: Standard error
• file=filename: File output with options like filecount=50,filesize=100M

3. Decorators: Making Logs Pretty

#

4. Converting Legacy Parameters

#

GC Related Conversions:

Other Conversions:

Dynamic JVM Log Configuration: Real-time Adjustments

#

Here’s where things get really cool! You can modify JVM logging on-the-fly using jcmd with the VM.log command. For a process with PID 22:

jcmd 22 VM.log

Viewing Current Configuration

#

jcmd 22 VM.log list

Sample output:

Log output configuration:
 #0: stdout all=warning uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/log/gc.log all=off,gc*=debug utctime,level,tags filecount=50,filesize=100M
 #3: file=/project/log/jit_compile.log all=off,jit+compilation=debug utctime,level,tags filecount=10,filesize=100M

Rotating Log Files

#

jcmd 22 VM.log rotate

Adding New Log Configuration

#

jcmd 22 VM.log output=/project/core/log/gc.log output_options="filecount=50,filesize=100M" decorators="utctime,level,tags" what="gc*=debug"

Modifying Existing Configuration

#

Configurations are identified by their output parameter. Same output = modification:

jcmd 22 VM.log output=/project/core/log/gc.log what="gc*=info"

Important: Each what setting is additive, not replacement! The system intelligently merges related tags.

Disabling All Logging

#

jcmd 22 VM.log disable

This completely clears all logging configuration, including startup parameters!

And there you have it! The new unified logging system in OpenJDK 11 might seem complex at first, but once you get the hang of it, it’s incredibly powerful and flexible. No more juggling dozens of different flags - just one clean, consistent interface for all your JVM logging needs! 🎉

Happy logging, and may your performance tuning adventures be ever successful! 🚀