Brice Dutheil
gravatar

Java mostly, and general tech

© 2010 - 2022 Brice Dutheil CC BY-SA 4.0
Edit this page

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

2020-07-28
log jvm java unified logging jep-158 jep-271
123 min read

Unified logging was introduced in JDK 9, and is available for us all, in the JDK 11 LTS. Like other great serviceability feature (jcmd or JFR) this was inspired by JRockit.

As a pre-jdk9 users I had my way using the explicit GC logging options. Also, on occasions it was useful to toggle other options like tracing class un/loading.

Starting from JDK 9, the JVM maintainers chose to overhaul the way JVM logs things. I believe that unified logging is great, but after using it I believe its purpose targets more JDK maintainers, eventually library maintainers, than end users. Meanwhile it’s likely that one may need to activate GC logs.

So, while JDK 9 may seem old news today I still find it difficult to know exactly what will be logged. Very well written blogs such as this one from Nicolai Parlog usually only touch the surface of unified logging and usually focus on GC logs. And the official documentation rarely document JVM logging well enough, apart from how old options translate in unified logging.

While GC logging is usually a well covered topic, I found there’s information some gaps like IHOP messages missing as the multitude of tags and their various levels may not be set as necessary.

In my opinion the flexibility of this logging system brought a major downside from a user’s perspective in its configuration correctness, and I think in some ways it’s more obscure compared to the previous explicit logging flags.

Anyway, let’s begin our exploration with a small recapitulation of JEP-158 which lays out the foundation of JVM unified logging.

Unified JVM Logging (JEP-158)

The JEP describes how the logging configuration works in the command line:

java log configuration command line syntax 
-Xlog[:option]
    option         :=  [<what>][:[<output>][:[<decorators>][:<output-options>]]]
                       'help'
                       'disable'
    what           :=  <selector>[,...]
    selector       :=  <tag-set>[*][=<level>]
    tag-set        :=  <tag>[+...]
                       'all'
    tag            :=  name of tag
    level          :=  trace
                       debug
                       info
                       warning
                       error
    output         :=  'stderr'
                       'stdout'
                       [file=]<filename>
    decorators     :=  <decorator>[,...]
                       'none'
    decorator      :=  time
                       uptime
                       timemillis
                       uptimemillis
                       timenanos
                       uptimenanos
                       pid
                       tid
                       level
                       tags
    output-options :=  <output_option>[,...]
    output-option  :=  filecount=<file count>
                       filesize=<file size>
                       parameter=value

This command-line option is the main entry point to unified logging. It allows configuring logs that required multiple options in a single one.

Moreover, it’s now possible to declare multiple log configuration simply by adding additional -Xlog…​ options. Their output must however be unique in these logs, otherwise the last option declaration will override the previous log configuration.

Also, if you already heard of jcmd, unified logging JEP enabled log configurable at runtime. It’s the second main entry point to unified logging. If you didn’t hear about jcmd you really should check it out. It’s the future of the serviceability / diagnostic command on the JDK.

A note about jcmd

Controlling at runtime

Logging can be controlled at runtime through Diagnostic Commands (the jcmd utility). Everything that can be specified on the command line can also be specified dynamically with Diagnostic Commands. Since diagnostic commands are automatically exposed as MBeans it will be possible to use JMX to change logging configuration in runtime.

Now let’s see what we can do with unified logging and profit from the insight it gives in the JVM.

Useful usage of unified logging

How to use the tool, help from the command line

While the JEP explains things, it’s usually not how we get the first contact: We use the command line help, which is describing just as well how to use on the command line.

Also, you may have to enable logs on a running VM, well in this case the jcmd sub-command VM.log is your tool.

java command
$ 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, 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
 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.
  Additional output-options for file outputs:
   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.

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'.
jcmd command
$ jcmd $(pidof java) help VM.log
6:
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)

Configuring unified logging

From the help and the JEP above here’s what to retain:

Tags

When a log message is shown, it should be associated with a set of tags in the JVM which identify by names: os, gc, modules…​

  • We can apply different settings for individual tags.

  • * denotes wildcard tag match. Not using * means all messages matching exactly the specified tags.

Levels

We can perform logging at different levels. The available levels are error, warning, info, debug, trace and develop.

To disable logging, use the alternative off.

Outputs

The output currently supports 3 types: stdout, stderr, or a text file, which can be set up for log file rotation based on written size and a number of files to rotate (for example: each 10MB, keep 5 files in rotation)

Decorators

There are more details about the message called decorators. Here is the list:

  • time/timemillis/timenanos: current time and date (ISO-8601 format)

  • uptime/uptimemillis/uptimenanos: time since the start of the JVM

  • pid: process identifier

  • tid: thread identifier

  • level: level associated with the log message

  • tags: tag associated with the log message

Default settings

  1. tag-set: all.

  2. level: info

  3. output: stdout

  4. decorators: uptime, level, tags

In practice this will give:

java command
-Xlog:pagesize,os*,os+container=trace:file=/var/log/%t-os-container-pagesise.log:uptime,tags,level
jcmd command
$ jcmd $(pidof java) VM.log output=/var/log/%t-os-container-pagesise.log what=pagesize,os*,os+container=trace decorators=uptime,tags,level

The above commands are equivalent, but note that depending on the specified tags and level, the log content may be less useful when enabled at a later time. In the above example in particular the os+container=trace will output some interesting logs only during JVM startup.

Tag set and tag prefixes

In the rest of the article I will mention two related notions about tags. Tags are not hierarchic, however, when their use in the JDK code base suggests there is still some kind of hierarchy.

As we’ll see later some tags are standalone tags, but a large proportion of tags are always logged with other. We could say they are part of a group with a root tag like gc, class, etc. Those are my observations, but let’s look at the JEP-158 diff.

There’s one file that caught attention, it’s logTagSet.hpp

The tagset represents a combination of tags that occur in a log call somewhere. Tagsets are created automatically by the LogTagSetMappings and should never be instantiated directly somewhere else.

So when one sees a class, path combination it’s in fact a tag set. I will refer to these as tag-set, tag set, or tagset. And, I’ll use the term log tag root to indicate that a tag is used as the first tag, it’s generally about a JVM component like GC, classes, or JFR.

There is another construct on top of tagsets, that is called log prefix. We can learn about it in logPrefix.hpp

Prefixes prepend each log message for a specified tagset with the given prefix. A prefix consists of a format string and a value or callback. Prefixes are added after the decorations but before the log message.

Log prefixes allow it to prepend the log message (that’s the prefix) with something for declared tagsets. As we’ll see later there is currently only one list of tagsets that uses the log prefix mechanism, GC logging to print the GC id:

Migrating the GC log configuration (JEP-271)

While this topic may seem covered by other blogs I wasn’t satisfied by the actual equivalence or not of the log configuration. I got the configuration wrong as in incomplete several times until I decided to dive in.

GC unified logging is covered by another JEP, JEP 271: Unified GC Logging, which relies on JEP-158 as mentioned earlier. However, this JEP is much more concise and barely describes how the previous logging option will be turned in unified logs.

One of the best source came from Poonam Bajaj Parhar's talk on unified GC logs However the most interesting data is not searchable because it’s an image of a table and everything is not there, for the poor souls that need to work with other GCs.

The basic translation of the following usual GC logging configuration:

pre-jdk9
-XX:+PrintGCDetails                           \
-XX:+PrintGCApplicationStoppedTime            \
-XX:+PrintGCApplicationConcurrentTime         \
-XX:+PrintGCCause                             \
-XX:+PrintGCID                                \
-XX:+PrintTenuringDistribution                \
-XX:+PrintGCDateStamps                        \
-XX:+UseGCLogFileRotation                     \
-XX:NumberOfGCLogFiles=5                      \
-XX:GCLogFileSize=10M                         \
-Xloggc:/var/log/`date +%FT%H-%M-%S`-gc.log   \

These flags could be translated to the following configuration:

log config
-Xlog:gc*,gc+heap=debug,gc+ref=debug,gc+ergo*=trace,gc+age*=trace,gc+phases*=debug,safepoint*:file=/var/log/%t-gc.log:uptime,tags,level:filecount=10,filesize=20M
log config breakdown
-Xlog:
  gc*, (1)
  gc+heap=debug, (2)
  gc+ref=debug, (3)
  gc+ergo*=trace, (4)
  gc+age*=trace, (5)
  gc+phases*=debug, (6)
  safepoint* (7)
  :file=/var/log/%t-gc.log (8)
  :time,tags,level (9)
  :filecount=5,filesize=10M (10)
1 PrintGCDetails (remember that default level is info)
2 PrintHeapAtGC
3 PrintReferenceGC
4 PrintAdaptiveSizePolicy
5 PrintTenuringDistribution
6 PrintParallelOldGCPhaseTimes
7 PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime
8 Xloggc
9 PrintGCDateStamps (but also decorates with tags and level, useful to know identify the source of the log).
10 UseGCLogFileRotation, NumberOfGCLogFiles, GCLogFileSize

Note that some options do not have equivalents in unified GC logging. Either because the tag system is more precise, or because the log message themselves changed, e.g. the GC cause and the GC id are now always logged.

Now it’s the right opportunity to warn about the slight caveats of this log configuration.

This configuration is fine and works reasonably well, BUT this configuration actually may miss some logs like some ihop, which is not only logged with the ergo tag as we’ll see.

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.

Table 1. Exhaustive GC logging option translation table (with some caveats)
Old GC log flags usually set with -XX:+…​ Equivalent tags with log level Definition of the the old flag

PrintGC -Xloggc:<gc-log-file-path>

gc

Print message at garbage collection

PrintGCDetails -Xloggc:<gc-log-file-path>

gc*

Print more details at garbage collection

-verbose:gc

gc=trace gc+heap=trace gc+heap+exit=trace gc+metaspace=trace gc+sweep=debug gc+heap+ergo=debug

Verbose GC

PrintGCCause

GC cause is now always logged

Include GC cause in GC logging

PrintGCID

GC ID is now always logged

Print an identifier for each garbage collection

PrintGCApplicationStoppedTime

safepoint

Print the time the application has been stopped

PrintGCApplicationConcurrentTime

safepoint

Print the time the application has been running

PrintTenuringDistribution

gc+age*=trace

Print tenuring age information

PrintAdaptiveSizePolicy

gc+ergo*=trace

Print information about AdaptiveSizePolicy

PrintHeapAtGC

gc+heap=debug

Print heap layout before and after each GC

PrintHeapAtGCExtended

gc+heap=trace

Print extended information about the layout of the heap when -XX:+PrintHeapAtGC is set

PrintClassHistogramBeforeFullGC

classhisto*=trace

Print a class histogram before any major stop-world GC

PrintClassHistogramAfterFullGC

classhisto*=trace

Print a class histogram after any major stop-world GC

PrintStringDeduplicationStatistics

gc+stringdedup*=debug

Print string deduplication statistics

PrintJNIGCStalls

gc+jni=debug

Print diagnostic message when GC is stalled by JNI critical section

PrintReferenceGC

gc+ref=debug

Print times spent handling reference objects during GC

PrintGCTaskTimeStamps

task*=debug

Print timestamps for individual gc worker thread tasks

PrintTaskQueue

gc+task+stats=trace

Print taskqueue statistics for parallel collectors

PrintPLAB

gc+plab=trace

Print (survivor space) promotion LAB’s sizing decisions

PrintOldPLAB

gc+plab=trace

Print (old gen) promotion LAB’s sizing decisions

PrintPromotionFailure

gc+promotion=debug

Print additional diagnostic information following promotion failure

PrintTLAB

gc+tlab=trace

Print various TLAB related information (augmented with -XX:+TLABStats)

PrintTerminationStats

gc+task+stats=debug

Print termination statistics for parallel collectors

G1PrintHeapRegions

gc+region=trace

If set G1 will print information on which regions are being allocated and which are reclaimed

G1PrintRegionsLivenessInfo

gc+liveness=trace

Prints the liveness information for all regions in the heap at the end of a marking cycle

G1SummarizeConcMark

gc+marking=trace

Summarize concurrent mark info

G1SummarizeRSets

gc+remset*=trace

Summarize remembered set processing info

G1TraceConcRefinement

gc+refine=debug

Trace G1 concurrent refinement

G1TraceEagerReclaimHumongousObjects

gc+humongous=debug

Print some information about large object liveness at every young GC

G1TraceStringSymbolTableScrubbing

gc+stringdedup=trace

Trace information string and symbol table scrubbing

PrintParallelOldGCPhaseTimes

gc+phases=trace

Print the time taken by each phase in ParallelOldGC

CMSDumpAtPromotionFailure

gc+promotion=trace

Dump useful information about the state of the CMS old generation upon a promotion failure (complemented by flags CMSPrintChunksInDump or CMSPrintObjectsInDump)

CMSPrintEdenSurvivorChunks

gc+heap=trace

Print the eden and the survivor chunks used for the parallel initial mark or remark of the eden/survivor spaces

PrintCMSInitiationStatistics

gc=trace

Statistics for initiating a CMS collection

PrintCMSStatistics

gc=debug (trace) gc+task=trace gc+survivor=trace log+sweep=debug (trace)

Statistics for CMS (complemented by CMSVerifyReturnedBytes)

PrintFLSCensus

gc+freelist+census=debug

Census for CMS' FreeListSpace

PrintFLSStatistics

gc+freelist+stats=debug (trace) gc+freelist*=debug (trace)

Statistics for CMS' FreeListSpace

TraceCMSState

gc+state=debug

Trace the state of the CMS collection

TraceSafepoint

safepoint=debug

Trace application pauses due to VM operations in safepoints

TraceSafepointCleanupTime

safepoint+cleanup=info

break down of clean up tasks performed during safepoint

TraceAdaptativeGCBoundary

heap+ergo=debug

Trace young-old boundary moves

TraceDynamicGCThreads

gc+task=trace

Trace the dynamic GC thread usage

TraceMetadataHumongousAllocation

gc+metaspace+alloc=debug

Trace humongous metadata allocations

VerifySilently

gc+verify=debug

Do not print the verification progress
Table 1. old options are now decorators

PrintGCDateStamps

time

PrintGCTimeStamps

uptime

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 improve 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.

I believe that if we configure/select tags too restrictively it might be counter-productive.

Embracing unified logging for GC logs

This 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.

log config
-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, (1)
  gc+ergo*=trace, (2)
  gc+age*=trace, (3)
  safepoint*
  :file=/gclogs/%t-gc.log:uptime,tags,level:filecount=10,filesize=20M
1 Logs everything under gc at debug level.
2 Specific tagset level configuration for ergonomics.
3 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

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:

Activate a new log configuration
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 other options

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* options are still present, even in JDK 14, although they output a warning.

Table 1. Other tracing option translation

TraceClassInitialization

class+init=info

TraceClassLoading

class+load=info (debug)

TraceClassLoadingPreorder

class+preorder=debug

TraceClassUnloading

class+unload=info (trace)

TraceClassPaths

class+path=info

TraceClassResolution

class+resolve=debug

TraceLoaderConstraints

class+loader+constraints=info

TraceClassLoaderData

class+loader+data=debug (trace)

TraceRedefineClasses

redefine+class*=info (debug, trace)

TraceMonitorInflation

monitorinflation=debug

TraceBiasedLocking

biasedlocking=info (trace)

TraceExceptions

exceptions=info

TraceJVMTIObjectTagging

jvmti+objecttagging=debug
Tracing option declaration in the JVM code base
src/hotspot/share/runtime/arguments.cpp
// 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

Building a unified logging tag reference

Ok nice, but java -Xlog:help lists a lot more available tags than those already mentioned.

The issue with unified logging is the documentation: identifying the tag we want can be tedious. If I select the tag dump what will it output and when, is it about heap dump? Same if I select system: is it about system calls, or else? Well it turns out there’s just no documentation whatsoever, you need to look at the code.

The starting point for this job was this commit and what the JEP-158 proposed:

JEP-158

JVM interface

In the JVM a set of macros will be created with an API similar to:

log_<level>(Tag1[,...])(fmtstr, ...)
    syntax for the log macro

Example:

log_info(gc, rt, classloading)("Loaded %d objects.", object_count)
    the macro is checking the log level to avoid uneccessary
    calls and allocations.

log_debug(svc, debugger)("Debugger interface listening at port %d.", port_number)

The idea of this section is to build a logging tag reference. For that I needed grep and the hotspot repo. I build this reference on the code found in 11.0.7, but I don’t think there was any change in 11.0.8; please keep in mind this is only a snapshot and it’s likely that tags get added or changed in later JVM revisions.

In the commit above there’s an interesting file src/hotspot/share/logging/logTag.hpp that declares all logging tags (138 in total). From there I searched where these tags where used.

Table 1. Log tags

add

redefine

Logs when methods are redefined.

age

gc

GC tenuring distribution and related statistics.

alloc

gc

GC region or space allocation.

annotation

redefine

Logs about annotation during redefinition, this tag appear to be only combined with redefine.

aot

aot

Ahead Of Time mechanism logs.

arguments

JVM options warnings or errors (only errors, unless level is trace), e.g. when using a deprecated logging option that should use unied logging instead.

attach

JVM attachment listener

barrier

gc,xxx

GC Write barrier coverage

biasedlocking

Biased Locking mechanism src/hotspot/share/runtime/biasedLocking.hpp

blocks

oopstorage, gc

bot

gc

Block Offset Table (side data structure with offset information indicating how far back the GC needs to go to find the beginning of an object).

breakpoint

jvmti (Redefinition)

Breakpoint setting or clearing Part of the JVMTI, but logged under redefine log tag root.

bytecode

jfr

Logs about bytecode modifications performed by JFR, always combined with jfr.

cds

cds

Class Data Sharing logs

census

gc

CMS log about freelist information.

class

class, aot

Class related information

classhisto

gc

cleanup

safepoint

Safepoint cleaning information

codecache

codecache, compilation

code cache for generated code: compiled java methods, runtime stubs, transition frames, etc. Segregated in 3 heaps (Non-nmethods like Buffers, Adapters and Runtime Stubs, nmethods that are profiled, nmethods that are not profiled). src/hotspot/share/code/codeCache.cpp

compaction

gc

GC compaction for G1GC and Parallel

compilation

compilation, jit

Compilation

constantpool

class, redefine

Constant pool, logged mostly during redefine

constraints

class

Class loader constraints

container

os

Container (CGroup) related (cpu, cpuset, memory, mountinfo, …​)

coops

gc

Compressed ordinary object pointers

cpu

gc, os

CPU features when logged with os, CPU time ith gc

cset

gc

Collection Set in G1

data

class

Classloader data (allocation space, or metaspace)

datacreation

perf

Related to perf data creation

dcmd

jfr

JFR Diagnostic commands logs always combined with the log tag root by jfr

decoder

Related to ELF decoding (Executable and Linkable Format) on Linux.

defaultmethods

Runtime support for default method. Part of classes, but logged as a standalone tag.

director

gc

Related to ZGC

dump

redefine

Redefinition debug logging about old or obsolete method after redefinition.

ergo

gc

Ergonomics, usually combined with gc, but can be found alone (e.g. for 2 logs about thread local handshakes)

event

jfr

About JFR events

exceptions

exceptions, redefine

About Java exceptions handling in different parts (interpreter, during safepoint, compiler, …​). Specific exception handling during redefined class loading when combined with redefine.

exit

gc

GC/heap related information after GC. LogStreamHandle(Debug, gc, heap, exit) lsh; src/hotspot/share/gc/shared/genCollectedHeap.cpp

fingerprint

class, aot

Class fingerprinting

free

malloc

Log any C stdlib malloc, realloc or free calls, always logged via malloc, free tags.

freelist

gc

Chunks of memory that are supposed to be free, for CMS and metaspace

gc

gc

GC log tag root.

handshake

thread

Thread local handshakes src/hotspot/share/runtime/handshake.hpp

hashtables

When standalone, it’s the internal bucketed hash table, far cousin of a HashMap, Hotspot uses it for strings, and other symbols. CDS uses another internal implementation for statistics, hence this tag may be combined with cds log tag root.

heap

gc

Various GC heap related logs

humongous

gc

Humongous objects in G1GC

ihop

gc

Heap occupancy (initial, current, target) in G1GC

iklass

class, redefine

Internal class instance representation, log tag roots : redefine, classes

init

gc, class

Mostly about class initialization when log tag root is class. About ZGC initialization when combined with gc.

inlining

jit

Method inlining information

interpreter

interpreter

Interpreter logs, only logs with oopmap and safepoint sub-tags.

itables

JVM virtual call mechanism for interface calls, during JVM development (non-product build needed). Also see vtables tag. Hotspot wiki

jfr

jfr

JDK Flight Recorder

jit

jit

Logs about method inlining and compilation

jni

gc

Only logged during GC locker.

jvmti

jvmti

liveness

gc

G1GC region liveness (dead objects vs live objects)

load

gc, class, redefine

Trace all classes loaded, including the redefined ones.

loader

class

Class loader data and constraints

logging

About unified logging

malloc

malloc

Log any C stdlib malloc, realloc or free calls, always logged via malloc, free tags.

mark

redefine

Mark obsolete method during redefine

marking

gc

Marking information for G1GC, CMS, ZGC

membername

Hashtable used by redefinition to replace methods. Used in conjunction with table, but without redefine log tag root.

memops

perf

Memory operation logs initialize and mmap_attach_shared

metadata

jfr, redefine

Logs about class redefinition when log tag root is redefine. Or logs about JFR event metadata, when log tag root is jfr.

metaspace

gc

Logs about the metaspace memory space

methodcomparator

redefine

Logs about method equivalence during redefinition.

mirror

cds

Logs about cds processing of class mirror. A java mirror is an instance of a java.lang.Class.

mmu

gc

Minimum Mutator Utilization is the (time) goal of GC work for G1GC and ZGC. G1GC defines this as a pause time goal (MaxGCPauseMillis) over a time slice (GCPauseIntervalMillis).

module

Module system

monitorinflation

Runtime synchronization support

monitormismatch

Monitor matching failures during OopMapGeneration

nestmates

class, redefine

Nestmate attributes logging logging, seen with log tag roots class or redefine.

nmethod

gc, class, redefine

Native methods (as in compiled code versions of Java methods) logs in various subsystems: gc, class, redefine

normalize

redefine

Logs after method addition, deletion, replacement during redefinition

objecttagging

jvmti

JVMTI object tagging calls

obsolete

redefine

Obsolete method entry mainly for redefinition (and JVMTI)

oldobject

jfr

Old object sampling, currently only logging that a sample was skipped due to lock contention. Log tag root is jfr.

oom

gc

Reported when metaspace is out of memory.

oopmap

interpreter, redefine

Logs on Ordinary Object Pointer caching, combined with by interpreter and redefine.

oops

gc

Ordinary Object Pointers logs in CMS and ZGC

oopstorage

Internal off-heap data structure for management of references to objects allocated in the Java heap

os

os

Operating System interactions logs.

pagesize

Logs about page size. Standalone tag.

parser

jfr

Event used in the JFR parser when reading a recording. Log tag root is jfr.

patch

module

Logging --patch-module

path

class

Class path or module path processing

perf

perf

Logs about JVM perf counters. But when combined with stringtable it’s about interned strings (String.intern()).

phases

gc

Logs that is part of phase of a GC, in particular for ZGC and G1GC.

plab

gc

Logs about per-GC-thread allocation buffer, those are used during GC to prevent thread competition on the same memory space.

preorder

class

Trace all classes loaded in order referenced (not loaded)

preview

Trace loading of preview feature types

promotion

gc

Object promotion logs during GC.

protectiondomain

class

Class protection domain verification.

purge

redefine

Logs about previous class version unloading during redefinition.

redefine

redefine

Class redefinition sub-subsystem, in particular for JVMTI (e.g. when debugging) and with Java agent doing class transformation / re-transformation.

ref

gc

GC object or class references related logs

refine

gc

G1GC logs about refinement threads of the RSet (Remembered set)

region

gc

G1GC logs about region. The alloc and heap combination at debug level will print region statistics, trace level logs the actions and more details that the GC performs on a region.

reloc

gc

ZGC object set relocation.

remset

gc

G1GC remembered set. The tracking and exit tag can come along if level is trace.

resolve

class, aot

Logs about constant pool resolutions, e.g. when loading classes, lambdas, doing reflection, jni

safepoint

safepoint

JVM stop-the-world operations Heap Dump, some GC tasks, de-optimization, biased locking revocation, library loading, etc…​ (src/hotspot/share/runtime/vm_operations.hpp, the operation in this enum are not all in safepoint though). Specific operation logs can be logged with the standalone vmoperation.

sampling

jfr

Old object sampling in JFR. trace level only.

scavenge

gc

CMS, Parallel, and Serial GC scavenge traces.

setting

jfr

Part of jfr, mostly about JFR configuration.

smr

thread

Thread Safe Memory Reclamation (Thread-SMR), hazard pointers. src/hotspot/share/runtime/threadSMR.cpp.

stackmap

redefine

Constant pool changes in method stackmap during redefinition

stacktrace

Logged during Throwable.fillInStackTrace().

stackwalk

Logs when using StackWalker.

start

gc, codecache

Indicates a ZGC phase start, thus it’s combined with gc. But can also indicate other operation start, like for codecache.

startuptime

Logs the JVM subsystems startup time (interpreter, GC, module systems, class loading, aot, genesis which is about memory zones …​)

state

gc

CMS GC states.

stats

gc

GC stats logs. Also seen with (oopstorage, blocks tag set).

stringdedup

gc

G1GC string deduplication (for old generation)

stringtable

About interned strings (String.intern()), can be seen with the gc log tag root when G1GC is in use to log string and symbol cleanups.

subclass

class, redefine

Sub-class unloading. Affected subclasses during redefinition.

survivor

gc

CMS GC survivor information.

sweep

gc, codecache

CMS GC sweeping activity. And code cache native methods flushing depending on the log tag root.

system

jfr

JFR system logging, recording start/stop, emergency dump, etc.

table

membername

Only used with membername, about the hashtable to record methods, and replace them during redefinition.

task

gc

Mostly related to GC tasks, useful to see the phases tag. Also appears combined with handshake for thread local handshakes.

thread

os

When used as a log tag root, it’s about smr, when it’s combined with the os log tag root it’s about the thread lifecycle and guards.

time

gc

Timed Parallel GC operations

timer

thread, redefine

Timed redefine operation, and thread exit

tlab

gc

Thread local allocation buffers statistics (trace)

tracking

gc

G1GC remembered set tracking

unload

class

Class or module unloading

unshareable

cds

For classes that cannot be shared, especially interesting during CDS archive creation

update

redefine

Logs about redefinition changes in classes, methods, constant pool, vtable, itable, etc.

verification

Classes bytecode verifier, when standalone. Same for classes in CDS archive when combined with cds.

verify

gc

Verification operations done during GC operations.

vmoperation

Logs VM operations

vmthread

JVM threads that perform the VM operations (usually during safepoints)

vtables

Java’s virtual calls mechanism (virtual table allows to find the right method address for the current instance in a hierarchy of classes). Those that did C++ before will remember.

vtablestubs

Java’s virtual calls mechanism that is used for megamorphic call sites (i.e. when the method to execute is not the same on successive executions because the object hierarchy differ). Hotspot wiki 1 2

workgang

gc

GC worker threads.

In building this reference we see that some JVM sub-systems can output a lot of logs. Two subsystems stands out in the way they describe their tagsets: JFR and the Garbage Collection:

JFR tag sets
src/hotspot/share/jfr/utilities/jfrLogTagSets.hpp
#define JFR_LOG_TAG_SET_LIST \
  JFR_LOG_TAG(jfr) \
  JFR_LOG_TAG(jfr, system) \
  JFR_LOG_TAG(jfr, system, event) \
  JFR_LOG_TAG(jfr, system, setting) \
  JFR_LOG_TAG(jfr, system, bytecode) \
  JFR_LOG_TAG(jfr, system, parser) \
  JFR_LOG_TAG(jfr, system, metadata) \
  JFR_LOG_TAG(jfr, metadata) \
  JFR_LOG_TAG(jfr, event) \
  JFR_LOG_TAG(jfr, setting) \
  JFR_LOG_TAG(jfr, dcmd)
  /* NEW TAGS, DONT FORGET TO UPDATE JAVA SIDE */

However, note that the tags seen above are not all used in the VM native code, instead JFR is unique in its genre as it is using unified logging in its Java code base. For that the above C++ enum is bound as Java enum src/jdk.jfr/share/classes/jdk/jfr/internal/LogTag.java, and can call the native log method via this src/jdk.jfr/share/classes/jdk/jfr/internal/JVM.java class.

GC tag sets, declared to print the message prefix
src/hotspot/share/logging/logPrefix.hpp#L45-L90
#define LOG_PREFIX_LIST \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, age)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, alloc)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, alloc, region)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, barrier)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, classhisto)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, compaction)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, cpu)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo, cset)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo, heap)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo, ihop)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo, refine)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, heap)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, heap, region)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, freelist)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, humongous)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ihop)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, liveness)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, load)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, marking)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, metaspace)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, mmu)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, nmethod)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, ref)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, start)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, task)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, plab)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, region)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, remset)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, remset, tracking)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ref)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ref, start)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, reloc)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, start)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, stringtable)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, sweep)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, start)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, stats)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, time)) \
  DEBUG_ONLY(LOG_PREFIX(Test_log_prefix_prefixer, LOG_TAGS(logging, test))) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, tlab)) \
  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, workgang))
Classes, Classloading, JVMTI, compiler, etc.

The other tag-sets are not declared, so I’m listing some of them in a non exhaustive way for the other major JVM component.

AOT src/hotspot/share/aot/aotCodeHeap.cpp

  • log_debug(aot, class, resolve)

  • log_info(aot, class, resolve)

  • log_trace(aot, class, fingerprint)

  • log_trace(aot, class, load)

Classes
Class file loading, linking
Class loading service
Constant Pool
Native methods (compiled code versions of Java methods)
Memory
OOPS
JNI
Reflection
Class Data Sharing
Redefinition
Method comparator (equivalent modulo constant pool or EMCP)
Native methods (compiled code versions of Java methods)
CPU specific
Constant pool
Class, vtables, itables
Interpreter
JVMTI
Java Virtual Machine Tool Interface (JVMTI, JSR-163)
Compilation, Just-in-Time, Interpreter

Interpreter * log_debug(interpreter, oopmap) src/hotspot/share/interpreter/oopMapCache.cpp * log_debug(interpreter, safepoint) src/hotspot/share/interpreter/templateInterpreter.cpp

Other tags combinations examples

OS and container related

If the workload you are working on is running on containers you may have heard of the os and container tags:

os, container, pagesize logs
$ head -n 200 /var/log/2020-05-22_22-28-32-os-container-pagezise.log
[0.003s][trace][os,container] OSContainer::init: Initializing Container Support
[0.003s][trace][os,container] Path to /memory.use_hierarchy is /sys/fs/cgroup/memory/memory.use_hierarchy
[0.003s][trace][os,container] Use Hierarchy is: 1
[0.003s][trace][os,container] Path to /memory.limit_in_bytes is /sys/fs/cgroup/memory/memory.limit_in_bytes
[0.003s][trace][os,container] Memory Limit is: 5368709120
[0.003s][info ][os,container] Memory Limit is: 5368709120
[0.003s][trace][os,container] Path to /cpu.cfs_quota_us is /sys/fs/cgroup/cpu/cpu.cfs_quota_us
[0.003s][trace][os,container] CPU Quota is: -1
[0.003s][trace][os,container] Path to /cpu.cfs_period_us is /sys/fs/cgroup/cpu/cpu.cfs_period_us
[0.003s][trace][os,container] CPU Period is: 100000
[0.003s][trace][os,container] Path to /cpu.shares is /sys/fs/cgroup/cpu/cpu.shares
[0.004s][trace][os,container] CPU Shares is: 1024
[0.004s][trace][os,container] OSContainer::active_processor_count: 4
[0.004s][trace][os,container] Path to /cpu.cfs_quota_us is /sys/fs/cgroup/cpu/cpu.cfs_quota_us
[0.004s][trace][os,container] CPU Quota is: -1
[0.004s][trace][os,container] Path to /cpu.cfs_period_us is /sys/fs/cgroup/cpu/cpu.cfs_period_us
[0.004s][trace][os,container] CPU Period is: 100000
[0.004s][trace][os,container] Path to /cpu.shares is /sys/fs/cgroup/cpu/cpu.shares
[0.004s][trace][os,container] CPU Shares is: 1024
[0.004s][trace][os,container] OSContainer::active_processor_count: 4
[0.004s][info ][os          ] Use of CLOCK_MONOTONIC is supported
[0.004s][info ][os          ] Use of pthread_condattr_setclock is supported
[0.004s][info ][os          ] Relative timed-wait using pthread_cond_timedwait is associated with CLOCK_MONOTONIC
[0.004s][info ][os          ] HotSpot is running with glibc 2.28, NPTL 2.28
[0.005s][info ][os          ] SafePoint Polling address, bad (protected) page:0x00007fa25e8ee000, good (unprotected) page:0x00007fa25e8ef000
[0.005s][info ][os          ] attempting shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libinstrument.so
[0.005s][info ][os          ] shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libinstrument.so was successful
[0.005s][info ][os          ] attempting shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libinstrument.so
[0.005s][info ][os          ] shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libinstrument.so was successful
[0.006s][info ][os          ] attempting shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libinstrument.so
[0.006s][info ][os          ] shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libinstrument.so was successful
[0.008s][info ][os,thread   ] Thread attached (tid: 8, pthread id: 140335320479488).
[0.008s][info ][os          ] attempting shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libzip.so
[0.008s][info ][os          ] shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libzip.so was successful
[0.008s][info ][os          ] attempting shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libjimage.so
[0.008s][info ][os          ] shared library load of /usr/lib/jvm/java-11-amazon-corretto/lib/libjimage.so was successful
[0.008s][trace][os,container] Path to /cpu.cfs_quota_us is /sys/fs/cgroup/cpu/cpu.cfs_quota_us
[0.008s][trace][os,container] CPU Quota is: -1
[0.008s][trace][os,container] Path to /cpu.cfs_period_us is /sys/fs/cgroup/cpu/cpu.cfs_period_us
[0.008s][trace][os,container] CPU Period is: 100000
[0.008s][trace][os,container] Path to /cpu.shares is /sys/fs/cgroup/cpu/cpu.shares
[0.008s][trace][os,container] CPU Shares is: 1024
[0.009s][trace][os,container] OSContainer::active_processor_count: 4
[0.009s][info ][pagesize    ] CodeHeap 'non-nmethods':  min=2496K max=5696K base=0x00007fa24090d000 page_size=4K size=5696K
[0.009s][info ][pagesize    ] CodeHeap 'profiled nmethods':  min=2496K max=120032K base=0x00007fa240e9d000 page_size=4K size=120032K
[0.009s][info ][pagesize    ] CodeHeap 'non-profiled nmethods':  min=2496K max=120032K base=0x00007fa2483d5000 page_size=4K size=120032K
[0.010s][info ][os,cpu      ] CPU:total 4 (initial active 4) (1 cores per cpu, 1 threads per core) family 6 model 142 stepping 10, cmov, cx8, fxsr, mmx, sse, sse2, sse3, ssse3, sse4.1, sse4.2, popcnt, avx, avx2, aes, clmul, erms, 3dnowpref, lzcnt, tsc, tscinvbit, bmi1, bmi2, fma
[0.010s][info ][os,cpu      ] CPU Model and flags from /proc/cpuinfo:
[0.010s][info ][os,cpu      ] model name  : Intel(R) Core(TM) i7-8559U CPU @ 2.70GHz
[0.010s][info ][os,cpu      ] flags               : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht pbe syscall nx pdpe1gb lm constant_tsc rep_good nopl xtopology nonstop_tsc cpuid tsc_known_freq pni pclmulqdq dtes64 ds_cpl ssse3 sdbg fma cx16 xtpr pcid sse4_1 sse4_2 movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch pti fsgsbase bmi1 avx2 bmi2 erms xsaveopt arat
[0.010s][info ][os,thread   ] Thread started (pthread id: 140335306258176, attributes: stacksize: 1024k, guardsize: 4k, detached).
[0.010s][info ][os,thread   ] Thread is alive (tid: 9, pthread id: 140335306258176).
[0.011s][info ][pagesize    ] Heap:  min=8M max=768M base=0x00000000d0000000 page_size=4K size=768M
[0.011s][info ][pagesize    ] Block Offset Table: req_size=1536K base=0x00007fa240389000 page_size=4K alignment=4K size=1536K
[0.011s][info ][pagesize    ] Card Table: req_size=1536K base=0x00007fa240209000 page_size=4K alignment=4K size=1536K
[0.011s][info ][pagesize    ] Card Counts Table: req_size=1536K base=0x00007fa240089000 page_size=4K alignment=4K size=1536K
[0.011s][info ][pagesize    ] Prev Bitmap: req_size=12M base=0x00007fa23b400000 page_size=4K alignment=4K size=12M
[0.011s][info ][pagesize    ] Next Bitmap: req_size=12M base=0x00007fa23a800000 page_size=4K alignment=4K size=12M
[0.011s][info ][os,thread   ] Thread started (pthread id: 140334742894336, attributes: stacksize: 1024k, guardsize: 4k, detached).
[0.011s][info ][os,thread   ] Thread is alive (tid: 10, pthread id: 140334742894336).
[0.011s][info ][os,thread   ] Thread started (pthread id: 140334741837568, attributes: stacksize: 1024k, guardsize: 4k, detached).
[0.011s][info ][os,thread   ] Thread is alive (tid: 11, pthread id: 140334741837568).
[0.012s][info ][os,thread   ] Thread started (pthread id: 140334703015680, attributes: stacksize: 1024k, guardsize: 4k, detached).
[0.012s][info ][os,thread   ] Thread is alive (tid: 12, pthread id: 140334703015680).
[0.012s][info ][os,thread   ] Thread started (pthread id: 140334499624704, attributes: stacksize: 1024k, guardsize: 4k, detached).
[0.012s][info ][os,thread   ] Thread is alive (tid: 13, pthread id: 140334499624704).
[0.021s][info ][os,thread   ] Thread started (pthread id: 140334490179328, attributes: stacksize: 1024k, guardsize: 4k, detached).
[0.021s][info ][os,thread   ] Thread is alive (tid: 14, pthread id: 140334490179328).
[0.024s][trace][os,container] Path to /cpu.cfs_quota_us is /sys/fs/cgroup/cpu/cpu.cfs_quota_us
[0.024s][trace][os,container] CPU Quota is: -1
[0.024s][trace][os,container] Path to /cpu.cfs_period_us is /sys/fs/cgroup/cpu/cpu.cfs_period_us
[0.024s][trace][os,container] CPU Period is: 100000
[0.024s][trace][os,container] Path to /cpu.shares is /sys/fs/cgroup/cpu/cpu.shares
[0.024s][trace][os,container] CPU Shares is: 1024
[0.024s][trace][os,container] OSContainer::active_processor_count: 4
[0.025s][info ][os,thread   ] Thread started (pthread id: 140334489122560, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.025s][info ][os,thread   ] Thread is alive (tid: 15, pthread id: 140334489122560).
[0.025s][info ][os,thread   ] Thread started (pthread id: 140334488069888, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.025s][info ][os,thread   ] Thread is alive (tid: 16, pthread id: 140334488069888).
[0.033s][info ][os,thread   ] Thread started (pthread id: 140334485497600, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.033s][info ][os,thread   ] Thread is alive (tid: 17, pthread id: 140334485497600).
[0.033s][info ][os,thread   ] Thread started (pthread id: 140334484444928, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.033s][info ][os,thread   ] Thread is alive (tid: 18, pthread id: 140334484444928).
[0.033s][info ][os,thread   ] Thread started (pthread id: 140334483392256, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.034s][info ][os,thread   ] Thread is alive (tid: 19, pthread id: 140334483392256).
[0.034s][info ][os,thread   ] Thread started (pthread id: 140334482339584, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.035s][info ][os,thread   ] Thread is alive (tid: 20, pthread id: 140334482339584).
[0.036s][trace][os,container] Path to /memory.limit_in_bytes is /sys/fs/cgroup/memory/memory.limit_in_bytes
[0.036s][trace][os,container] Memory Limit is: 5368709120
[0.036s][trace][os,container] Path to /memory.usage_in_bytes is /sys/fs/cgroup/memory/memory.usage_in_bytes
[0.036s][trace][os,container] Memory Usage is: 9551872
[0.037s][trace][os,container] Path to /memory.usage_in_bytes is /sys/fs/cgroup/memory/memory.usage_in_bytes
[0.037s][trace][os,container] Memory Usage is: 9682944
...
[0.058s][trace][os,container] Path to /memory.limit_in_bytes is /sys/fs/cgroup/memory/memory.limit_in_bytes
[0.058s][trace][os,container] Memory Limit is: 5368709120
[0.058s][trace][os,container] Path to /memory.usage_in_bytes is /sys/fs/cgroup/memory/memory.usage_in_bytes
[0.058s][trace][os,container] Memory Usage is: 12820480
...
[0.064s][info ][os,thread   ] Thread started (pthread id: 140334481286912, attributes: stacksize: 1024k, guardsize: 0k, detached).
[0.064s][info ][os,thread   ] Thread is alive (tid: 21, pthread id: 140334481286912).
...
[8005.132s][trace][os,container] Path to /memory.limit_in_bytes is /sys/fs/cgroup/memory/memory.limit_in_bytes
[8005.132s][trace][os,container] Memory Limit is: 5368709120
[8005.132s][trace][os,container] Path to /memory.usage_in_bytes is /sys/fs/cgroup/memory/memory.usage_in_bytes
[8005.132s][trace][os,container] Memory Usage is: 4093734912
[8014.238s][trace][os,container] Path to /memory.limit_in_bytes is /sys/fs/cgroup/memory/memory.limit_in_bytes
[8014.238s][trace][os,container] Memory Limit is: 5368709120
[8014.238s][trace][os,container] Path to /memory.usage_in_bytes is /sys/fs/cgroup/memory/memory.usage_in_bytes
[8014.238s][trace][os,container] Memory Usage is: 4093943808
...

Class redefinition

public class AgentTest {

    public static void main(String[] args) {
        Foo foo = new Foo();
        System.out.printf("[%.3fs][stdout] m(): %s%n",
                          ManagementFactory.getRuntimeMXBean().getUptime() / 1000d,
                          foo.m());

        ByteBuddyAgent.install();
        new ByteBuddy()
                .redefine(Bar.class)
                .name(Foo.class.getName())
                .make()
                .load(Foo.class.getClassLoader(), ClassReloadingStrategy.fromInstalledAgent());

        System.out.printf("[%.3fs][stdout] m(): %s%n",
                          ManagementFactory.getRuntimeMXBean().getUptime() / 1000d,
                          foo.m());
    }

    private static class Foo {
        String m() { return "foo"; }
    }
    private static class Bar {
        String m() { return "bar"; }
    }
}
Logs when running the code snippet
$ java -Xlog:redefine+class*=debug -cp .:./lib/byte-buddy-agent-1.10.13.jar:./lib/byte-buddy-1.10.13.jar AgentTest
[0.151s][stdout] m(): foo
[0.688s][debug][redefine,class,load] loading name=AgentTest$Foo kind=101 (avail_mem=108304K)
[0.688s][info ][redefine,class,constantpool] old_cp_len=25, scratch_cp_len=29
[0.688s][debug][redefine,class,constantpool] after pass 0: merge_cp_len=25
[0.688s][debug][redefine,class,constantpool] after pass 1a: merge_cp_len=31, scratch_i=25, index_map_len=6
[0.688s][debug][redefine,class,constantpool] after pass 1b: merge_cp_len=31, scratch_i=29, index_map_len=10
[0.688s][info ][redefine,class,constantpool] merge_cp_len=31, index_map_len=10
[0.688s][debug][redefine,class,load        ] loaded name=AgentTest$Foo (avail_mem=108304K)
[0.690s][info ][redefine,class,update      ] adjust: name=AgentTest$Foo
[0.690s][debug][redefine,class,update,constantpool] cpc special, static or dynamic entry update: <init>(()V)
[0.690s][info ][redefine,class,load               ] redefined name=AgentTest$Foo, count=1 (avail_mem=108304K)
[0.690s][info ][redefine,class,timer              ] vm_op: all=0  prologue=0  doit=0
[0.690s][info ][redefine,class,timer              ] redefine_single_class: phase1=0  phase2=0
[0.690s][stdout] m(): bar

These logs are quite technical, but they may be useful when developing agents.

During debug

import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.management.ManagementFactory;

public class DebugTest {

    public static void main(String[] args) {
        var foo = new Foo();
        System.out.printf("[%.3fs][stdout] m(): %s%n",  (1)
                          ManagementFactory.getRuntimeMXBean().getUptime() / 1000d,
                          foo.m());
        System.out.printf("[%.3fs][stdout] m(): %s%n",  // in debug advance by one step
                          ManagementFactory.getRuntimeMXBean().getUptime() / 1000d,
                          foo.m());
    }

    private static class Foo {
        @Alpha(v = "bim")
        String m() { return "foo"; }
    }

    @Retention(RetentionPolicy.RUNTIME)
    @interface Alpha { String v(); }

    @Retention(RetentionPolicy.RUNTIME)
    @interface Beta { String val(); }
}
1 Set break point here, then change the inner class Foo, like the annotation value, adds another instruction, change the return values of m(), etc.
Change Foo.m() class after instantiation during debug
$ java -Xlog:redefine*=trace,jvmti*=trace -agentlib:jdwp=transport=dt_socket,server=n,suspend=y,address=61222 -cp . DebugTest
[51.942s][debug][redefine,class,load] loading name=sandbox.DebugTest kind=102 (avail_mem=1416012K)         (1)
[51.942s][trace][redefine,class,normalize] Method matched: new: sandbox.DebugTest.<init>()V [0] == old: sandbox.DebugTest.<init>()V [0]
[51.942s][trace][redefine,class,normalize] Method matched: new: sandbox.DebugTest.main([Ljava/lang/String;)V [1] == old: sandbox.DebugTest.main([Ljava/lang/String;)V [1]
[51.942s][info ][redefine,class,constantpool] old_cp_len=91, scratch_cp_len=91
[51.942s][debug][redefine,class,constantpool] after pass 0: merge_cp_len=91
[51.942s][debug][redefine,class,constantpool] after pass 1a: merge_cp_len=91, scratch_i=91, index_map_len=0
[51.942s][info ][redefine,class,constantpool] merge_cp_len=91, index_map_len=0
[51.942s][debug][redefine,class,load        ] loaded name=sandbox.DebugTest (avail_mem=1416012K)
[51.942s][debug][redefine,class,load        ] loading name=sandbox.DebugTest$Foo kind=102 (avail_mem=1416012K)
[51.942s][trace][redefine,class,normalize   ] Method matched: new: sandbox.DebugTest$Foo.<init>()V [0] == old: sandbox.DebugTest$Foo.<init>()V [0]
[51.942s][trace][redefine,class,normalize   ] Method matched: new: sandbox.DebugTest$Foo.m()Ljava/lang/String; [1] == old: sandbox.DebugTest$Foo.m()Ljava/lang/String; [1]
[51.942s][info ][redefine,class,constantpool] old_cp_len=40, scratch_cp_len=48                             (2)
[51.942s][debug][redefine,class,constantpool] after pass 0: merge_cp_len=40
[51.942s][trace][redefine,class,constantpool] mapped tag 8 at index 7 to 40
[51.942s][trace][redefine,class,constantpool] mapped tag 1 at index 8 to 41
[51.942s][trace][redefine,class,constantpool] mapped tag 1 at index 12 to 42
[51.942s][trace][redefine,class,constantpool] Class entry@43 name_index change: 12 to 42
[51.942s][trace][redefine,class,constantpool] mapped tag 100 at index 10 to 43
[51.942s][trace][redefine,class,constantpool] mapped tag 1 at index 13 to 44
[51.942s][trace][redefine,class,constantpool] mapped tag 1 at index 14 to 45
[51.942s][trace][redefine,class,constantpool] NameAndType entry@46 name_ref_index change: 13 to 44
[51.942s][trace][redefine,class,constantpool] NameAndType entry@46 signature_ref_index change: 14 to 45
[51.942s][trace][redefine,class,constantpool] mapped tag 12 at index 11 to 46
[51.942s][trace][redefine,class,constantpool] Methodref entry@47 class_index changed: 10 to 43
[51.942s][trace][redefine,class,constantpool] Methodref entry@47 name_and_type_index changed: 11 to 46
[51.942s][trace][redefine,class,constantpool] mapped tag 10 at index 9 to 47
...
[51.942s][trace][redefine,class,constantpool] mapped tag 1 at index 39 to 31
[51.942s][debug][redefine,class,constantpool] after pass 1a: merge_cp_len=50, scratch_i=40, index_map_len=33
[51.943s][trace][redefine,class,constantpool] mapped tag 1 at index 40 to 32
...
[51.943s][trace][redefine,class,constantpool] mapped tag 1 at index 46 to 50
[51.943s][trace][redefine,class,constantpool] Class entry@51 name_index change: 46 to 50
[51.943s][trace][redefine,class,constantpool] mapped tag 100 at index 45 to 51
[51.943s][trace][redefine,class,constantpool] mapped tag 1 at index 47 to 52
[51.943s][debug][redefine,class,constantpool] after pass 1b: merge_cp_len=53, scratch_i=48, index_map_len=41
[51.943s][info ][redefine,class,constantpool] merge_cp_len=53, index_map_len=41
[51.943s][trace][redefine,class,constantpool] index_map[0]: old=7 new=40
[51.943s][trace][redefine,class,constantpool] index_map[1]: old=8 new=41
...
[51.943s][trace][redefine,class,constantpool] index_map[40]: old=47 new=52
[51.943s][trace][redefine,class,constantpool] ldc@0x0000000110ee1348 old=7, new=40
[51.943s][trace][redefine,class,constantpool] invokestatic@0x0000000110ee134a old=9, new=47
[51.943s][trace][redefine,class,constantpool] new@0x0000000110ee134e old=15, new=7
[51.943s][trace][redefine,class,constantpool] ldc@0x0000000110ee1352 old=17, new=9
[51.943s][trace][redefine,class,constantpool] invokespecial@0x0000000110ee1354 old=19, new=11
[51.943s][trace][redefine,class,constantpool] invokevirtual@0x0000000110ee1357 old=22, new=14
[51.943s][debug][redefine,class,annotation  ] num_annotations=1                                            (3)
[51.943s][debug][redefine,class,annotation  ] mapped old type_index=35
[51.943s][debug][redefine,class,annotation  ] type_index=48  num_element_value_pairs=1
[51.943s][debug][redefine,class,annotation  ] mapped old element_name_index=36
[51.943s][debug][redefine,class,annotation  ] element_name_index=49
[51.943s][debug][redefine,class,annotation  ] tag='s'
[51.943s][debug][redefine,class,annotation  ] mapped old const_value_index=37
[51.943s][debug][redefine,class,annotation  ] const_value_index=29
[51.943s][trace][redefine,class,constantpool] inner_class_info change: 26 to 18
[51.943s][trace][redefine,class,constantpool] outer_class_info change: 41 to 33
[51.943s][trace][redefine,class,constantpool] inner_name change: 44 to 36
[51.943s][trace][redefine,class,constantpool] inner_class_info change: 45 to 51
[51.943s][trace][redefine,class,constantpool] outer_class_info change: 41 to 33
[51.943s][trace][redefine,class,constantpool] inner_name change: 47 to 52
[51.943s][trace][redefine,class,constantpool] method-name_index change: 33 to 25
[51.943s][trace][redefine,class,constantpool] method-signature_index change: 25 to 17
[51.943s][trace][redefine,class,constantpool] lvt-name_cp_index change: 31 to 23
[51.943s][trace][redefine,class,constantpool] lvt-descriptor_cp_index change: 32 to 24
[51.943s][trace][redefine,class,constantpool] lvt-name_cp_index change: 31 to 23
[51.943s][trace][redefine,class,constantpool] lvt-descriptor_cp_index change: 32 to 24
[51.943s][debug][redefine,class,load        ] loaded name=sandbox.DebugTest$Foo (avail_mem=1416012K)       (4)
[51.943s][trace][redefine,class,obsolete,mark] EMCP_cnt=2, obsolete_cnt=0                                  (5)
[51.943s][trace][redefine,class,iklass,add   ] adding previous version ref for sandbox.DebugTest, EMCP_cnt=2
[51.943s][trace][redefine,class,iklass,add   ] EMCP method sandbox.DebugTest.<init>()V is NOT on_stack 0x0000000110edf4a8
[51.943s][trace][redefine,class,iklass,add   ] EMCP method sandbox.DebugTest.main([Ljava/lang/String;)V is on_stack 0x0000000110edf5c0
[51.943s][trace][redefine,class,iklass,add   ] scratch class added; one of its methods is on_stack.
[51.943s][info ][redefine,class,load         ] redefined name=sandbox.DebugTest, count=1 (avail_mem=1416012K)
[51.943s][trace][redefine,class,obsolete,mark] mark m(()Ljava/lang/String;) as obsolete
[51.943s][trace][redefine,class,obsolete,mark] EMCP_cnt=1, obsolete_cnt=1                                  (6)
[51.943s][trace][redefine,class,iklass,add   ] adding previous version ref for sandbox.DebugTest$Foo, EMCP_cnt=1
[51.943s][trace][redefine,class,iklass,add   ] scratch class not added; no methods are running
[51.943s][info ][redefine,class,update       ] adjust: name=sandbox.DebugTest$Foo
[51.943s][debug][redefine,class,update,constantpool] cpc special, static or dynamic entry update: <init>(()V)
[51.943s][info ][redefine,class,load               ] redefined name=sandbox.DebugTest$Foo, count=1 (avail_mem=1416012K)
[51.944s][trace][redefine,class,obsolete,metadata  ] calling check_class
[51.944s][info ][redefine,class,timer              ] vm_op: all=0  prologue=0  doit=0
[51.944s][info ][redefine,class,timer              ] redefine_single_class: phase1=0  phase2=0
[51.964s][debug][redefine,class,breakpoint         ] setting breakpoint in main(([Ljava/lang/String;)V)    (7)
[57.587s][debug][redefine,class,breakpoint         ] clearing breakpoint in main(([Ljava/lang/String;)V)   (8)
[57.588s][debug][redefine,class,breakpoint         ] setting breakpoint in main(([Ljava/lang/String;)V)
[57.682s][stdout] m(): foo
[72.578s][debug][redefine,class,breakpoint         ] clearing breakpoint in main(([Ljava/lang/String;)V)   (9)
[72.586s][debug][redefine,class,load               ] loading name=sandbox.DebugTest kind=102 (avail_mem=1234396K)
[72.586s][trace][redefine,class,normalize          ] Method matched: new: sandbox.DebugTest.<init>()V [0] == old: sandbox.DebugTest.<init>()V [0]
[72.586s][trace][redefine,class,normalize          ] Method matched: new: sandbox.DebugTest.main([Ljava/lang/String;)V [1] == old: sandbox.DebugTest.main([Ljava/lang/String;)V [1]
[72.586s][info ][redefine,class,constantpool       ] old_cp_len=91, scratch_cp_len=91
[72.586s][debug][redefine,class,constantpool       ] after pass 0: merge_cp_len=91
[72.586s][debug][redefine,class,constantpool       ] after pass 1a: merge_cp_len=91, scratch_i=91, index_map_len=0
[72.586s][info ][redefine,class,constantpool       ] merge_cp_len=91, index_map_len=0
[72.586s][debug][redefine,class,load               ] loaded name=sandbox.DebugTest (avail_mem=1234396K)
[72.586s][debug][redefine,class,load               ] loading name=sandbox.DebugTest$Foo kind=102 (avail_mem=1234396K)
[72.586s][trace][redefine,class,normalize          ] Method matched: new: sandbox.DebugTest$Foo.<init>()V [0] == old: sandbox.DebugTest$Foo.<init>()V [0]
[72.586s][trace][redefine,class,normalize          ] Method matched: new: sandbox.DebugTest$Foo.m()Ljava/lang/String; [1] == old: sandbox.DebugTest$Foo.m()Ljava/lang/String; [1]
[72.586s][info ][redefine,class,constantpool       ] old_cp_len=53, scratch_cp_len=40
[72.586s][debug][redefine,class,constantpool       ] after pass 0: merge_cp_len=53
[72.586s][debug][redefine,class,constantpool       ] after pass 1a: merge_cp_len=53, scratch_i=40, index_map_len=0
[72.586s][info ][redefine,class,constantpool       ] merge_cp_len=53, index_map_len=0
[72.586s][debug][redefine,class,load               ] loaded name=sandbox.DebugTest$Foo (avail_mem=1234396K)
[72.586s][trace][redefine,class,obsolete,mark      ] EMCP_cnt=2, obsolete_cnt=0
[72.586s][trace][redefine,class,iklass,add         ] adding previous version ref for sandbox.DebugTest, EMCP_cnt=2
[72.586s][trace][redefine,class,iklass,purge       ] sandbox.DebugTest: previous versions
[72.586s][trace][redefine,class,iklass,purge       ] previous version 0x0000000800060458 is alive
[72.586s][trace][redefine,class,iklass,purge       ] previous methods length=2
[72.586s][trace][redefine,class,iklass,purge       ] purge: main(([Ljava/lang/String;)V): prev method @1 in version @0 is alive
[72.586s][trace][redefine,class,iklass,purge       ] previous version stats: live=1, deleted=0
[72.586s][trace][redefine,class,iklass,add         ] scratch class not added; no methods are running
[72.586s][info ][redefine,class,load               ] redefined name=sandbox.DebugTest, count=2 (avail_mem=1234396K)
[72.586s][trace][redefine,class,obsolete,mark      ] mark m(()Ljava/lang/String;) as obsolete
[72.586s][trace][redefine,class,obsolete,mark      ] EMCP_cnt=1, obsolete_cnt=1
[72.586s][trace][redefine,class,iklass,add         ] adding previous version ref for sandbox.DebugTest$Foo, EMCP_cnt=1
[72.586s][trace][redefine,class,iklass,add         ] scratch class not added; no methods are running
[72.586s][info ][redefine,class,update             ] adjust: name=sandbox.DebugTest$Foo
[72.586s][debug][redefine,class,update,constantpool] cpc special, static or dynamic entry update: <init>(()V)
[72.587s][info ][redefine,class,load               ] redefined name=sandbox.DebugTest$Foo, count=2 (avail_mem=1234396K)
[72.587s][trace][redefine,class,obsolete,metadata  ] calling check_class
[72.588s][info ][redefine,class,timer              ] vm_op: all=0  prologue=0  doit=0
[72.588s][info ][redefine,class,timer              ] redefine_single_class: phase1=0  phase2=0
[72.630s][debug][redefine,class,breakpoint         ] setting breakpoint in main(([Ljava/lang/String;)V)
[75.100s][debug][redefine,class,breakpoint         ] clearing breakpoint in main(([Ljava/lang/String;)V)  (10)
[75.101s][debug][redefine,class,breakpoint         ] setting breakpoint in main(([Ljava/lang/String;)V)
[75.104s][stdout] m(): fable
1 The JVM is already at breakpoint, first logs when the modified Foo is reloaded, the logs gives nice insight on the machinery that is necessary to replace a simple method.
2 There’s a lot of activity on the constant pool which is used by the JVM to find internal class symbols, among other things.
3 Since I modified annotations, there’s some change to perform on this side too.
4 The new redefined class is actually loaded, yet not used.
5 The JVM identified two Equivalent Modulo Constant Pool methods (i.e. the original method and the method I just modified).
6 The old method is obsoleted.
7 The redefinition is over, and sets again the breakpoint.
8 In debug simply continue to the next step.
9 Once again modify the m() method and reload the class.
10 Class Is reloaded, continue.

These logs are rarely useful unless you work with IDE, debuggers or the JVM itself. However, they are interesting to understand what’s going on when debugging. One thing to mention is that the JVMTI infrastructure relies a lot on the redefinition component, it’s one of the most complex pieces in the JVM.

Just-in-Time and compilation

If you need to look in the compilation of methods, because something do not perform as expected, one may want to toggle the logs for the just-in-time and compilation logs:

Just-in-Time compilation and inlining
$ java -Xlog:jit*=debug,compilation*=debug -cp . JustStartMainTest
...
[0.053s][debug][jit,compilation      ]   30       3       java.util.ImmutableCollections$SetN$SetNIterator::hasNext (13 bytes)
[0.053s][debug][compilation,codecache] CodeHeap 'non-profiled nmethods': size=120032Kb used=2Kb max_used=2Kb free=120029Kb
[0.053s][debug][compilation,codecache] CodeHeap 'profiled nmethods': size=120028Kb used=36Kb max_used=36Kb free=119991Kb
[0.053s][debug][compilation,codecache] CodeHeap 'non-nmethods': size=5700Kb used=972Kb max_used=977Kb free=4727Kb
[0.053s][debug][jit,compilation      ]   31       3       java.util.ImmutableCollections$SetN$SetNIterator::nextIndex (56 bytes)
[0.053s][debug][compilation,codecache] CodeHeap 'non-profiled nmethods': size=120032Kb used=2Kb max_used=2Kb free=120029Kb
[0.053s][debug][compilation,codecache] CodeHeap 'profiled nmethods': size=120028Kb used=37Kb max_used=37Kb free=119990Kb
[0.053s][debug][compilation,codecache] CodeHeap 'non-nmethods': size=5700Kb used=972Kb max_used=977Kb free=4727Kb
[0.053s][debug][jit,compilation      ]   32       3       java.util.ImmutableCollections$SetN$SetNIterator::next (47 bytes)
[0.053s][debug][jit,inlining         ]                               @ 1   java.util.ImmutableCollections$SetN$SetNIterator::hasNext (13 bytes)
[0.053s][debug][jit,inlining         ]                               @ 15   java.util.ImmutableCollections$SetN$SetNIterator::nextIndex (56 bytes)   callee is too large
[0.053s][debug][jit,inlining         ]                               @ 43  java/util/NoSuchElementException::<init> (not loaded)   not inlineable
[0.054s][debug][compilation,codecache] CodeHeap 'non-profiled nmethods': size=120032Kb used=2Kb max_used=2Kb free=120029Kb
[0.054s][debug][compilation,codecache] CodeHeap 'profiled nmethods': size=120028Kb used=38Kb max_used=38Kb free=119989Kb
[0.054s][debug][compilation,codecache] CodeHeap 'non-nmethods': size=5700Kb used=972Kb max_used=977Kb free=4727Kb
...

The above log snippet shows that the JVM is

  1. compiling methods next and hasNext,

  2. then tries to inline hasNext into next,

  3. then tries to inline nextIndex into next but fails.

This article has been written using the code base of JDK11u 11.0.8. Not everything is logged via the unified logging mechanism, and I don’t think this changed in recent JDK versions e.g. JDK 15 which is not yet out at this time.

So, for example if you need to work with the JVM C2 compiler for some reason then -Xlog:jit*=debug,compilation*=debug might not be enough, instead you’ll need to use -XX:+LogCompilation, which by default will generate a file like hotspot_pid{pid}.log in the working directory, unless this flag -XX:LogFile=compilation-log.xml is specified. The content of this file is actually an XML document.

Safepoints and JVM operations

public class DebugTest {
    public static void main(String[] args) {
        System.out.printf("[%.3fs][stdout] ping%n", ManagementFactory.getRuntimeMXBean().getUptime() / 1000d);
        System.out.printf("[%.3fs][stdout] pong%n", ManagementFactory.getRuntimeMXBean().getUptime() / 1000d); (1)
    }
}
1 breakpoint

When debugging for example this simple program, we see already a lot of activity performed by the JVM using -Xlog:safepoint*=info, I found that vmoperation is not quite useful as a user, as the safepoint logs provides enough data.

ThreadsSuspendJVMTI
[0.072s][info ][safepoint] Entering safepoint region: ThreadsSuspendJVMTI (1)
[0.072s][info ][safepoint,cleanup] deflating idle monitors, 0.0000001 secs
[0.072s][info ][safepoint,cleanup] updating inline caches, 0.0000148 secs
[0.072s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000003 secs
[0.072s][info ][safepoint,cleanup] purging class loader data graph, 0.0000001 secs
[0.072s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000002 secs
[0.072s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0000555 secs
[0.072s][info ][safepoint        ] Leaving safepoint region
[0.072s][info ][safepoint        ] Total time for which application threads were stopped: 0.0000831 seconds, Stopping threads took: 0.0000083 seconds (2)
1 Name of the VM operation
2 Summary of the JVM stopped time
ChangeBreakpoints
[0.072s][info ][safepoint        ] Application time: 0.0001442 seconds
[0.072s][info ][safepoint        ] Entering safepoint region: ChangeBreakpoints
[0.072s][info ][safepoint,cleanup] deflating idle monitors, 0.0000001 secs
[0.072s][info ][safepoint,cleanup] updating inline caches, 0.0000001 secs
[0.072s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000002 secs
[0.072s][info ][safepoint,cleanup] purging class loader data graph, 0.0000001 secs
[0.072s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000001 secs
[0.072s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0000210 secs
[0.072s][info ][safepoint        ] Leaving safepoint region
[0.072s][info ][safepoint        ] Total time for which application threads were stopped: 0.0000686 seconds, Stopping threads took: 0.0000124 seconds
EnableBiasedLocking
[0.117s][info ][safepoint        ] Application time: 0.0446646 seconds
[0.117s][info ][safepoint        ] Entering safepoint region: EnableBiasedLocking
[0.117s][info ][safepoint,cleanup] deflating idle monitors, 0.0000002 secs
[0.117s][info ][safepoint,cleanup] updating inline caches, 0.0000003 secs
[0.117s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000004 secs
[0.117s][info ][safepoint,cleanup] purging class loader data graph, 0.0000001 secs
[0.117s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000003 secs
[0.117s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0000390 secs
[0.117s][info ][safepoint        ] Leaving safepoint region
[0.117s][info ][safepoint        ] Total time for which application threads were stopped: 0.0000901 seconds, Stopping threads took: 0.0000048 seconds
RevokeBias
[0.127s][info ][safepoint        ] Application time: 0.0099803 seconds
[0.127s][info ][safepoint        ] Entering safepoint region: RevokeBias
[0.127s][info ][safepoint,cleanup] deflating idle monitors, 0.0000002 secs
[0.127s][info ][safepoint,cleanup] updating inline caches, 0.0000055 secs
[0.127s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000004 secs
[0.127s][info ][safepoint,cleanup] purging class loader data graph, 0.0000001 secs
[0.127s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000003 secs
[0.127s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0000486 secs
[0.127s][info ][safepoint        ] Leaving safepoint region
[0.127s][info ][safepoint        ] Total time for which application threads were stopped: 0.0000974 seconds, Stopping threads took: 0.0000069 seconds

These are the very first snippets of logs about safepoint during a quick debug, but there are a lot more reasons.

Safepoint logging is useful if the application is regularly stopped, but the GC is not the root cause. So it’s useful to always log safepoints.

$ grep "Entering safepoint" /var/log/2020-01-28_13-36-23-vm.log
[6.880s][info ][safepoint     ] Entering safepoint region: Deoptimize
[6.880s][info ][safepoint        ] Entering safepoint region: Deoptimize
[6.884s][info ][safepoint        ] Entering safepoint region: Deoptimize
[7.231s][info ][safepoint        ] Entering safepoint region: Deoptimize
[7.277s][info ][safepoint        ] Entering safepoint region: Deoptimize
[7.481s][info ][safepoint        ] Entering safepoint region: Deoptimize
[7.913s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[7.935s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[7.979s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.001s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.023s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.051s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.075s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.102s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.154s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[8.317s][info ][safepoint        ] Entering safepoint region: Deoptimize
[8.637s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[8.892s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[9.251s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[9.450s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.482s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.505s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.508s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.572s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.574s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.750s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.753s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.817s][info ][safepoint        ] Entering safepoint region: Deoptimize
[9.885s][info ][safepoint        ] Entering safepoint region: FindDeadlocks
[10.650s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[10.669s][info ][safepoint        ] Entering safepoint region: Deoptimize
[11.131s][info ][safepoint        ] Entering safepoint region: Deoptimize
[11.166s][info ][safepoint        ] Entering safepoint region: Deoptimize
[11.407s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[11.870s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[11.979s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[12.344s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[12.394s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[12.435s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[12.484s][info ][safepoint        ] Entering safepoint region: Deoptimize
[12.488s][info ][safepoint        ] Entering safepoint region: Deoptimize
[12.494s][info ][safepoint        ] Entering safepoint region: Deoptimize
[12.789s][info ][safepoint        ] Entering safepoint region: RedefineClasses
[13.143s][info ][safepoint        ] Entering safepoint region: JFRCheckpoint
[13.147s][info ][safepoint        ] Entering safepoint region: JFROldObject
[13.155s][info ][safepoint        ] Entering safepoint region: ClassLoaderStatsOperation
[13.165s][info ][safepoint        ] Entering safepoint region: EnableBiasedLocking
[13.190s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[13.201s][info ][safepoint        ] Entering safepoint region: Deoptimize
[13.352s][info ][safepoint        ] Entering safepoint region: Deoptimize
[14.133s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[14.134s][info ][safepoint        ] Entering safepoint region: Deoptimize
[14.453s][info ][safepoint        ] Entering safepoint region: Deoptimize
[14.463s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[14.728s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[15.211s][info ][safepoint        ] Entering safepoint region: RevokeBias
...
[15.303s][info ][safepoint        ] Entering safepoint region: RevokeBias
[15.305s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[15.329s][info ][safepoint        ] Entering safepoint region: RevokeBias
...
[15.397s][info ][safepoint        ] Entering safepoint region: RevokeBias
[15.400s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[15.407s][info ][safepoint        ] Entering safepoint region: RevokeBias
...
[15.473s][info ][safepoint        ] Entering safepoint region: RevokeBias
[15.473s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[15.484s][info ][safepoint        ] Entering safepoint region: RevokeBias
[15.485s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[15.616s][info ][safepoint        ] Entering safepoint region: RevokeBias
...
[17.756s][info ][safepoint        ] Entering safepoint region: RevokeBias
[17.756s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[17.868s][info ][safepoint        ] Entering safepoint region: RevokeBias
[17.928s][info ][safepoint        ] Entering safepoint region: Deoptimize
[17.954s][info ][safepoint        ] Entering safepoint region: Deoptimize
[18.727s][info ][safepoint        ] Entering safepoint region: G1CollectForAllocation
[18.980s][info ][safepoint        ] Entering safepoint region: Deoptimize
[19.555s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[19.744s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[19.972s][info ][safepoint        ] Entering safepoint region: RevokeBias
...
[20.330s][info ][safepoint        ] Entering safepoint region: RevokeBias
[20.548s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[20.693s][info ][safepoint        ] Entering safepoint region: BulkRevokeBias
[21.562s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[22.563s][info ][safepoint        ] Entering safepoint region: Cleanup
[22.776s][info ][safepoint        ] Entering safepoint region: Deoptimize
[23.252s][info ][safepoint        ] Entering safepoint region: Deoptimize
[23.763s][info ][safepoint        ] Entering safepoint region: RevokeBias
[23.819s][info ][safepoint        ] Entering safepoint region: RevokeBias
[24.183s][info ][safepoint        ] Entering safepoint region: Deoptimize
[24.437s][info ][safepoint        ] Entering safepoint region: Deoptimize
[24.542s][info ][safepoint        ] Entering safepoint region: FindDeadlocks
[24.543s][info ][safepoint        ] Entering safepoint region: FindDeadlocks
[25.361s][info ][safepoint        ] Entering safepoint region: Deoptimize
[26.319s][info ][safepoint        ] Entering safepoint region: Deoptimize
[27.006s][info ][safepoint        ] Entering safepoint region: Deoptimize
[27.163s][info ][safepoint        ] Entering safepoint region: Deoptimize
[27.438s][info ][safepoint        ] Entering safepoint region: Deoptimize
[28.316s][info ][safepoint        ] Entering safepoint region: Deoptimize
[28.800s][info ][safepoint        ] Entering safepoint region: ICBufferFull
[29.801s][info ][safepoint        ] Entering safepoint region: Cleanup
[30.523s][info ][safepoint        ] Entering safepoint region: RevokeBias
...
[41.174s][info ][safepoint        ] Entering safepoint region: FindDeadlocks
...
[51.716s][info ][safepoint        ] Entering safepoint region: G1CollectForAllocation
...

There’s a lot of activity. Most of this VM activity will be easier to analyze using JFR / JDK Mission Control, but for logging very long running processes, logs are still quite useful.

Programmatic access

For those that played with jcmd before you may already know all commands are available as MXBeans. This immediately suggests that it’s possible to invoke these command programmatically.

Enable GC logging programmatically
import javax.management.InstanceNotFoundException;
import javax.management.IntrospectionException;
import javax.management.MBeanException;
import javax.management.MBeanInfo;
import javax.management.MalformedObjectNameException;
import javax.management.ObjectName;
import javax.management.ReflectionException;
import java.lang.management.ManagementFactory;

public class TriggerGcLogsProgrammatically {
    public static void main(String[] args) throws Exception {
        // jcmd $(pidof java) VM.log what=gc*=debug decorators=uptime,tags,level output=stderr
        executeDcmd("vmLog", (1)
                    "what=gc*=trace", (2)
                    "decorators=uptime,tags,level", (3)
                    "output=stderr"); (4)

        // jcmd $(pidof java) VM.log list
        System.out.printf("%s%n", executeDcmd("vmLog", "list"));
    }

    private static String executeDcmd(String operationName, String... params) throws Exception {
        var objectName = new ObjectName("com.sun.management:type=DiagnosticCommand");
        var mbeanServer = ManagementFactory.getPlatformMBeanServer();

        return (String) mbeanServer.invoke(objectName,
                                           operationName,
                                           new Object[]{params},
                                           new String[]{String[].class.getName()});
    }
}
1 Equivalent to VM.log
2 Tag selection with their level configuration
3 Decorators
4 Output section

Wrap up

Unified logging is a great change in the JVM: Its flexibility and ubiquity gives great insight in the JVM. Also, a strong point of this implementation is dynamic configuration change: It is very useful when one doesn’t want to restart a process just to raise the logging levels, or to gain insight on a JVM component.

Yet not everyone will be interested in most of these subsystems. I’m pretty sure GC logs will be the most used logs. On this in particular, I think JDK maintainers should add tags for the type of GC, cms for CMS, zgc for ZGC, g1 for G1GC, shenandoah for Shenandoah, etc.

In that regard I believe the new system lacks good default options for logging. As seen above it’s easy to miss valuable information by being too restrictive with the tags. The removed GC logging flags were more explicit.

In particular, I think unified logging suffers from few drawbacks:

  • discoverability: while anyone can peek at the available tags the mass of the tags makes the system hard to use if you don’t know already what to expect from these tags.

  • documentation: tags are not documented, most don’t auto-document themselves so if you don’t know already what to expect from these tags you’ll need to take the long road to try each combination.

  • stability: while the JVM checks if the selected tags exists it doesn’t check if the combination will log something. On each JDK version logs can change in subtle ways for whatever reasons (like bug-fixing). It’s best to verify on each new JDK version if things changed.

Command line flags provided a good user experience, they were discoverable because documented, they were explicit, and usually stable. These flags are gone for GC logging, but there are still some old Trace* flags that setup unified logging. If JDK maintainers chose to keep the old flags or proposed alternative flags for GC that would have made unified logging use more practical I think.

If you spot anything incorrect please leave a message to fix the issue.

Using JDK FlightRecorder and JDK Mission Control Reads network addresses in /proc