Embracing JVM unified logging (JEP-158 / JEP-271)

In the previous blog post, I briefly introduced unified logging and a simple GC configuration. However for the savvy GC tuners, there are many more options. And there are other logging options that transitionned to unified logging infrastructure as well.

I wasn’t satisfied with the official documentation and other blog posts as they usually present only a fragmented picture of the previous options. This led me to dig in.

Migrating the GC logging (continued)

Exhaustive translation table

I extracted the following table from the actual patches that implemented JEP-271, see JDK-8059805, JDK-8145092, and in particular the related diff (on github).

In a lesser way I used the official java documentation, which I found somewhat lacking in this regard.

Caveat when using this translation table

I noticed while analyzing GC logs with the above unified logging configuration that some logs I expected were missing, and while doing this translation table I identified the log statements I expected. They had a different tag set.

On the example of heap occupancy logs (IHOP), it was logged with PrintAdaptiveSizePolicy and now it’s supposed to be logged as part of the GC ergonomics by setting gc+ergo* to trace. Looking at the code, I noticed the ihop tag is not always combined with ergo.

This tag is not the only one, in the diff I mentioned previously there’s an interesting file that declares GC log prefix for a list of tag-sets. The diff is huge and may take some time to load, search for the following file
src/share/vm/logging/logPrefix.hpp.

Also, some logging tags are common to multiple GC. While there is nothing wrong in this, it’s easy to update the logging configuration when changing the GC algorithm, e.g. using CMS then switch to G1GC. I would have preferred an additional tag for each GC algorithms (g1 for g1GC, cms for Concurrent Mark and Sweep,shenandoah for Shenandoah, etc) that would have allowed to configure logging this way -Xlog:zgc=info*. Unfortunately this is only a dream at this time.

Moreover, JDK maintainers are improving the JVM sub-systems logging over time, possibly backporting improvements. This makes the tag selection hard to use properly and tedious to maintain. Very few will grep the JDK code base to track which tag they need to tune GCs which is already arcane enough.

The bottom line is that I believe that the configured/selected tags are too restrictive it might be counter-productive to get valuable information, and may even prevent to get log message from loggers that may be added in the future.

Embracing unified logging for GC logs

These caveats led me to think that instead of trying to mimic old logging options, I should instead prefer to log more tags and simplify the overall logging configuration.

-Xlog:gc*=debug,gc+ergo*=trace,gc+age*=trace,safepoint*:file=/gclogs/%t-gc.log:uptime,tags,level:filecount=10,filesize=20M

Log config breakdown

-Xlog:
  gc*=debug,
  gc+ergo*=trace,
  gc+age*=trace,
  safepoint*
  :file=/gclogs/%t-gc.log:uptime,tags,level:filecount=10,filesize=20M

• Line 2: Logs everything under gc at debug level.
• Line 3: Specific tagset level configuration for ergonomics.
• Line 4: Specific tagset level configuration for tenuring distribution.

The above configuration is simpler at the expense of possibly larger file size. Also, using gc*=debug allows it to catch extra tags, and possibly new gc related tags that show up. In my opinion this configuration does not have any caveats.

And as mentioned I benefited from other tags under gc that I wasn’t even looking at before because I simply didn’t think to enable the logging option, like PrintJNIGCStalls in pre-jdk9 jni tag in unified logging or dreaded humongous allocations in G1GC via the humongous tag. In short this simpler configuration enabled more logging, which means GC analysis tool can spot other useful information.

GC tagsets with gc*=debug configuration

• gc,age
• gc,alloc,region
• gc,cpu
• gc,ergo
• gc,ergo,cset
• gc,ergo,ihop
• gc,ergo,refine
• gc,heap
• gc,humongous
• gc,ihop
• gc,jni
• gc,marking
• gc,metaspace
• gc,mmu
• gc,phases
• gc,phases,ref
• gc,phases,start
• gc,plab
• gc,ref
• gc,ref,start
• gc,refine
• gc,remset,tracking
• gc,start
• gc,stats
• gc,stringdedup
• gc,stringtable
• gc,task
• gc,task,stats
• gc,tlab

Of course if one want to focus on a certain part, it is alwasy possible to specify explicitly the tags with a higher logging level.

Try GC logging configurations

Unlike os and container logs, GC happens almost continuously. This opens the opportunity to try log configurations at runtime using jcmd. In the example below I wanted to monitor more thoroughly G1GC regions:

jcmd $(pidof java) \
  VM.log \
    what="gc*=debug,gc+ergo*=trace,gc+age*=trace,gc+region=trace,gc+liveness=trace,safepoint*" \
    decorators=time,tags,level \
    output="file=/var/log/%t-gc-region-tracing.log" \
    output_options="filecount=10,filesize=20M"

Migrating the Trace* flags

One thing I used to log is about classes, particularly during development. Especially loading and unloading. I used this a lot while debugging some aspects of Mockito and some application servers back in the days.

Some of the Trace* flags are still present, even in JDK 14, although they output a warning encouraging to switch to unified logging.

// NOTE: A compatibility request will be necessary for each alias to be removed.
static AliasedLoggingFlag const aliased_logging_flags[] = {
  { "PrintCompressedOopsMode",   LogLevel::Info,  true,  LOG_TAGS(gc, heap, coops) },
  { "PrintSharedSpaces",         LogLevel::Info,  true,  LOG_TAGS(cds) },
  { "TraceBiasedLocking",        LogLevel::Info,  true,  LOG_TAGS(biasedlocking) },
  { "TraceClassLoading",         LogLevel::Info,  true,  LOG_TAGS(class, load) },
  { "TraceClassLoadingPreorder", LogLevel::Debug, true,  LOG_TAGS(class, preorder) },
  { "TraceClassPaths",           LogLevel::Info,  true,  LOG_TAGS(class, path) },
  { "TraceClassResolution",      LogLevel::Debug, true,  LOG_TAGS(class, resolve) },
  { "TraceClassUnloading",       LogLevel::Info,  true,  LOG_TAGS(class, unload) },
  { "TraceExceptions",           LogLevel::Info,  true,  LOG_TAGS(exceptions) },
  { "TraceLoaderConstraints",    LogLevel::Info,  true,  LOG_TAGS(class, loader, constraints) },
  { "TraceMonitorInflation",     LogLevel::Debug, true,  LOG_TAGS(monitorinflation) },
  { "TraceSafepointCleanupTime", LogLevel::Info,  true,  LOG_TAGS(safepoint, cleanup) },
  { "TraceJVMTIObjectTagging",   LogLevel::Debug, true,  LOG_TAGS(jvmti, objecttagging) },
  { "TraceRedefineClasses",      LogLevel::Info,  false, LOG_TAGS(redefine, class) },
  { NULL,                        LogLevel::Off,   false, LOG_TAGS(_NO_TAG) }
};

#ifndef PRODUCT
// These options are removed in jdk9. Remove this code for jdk10.
static AliasedFlag const removed_develop_logging_flags[] = {
  { "TraceClassInitialization",   "-Xlog:class+init" },
  { "TraceClassLoaderData",       "-Xlog:class+loader+data" },
  { "TraceDefaultMethods",        "-Xlog:defaultmethods=debug" },
  { "TraceItables",               "-Xlog:itables=debug" },
  { "TraceMonitorMismatch",       "-Xlog:monitormismatch=info" },
  { "TraceSafepoint",             "-Xlog:safepoint=debug" },
  { "TraceStartupTime",           "-Xlog:startuptime" },
  { "TraceVMOperation",           "-Xlog:vmoperation=debug" },
  { "PrintVtables",               "-Xlog:vtables=debug" },
  { "VerboseVerification",        "-Xlog:verification" },
  { NULL, NULL }
};
#endif //PRODUCT

End words

In this article I provided an exhaustive translation table for GC logging flags and Trace* logging flags. However after using these log configuration the surfacing idea to bring home is there is a better approach than using a one-to-one mapping from flags to tags, instead favoring tag with wildcard resulting in simpler and future-proof log configuration.