Java 9 provides a common logging system for JVM components with extremely detailed level, an infrastructure to do the logging. With new command-line option -Xlog for all logging followed settings, Unified JVM Logging gives us a precise, easy-to-configure tool to do a root cause analysis of complex system-level JVM components.
I. Available Settings
The command line -Xlog is used for controlling all logging JVM components. Its arguments follow the rules:
– Multiple arguments will be applied in the order they appear on command line.
– Last configuration rules: for the same output, multiple arguments will override each other in the given order.
-Xlog:disable turns off all logging and clears all configuration of the logging framework (including warnings and errors).
The syntax for configuring the logging:
-Xlog:tag[*][=level][:output:decoration:output-option],tag...
-Xlog:help prints -Xlog usage syntax and available tags, levels, decorators along with some example command lines:
1. 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.
2. 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.
3. 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)
4. 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
. tag-set: all.
. level: info
. output: stdout
. decorators: uptime, level, tags
II. Example
-Xlog:gc* com.javasampleapproach.java9.Java9Starter
-Xlog:gc*,os com.javasampleapproach.java9.Java9Starter
-Xlog:os=debug,gc*=debug:stdout:pid,level,tags com.javasampleapproach.java9.Java9Starter
[7740][debug][os] Initial active processor count set to 4 [7740][info ][os] SafePoint Polling address: 0x000002e784750000 [7740][info ][os] Memory Serialize Page address: 0x000002e784790000 [7740][info ][gc,heap] Heap region size: 1M [7740][debug][gc,heap] Minimum heap 8388608 Initial heap 67108864 Maximum heap 1044381696 [7740][debug][gc,ergo,refine] Initial Refinement Zones: green: 4, yellow: 12, red: 20, min yellow size: 8 [7740][debug][gc,marking,start] Initialize Card Live Data [7740][debug][gc,marking ] Initialize Card Live Data 0.526ms [7740][debug][gc ] ConcGCThreads: 1 [7740][debug][gc ] ParallelGCThreads: 4 [7740][debug][gc ] Initialize mark stack with 4096 chunks, maximum 16384 [7740][debug][gc,ergo,heap ] Expand the heap. requested expansion amount:67108864B expansion amount:67108864B [7740][debug][gc,ihop ] Target occupancy update: old: 0B, new: 67108864B [7740][info ][gc ] Using G1 [7740][info ][gc,heap,coops ] Heap address: 0x00000000c1c00000, size: 996 MB, Compressed Oops mode: 32-bit [7740][debug][gc,metaspace,freelist] VirtualSpaceNode::take_from_committed() not available 524288 words [7740][debug][gc,metaspace,freelist] space @ 0x000002e7846895c0 0K, 0% used [0x000002e7a4740000, 0x000002e7a4740000, 0x000002e7a4740000, 0x000002e7a4f40000) [7740][debug][gc,metaspace,freelist] VirtualSpaceNode::take_from_committed() not available 49152 words [7740][debug][gc,metaspace,freelist] space @ 0x000002e784689830 0K, 0% used [0x0000000100000000, 0x0000000100000000, 0x0000000100000000, 0x0000000140000000) [7740][debug][gc,metaspace,freelist] VirtualSpaceNode::take_from_committed() not available 256 words [7740][debug][gc,metaspace,freelist] space @ 0x000002e784689830 48K, 100% used [0x0000000100000000, 0x0000000100060000, 0x0000000100060000, 0x0000000140000000) [7740][debug][gc,metaspace,freelist] VirtualSpaceNode::take_from_committed() not available 512 words [7740][debug][gc,metaspace,freelist] space @ 0x000002e7846895c0 512K, 100% used [0x000002e7a4740000, 0x000002e7a4b40000, 0x000002e7a4b40000, 0x000002e7a4f40000) === Java Sample Approach === [7740][debug][gc,refine ] Stopping 0 [7740][debug][gc,refine ] Stopping 1 [7740][debug][gc,refine ] Stopping 2 [7740][debug][gc,refine ] Stopping 3 [7740][info ][gc,heap,exit ] Heap [7740][info ][gc,heap,exit ] garbage-first heap total 65536K, used 1024K [0x00000000c1c00000, 0x00000000c1d00200, 0x0000000100000000) [7740][info ][gc,heap,exit ] region size 1024K, 2 young (2048K), 0 survivors (0K) [7740][info ][gc,heap,exit ] Metaspace used 4715K, capacity 4734K, committed 4864K, reserved 1056768K [7740][info ][gc,heap,exit ] class space used 419K, capacity 426K, committed 512K, reserved 1048576K
