Skip to main content

How to Convert JDK8 GC Log Flags to JDK9 with Unified Logging:

Introduction:

JDK9 introduced unified logging for all JDK9 components. It provides a way for the users to configure the content of the logs. Since all the logs follow the unified format, it would make parsing easier.

Users might have some difficulty finding the right tags and levels in JDK9, especially when migrating from JDK8. 

This post provides some basic back ground about unified logging in JDK9, and tags and levels in JDK9 corresponding to JDK8 flags for GC logging.

JDK9 Unified Logging:

With a JDK9 build, you can logging help by "java -Xlog:help". Here is the output from the command

./bin/java -Xlog:help
-Xlog Usage: -Xlog[:[what][:[output][:[decorators][:output-options]]]]
where 'what' is a combination of tags and levels on the form tag1[+tag2...][*][=level][,...]
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, aot, annotation, arguments, attach, barrier, biasedlocking, blocks, bot, breakpoint, census, class, classhisto, cleanup, compaction, constraints, constantpool, coops, cpu, cset, data, defaultmethods, dump, ergo, exceptions, exit, fingerprint, freelist, gc, hashtables, heap, humongous, ihop, iklass, init, itables, jni, jvmti, liveness, load, loader, logging, mark, marking, methodcomparator, metadata, metaspace, mmu, modules, monitorinflation, monitormismatch, nmethod, normalize, objecttagging, obsolete, oopmap, os, pagesize, patch, path, phases, plab, promotion, preorder, protectiondomain, ref, redefine, refine, region, remset, purge, resolve, safepoint, scavenge, scrub, stacktrace, stackwalk, start, startuptime, state, stats, stringdedup, stringtable, stackmap, subclass, survivor, sweep, task, thread, tlab, time, timer, update, unload, verification, verify, vmoperation, vtables, workgang, jfr, system, parser, bytecode, setting, event
 Specifying 'all' instead of a tag combination matches all tag combinations.

Described tag combinations:
 logging: Logging for the log framework itself

Available log outputs:
 stdout, stderr, file=<filename>
 Specifying %p and/or %t in the filename will expand to the JVM's PID and startup timestamp, respectively.

Some examples:
 -Xlog
Log all messages using '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 using 'info' level to stdout, with default decorations.

 -Xlog:gc=debug:file=gc.txt:none
Log messages tagged with 'gc' tag using 'debug' level to file 'gc.txt' with no decorations.

 -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1m
Log messages tagged with 'gc' tag using '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 using 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.

 -Xlog:gc*=info,safepoint*=off
Log messages tagged with at least 'gc' using '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' using 'trace' level to file 'safepointtrace.txt'.

JDK8 GC Logging Flags to JDK9 Tags and Levels:

Here I listed the most commonly used GC logging flags for JDK8, JDK9 tags and levels and some examples:

JDK8 JDK9 description
-XX:+PrintGC -Xloggc:<filename> -Xlog:gc:<filename> Log messages tagged with 'gc' tag using 'info' level to stdout, with default decorations.
-XX:+PrintGCDetails -Xloggc:<filename> -Xlog:gc=info print GC Detail.
old: prints phases, cputime, heap sizes
ul: can print those separately as controlled by the tag.

-Xlog:gc=info,phases*=debug add detailed phases info
-XX:+PrintGCDetails -XX:+UnlockDiagnosticVMOptions -XX:+G1SummarizeRSetStats -XX:G1SummarizeRSetStatsPeriod=<n> -Xloggc:<filename> -XX:G1SummarizeRSetStatsPeriod=<n> -Xlog:gc=info,remset*=trace:<filename> Print remember set memory footprint, and table usage statistics. This could be an expensive operation
-XX:+PrintTenuringDistribution -Xloggc:<filename> -Xlog:gc=info,heap*=info,phases*=debug,gc+age=debug:<filename>
or
-Xlog:gc=info,heap*=info,phases*=debug,gc+age=trace:<filename>		 Age distribution in survivor space
-XX:+PrintAdaptiveSizePolicy -Xloggc:<filename> -Xlog:gc=info,gc+ergo*=debug:$log_dir/gc.log information related to ergonomic decision makeing, such as CSET and IHOP
-XX:+PrintTLAB -Xlog:gc=info,gc+tlab=debug:$log_dir/gc.log - prints total
or
-Xlog:gc=info,gc+tlab=trace:$log_dir/gc.log - prints per thread info		 TLAB
-XX:PrintPLAB -Xlog:gc=info,gc+plab=debug:$log_dir/gc.log PLAB
-XX:G1SummarizeConcMark -Xlog:gc=info,gc+marking=trace:$log_dir/gc.log print marking statistics when jvm exit
-XX:+UnlockDiagnosticVMOptions -XX:G1TraceConcRefinement -Xlog:gc=info,gc+refine=debug:$log_dir/gc.log print when refinement threads are activated/deactivated
-XX:+PrintReferenceGC -Xlog:gc=info,gc+ref=debug:$log_dir/gc.log reference processing data
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -Xlog:gc=info,safepoint=info:$log_dir/gc.log
or
-Xlog:gc=info,safepoint=debug:$log_dir/gc.log - with per thread state		 safepoint: type of safepoint, how long to reach the safepoint
Labels:

Comments

Post a Comment

Popular posts from this blog

Gatling Load Test Tricks and Debug

Introduction: Gatling is a light weighted load generator. Though it is 'load test as code', sometimes it is hard to debug. Especially when there is lack of documentation and tutorial. I run into an issue when upgrading from 2.3.1 to 3.0.2. The error message is not very helpful. Here I will show this case to illustrate an upgrading issue, as well is tricks to print out some debug information. Some Debug Tricks: According to  gatling document , you can print out debug information in 2 ways. change conf/logback.xml to DEBUG/TRACE for logger name="io.gatling.http.engine.response" This generates too much information and my tests times out.  Use println in exec. This is more flexible and can prints the exact information I need. How ever I would like to put the debug messages in a separate file. Here is an example: val file = System.getProperty("file", "/tmp/debug_cookie.out") val scn = scenario(myReadScenario) .during (myDur
Post a Comment
Read more

Performance Test with Gatling in Cloud

Introduction: A lot of our performance tests are driven by gatling. When moving our tests to Google cloud, we face a lot of questions. One of them is how to manage the life cycle of the test. First, we need to generate the .csv file as the feeder to the gatling test. Second, we need to know when the test is finished. Third, we need to retrieve the results from the cloud. According to  Distributed load testing with Gatling and Kubernetes , a Kubernetes Job should be used. While this blog provides good information, I still need to figure out how to create the feeder .csv and share it with gatling script.  Using InitContainers to pre-populate Volume data in Kubernetes provides me another piece of information. In this blog post, I will show you my experiment of creating a Kubernetes job to drive performance workload with Gatling. Create Feeder script: My gatling script reads the feeder .csv (benchmark.csv). I have a python script generating the benchmark.csv file. 
Post a Comment
Read more

G1GC Performance Tuning Parameters

G1GC Performance Tuning Parameters In this post, I will list some common observations from G1GC logs, and the parameters you can try to tune the performance. To print GC logs, please refer to  my blog about how to print gc logs . Threads Related In JDK9, with -Xlog:gc*=info, or -Xlog:gc+cpu=info, you can get log entry like: [12.420s][info][gc,cpu      ] GC(0) User=0.14s Sys=0.03s Real=0.02s This can give you some indication about the cpu utilization for the GC pause. For example, this entry indicates for this gc pause, total user-cpu is 0.14s, wall time is 0.02s, and system time is 0.03s. The ratio of User/Real could be used as an estimation of number of gc threads you need. For this case, 18 gc threads should be good. If you see long termination time,  User/Real less than the gc threads, you can try to reduce the number of gc threads. Here is a list of threads related parameters: Name Pa
2 comments
Read more