OpenJDK 11 is the first long-term support release since OpenJDK 8, which has made major changes to JVM logging configuration, mainly normalization and unification. In OpenJDK 8, the logging configuration had a lot of state bits that were confusing and difficult to maintain and iterate on. In OpenJDK 11, the JVM logging configuration was finally standardized and unified. This article provides a basic explanation and analysis of these configurations.

JVM log tags

JVM logging is similar to logging in our Java code. In Java code, we typically use SLf4J for logging, for example:

Logger logger = LogFactory.getLooger("core-logger");
logger.info("this is core logger log");
Copy the code

The log will then print something like:

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

This information includes timestamp, log level, log label (core-Logger), and log content. JVM logs also include these elements. Here’s an example:

[s] 0.182 [debug] [jit compilation] 1 3 Java. Lang. StringLatin1: : hashCode (42 bytes) [s] 0.183 / debug/jit compilation, 2, 3 Java.lang.object: : < init > (1 bytes) [s] 0.183 [debug] [jit compilation] 3 3 Java. Lang. String: : hashCode (49 bytes)Copy the code

As you can see, the default JVM logs include:

[Startup elapsed time][Log level][Log label, which may contain multiple] Log contentCopy the code

One line of logs may contain multiple tags around which any subsequent JVM log-related configuration is configured. Most of the tags are for JVM developers, and some of them are for us who use JVMS to tune JVM parameters as well as code. So what tags do we need to care about? I personally divide the labels we need to care about into the following categories according to their functions

1. Gc

The GC log has many tags and combinations, most of which start with the GC tag and mix and match other tags. In general, there are several tags that we often use:

The labelgc

The general description of the gc log, usually set to info level to view the gc occurrence time, consumption time and memory size. For example: Pause Young (Normal) (G1 Evacuation Pause) 3480M->1565M(5120M) 15.968ms includes information on GC type, GC reason, collection memory size, duration, and more

The labelgc,age

Age information in gc. Objects with a higher age will enter the old age. Debug only prints the highest age and the expected size, not the current total size, for example:

[2020-02-26T08:34:12.823+0000][debug][GC,age] The GC (1661) Desired survivor size 167772160 bytes, New threshold 6 (Max Threshold 6) [2020-02-26T08:34:12.823+0000][trace][GC,age] Age 1: 16125960 bytes, 16125960 total [2020-02-26T08:34:12.823+0000][trace][GC,age] age 2: 16259512 bytes, 32385472 Total [2020-02-26T08:34:12.823+0000][trace][GC,age] age 3: 2435240 bytes, 34820712 Total [2020-02-26T08:34:12.823+0000][trace][GC,age] age 4: 17179320 Bytes, 52000032 Total [2020-02-26T08:34:12.823+0000][trace][GC,age] age 5: 43986952 bytes, 95986984 total [2020-02-26T08:34:12.823+0000][trace][GC,age] age 6: 20858328 bytes, 116845312 totalCopy the code

The labelgc,alloc.gc,alloc,region

These two parameters are valid only for g1 gc. When the GC is complete,alloc prints a trace level log that records which thread triggered the GC and the address of the gc result returned. This log is usually needed to debug the GC. Gc, Alloc,region Collects information about Regions in each GC and generates debug logs.

[the 2020-02-28 T02:14:02. 694 + 0000] [trace] [gc, alloc] SDK - 27692-2 - closer - t - 4: Successfully Scheduled collection RETURNING 0x00000007FFC00000 [2020-02-28T2:16:00.372 +0000][debug][GC,alloc,region] Gc (7848) Mutator Allocation stats, Regions: 677, Wasted size: 63832B (0.0%)Copy the code

This is the log you need to view for most GC problem location, info level printing the real time of each GC:

[2020-02-28T01:59:46.406+0000][info][GC, CPU] GC (7841) Sys=0.00s Real=0.04s [2020-02-28T02:01:20.148+0000][info][GC, CPU] GC (7842) User=0.04s Sys=0.06s Real=0.04sCopy the code

Note that this may differ from JFR’s statistics, where JFR counts gc times as starting from schedule GC, whereas here the time is starting from the start tag.

The labelgc,ergo.gc,ergo,cset.gc,ergo,ihop.gc,ergo,refine

This is the Adaptive Size Policy related log. If you want to learn the algorithm in detail, you can use the trace level. General debug level information is sufficient

[2020-02-28T01:59:46.367+0000][trace][GC, Ergo,cset] GC (7841) Start choosing cset. Pending cards: 26996 Predicted Base Time: 13.34ms Remaining Time: 186.66ms Target Pause Time: 200.00ms [2020-02-28T01:59:46.367+0000][TRACE][GC, Ergo,cset] GC (7841) Add young regions to Cset. Eden: 676 Regions, Survivors: 6 Regions, predicted Young Region Time: 19.02ms, Target Pause Time: 200.00ms [2020-02-28T01:59:46.367+0000][debug][GC,ergo,cset] Finish choosing cset. Old: 0 Regions, predicted Old Region time: 0.00ms, Time Remaining: 167.64 [2020-02-28T01:59:46.389+0000][debug][GC,ergo] GC (7841) Running G1 Clear Card Table Task using 4 workers for 7 Units of work for 895 regions. [2020-02-28T01:59:46.391+0000][debug][GC, Ergo] GC (7841) Running G1 Free Collection Set Using 4 workers for collection set Length 682 [2020-02-28T01:59:46.391+0000][trace][GC, Ergo,refine] GC (7841) Updating Refinement Zones: update_RS Buffers: 630ms, Refinement Zones: 630ms 19.998 MS [2020-02-28T01:59:46.391+0000][DEBUG][GC, Ergo,refine] GC (7841) Updated Refinement Zones: Green: 572, yellow: 1716, Red: 2860 [2020-02-28T02:01:20.108+0000][trace][GC, Ergo,cset] GC (7842) Start choosing cset. Pending cards: 25786 Predicted Base Time: 12.87ms Remaining Time: 187.13 MS Target Pause Time: 200.00ms [2020-02-28T02:01:20.108+0000][TRACE][GC, Ergo,cset] GC (7842) Add young regions to Cset. Eden: 677 Regions, Survivors: 5 Regions, Predicted Young Region Time: 14.43ms, Target Pause Time: 200.00ms [2020-02-28T02:01:20.108+0000][debug][GC,ergo,cset] Finish choosing cset. Old: 0 Regions, predicted Old Region time: 0.00ms, Time Remaining: 172.70 [2020-02-28T2:01:20.132 +0000][debug][GC,ergo] GC (7842) Running G1 Clear Card Table Task using 4 workers for 8 Units of work for 903 regions. [2020-02-28T02:01:20.133+0000][debug][GC, Ergo] GC (7842) Running G1 Free Collection Set Using 4 workers for collection set Length 682 [2020-02-28T02:01:20.133+0000][trace][GC, Ergo,refine] GC (7842) Updating Refinement Zones: update_rs Buffers: 306ms, Refinement Zones: 306ms 19.997 MS [2020-02-28T02:01:20.133+0000][debug][GC, Ergo,refine] GC (7842) Updated Refinement Zones: Green: 572, yellow: 1716, Red: 2860 [2020-02-28T02:04:36.095+0000][trace][GC, Ergo,cset] GC (7843) Start choosing cset. Pending cards: 26115 Predicted Base Time: 12.85ms Remaining Time: 187.15 MS Target Pause Time: 200.00ms [2020-02-28T02:04:36.095+0000][TRACE][GC, Ergo,cset] GC (7843) Add young regions to Cset. Eden: 676 Regions, Survivors: 6 Regions, predicted Young Region Time: 69.11ms, Target Pause Time: 200.00ms [2020-02-28T02:04:36.095+0000][debug][GC,ergo,cset] Finish choosing cset. Old: 0 Regions, predicted Old Region time: 0.00ms, Time Remaining: 118.04 [2020-02-28T2:04:36.118 +0000][debug][GC,ergo] GC (7843) Running G1 Clear Card Table Task using 4 workers for 7 Units of work for 894 regions. [2020-02-28T02:04:36.120+0000][debug][GC, Ergo] GC (7843) Running G1 Free Collection Set Using 4 workers for collection set Length 682 [2020-02-28T02:04:36.121+0000][trace][GC, Ergo,refine] GC (7843) Updating Refinement Zones: update_rs Buffers: 630ms, Refinement Zones: 630ms 19.997 MS [2020-02-28T02:04:36.121+0000][DEBUG][GC, Ergo,refine] GC (7843) Updated Refinement Zones: Green: 572, yellow: 1716, red: 2860Copy the code

The labelgc,heap.gc,heap,region

The DEBUG level of GC and HEAP displays the overview of the heap at the time of gc. For G1 GC, THE trace level of THE GC, Heap,region prints the details of each region. This is generally used for GC debugging.

We generally only care about the GC/HEAP logs

These labels are in

[2020-02-28T06:01:20.787+0000][debug][GC,heap] GC (7922) HEAP before GC invocations=7922 (full 0): garbage-first heap total 8388608K, used 4076387K [0x0000000600000000, 0x0000000800000000) [2020-02-28T06:01:20.787+0000][debug][GC,heap] GC (7922) Region Size 4096K, 682 young (2793472K), [DEBUG][GC,heap] GC (7922) Metaspace Used 163068K, Capacity 166731K, Survivors (20480K) [2020-02-28T06:01:20.787+0000] [2020-02-28T06:01:20.787+0000][debug][GC,heap] GC (7922) Class space used 18180K capacity 19580K, committed 20480K, Reserved 1048576K [2020-02-28T06:01:20.787+0000][trace][GC,heap,region] GC (7922) heap Regions: E=young(eden), S=young(survivor), O=old, HS=humongous(starts), HC=humongous(continues), CS=collection set, F=free, A=archive, TAMS=top-at-mark-start (previous, Next) [2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) | | 0 0 x0000000600000000, 0 x0000000600400000, 0x0000000600400000|100%| O| |TAMS 0x0000000600400000, 0 x0000000600000000 | Untracked [the 2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) | 1 | 0 x0000000600400000, 0x0000000600800000, 0x0000000600800000|100%| O| |TAMS 0x0000000600800000, 0 x0000000600400000 | Untracked [the 2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) | 2 | 0 x0000000600800000, 0x0000000600c00000, 0x0000000600c00000|100%| O| |TAMS 0x0000000600c00000, 0 x0000000600800000 | Untracked [the 2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) | 3 | 0 x0000000600c00000, 0x0000000601000000, 0x0000000601000000|100%| O| |TAMS 0x0000000601000000, 0 x0000000600c00000 | Untracked [the 2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) 4 | | 0 x0000000601000000, 0x0000000601400000, 0x0000000601400000|100%| O| |TAMS 0x0000000601400000, 0 x0000000601000000 | Untracked [the 2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) | | 0 5 x0000000601400000, 0x0000000601800000, 0x0000000601800000|100%| O| |TAMS 0x0000000601800000, 0 x0000000601400000 | Untracked [the 2020-02-28 T06:01:20. 787 + 0000] [trace] [gc, heap, region] gc (7922) | | 0 6 x0000000601800000, 0x0000000601c00000, 0x0000000601c00000|100%| O| |TAMS 0x0000000601c00000, 0x0000000601800000| UntrackedCopy the code

If you are using THE G1 GC and are prone to Evacuation failures or Humongous Allocation and are not sure why, consider looking at this tag-related log:

[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 219 object size 2160888 start 0x0000000636c00000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 412 object size 2160888 start 0x0000000667000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 443 object size 3241320 start 0x000000066ec00000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 489 object size 2160888 start 0x000000067a400000  with remset 2 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 490 object size 2160888 start 0x000000067a800000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 499 object size 7292936 start 0x000000067cc00000  with remset 2 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 536 object size 2160888 start 0x0000000686000000  with remset 2 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 656 object size 2160888 start 0x00000006a4000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 768 object size 2160888 start 0x00000006c0000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
[2020-02-28T06:01:20.831+0000][debug][gc,humongous                ] gc(7922) Live humongous region 786 object size 2160888 start 0x00000006c4800000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 0
Copy the code

Tags, metaspace, gc, gc metaspace, freelist, gc, metaspace, freelist, blocks view metaspace related gc logs, The info level of gc,metaspace will output the metaspace memory changes involved in each GC. If there are any changes, the detailed changes will be passed through GC,metaspace,freelist, Gc, metaspace freelist, blocks the trace level of output.

[2020-02-28T04:32:13.123+0000][info][GC,metaspace][7896] metaspace: 163062 k - > 163062 k (1198080 k) [2020-02-28 T04:35:44. 956 + 0000] [trace] [gc, metaspace, freelist] SpaceManager: : grow_and_allocate For 49 words 109 words used 19 words left [2020-02-28T04:35:44.956+0000][trace][GC,metaspace,freelist] ChunkManager::free_chunks_get: free_list: 0x00007fddccb89770 chunks left: 433. [the 2020-02-28 T04:35:44. 956 + 0000] [trace] [gc, metaspace, freelist] ChunkManager: : chunk_freelist_allocate: 0x00007fddccb89770 chunk 0x00007fdc74221000 size 128 count 433 Free chunk total 255616 count 824 [the 2020-02-28 T04:35:44. 956 + 0000] [trace] [gc, metaspace freelist, blocks] returning block at 0 x00007fdd95575b68 size = 19 [the 2020-02-28 T04:35:44. 956 + 0000] [trace] [gc, metaspace, freelist] SpaceManager: : added the chunk: [the 2020-02-28 T04:35:44. 956 + 0000] [trace] [gc, metaspace, freelist] Metachunk: bottom 0x00007fdc74221000 top 0x00007fdc74221040 end 0x00007fdc74221400 size 128 (specialized) [2020-02-28T04:35:44.956+0000][trace][GC, Metaspace,freelist] Free chunk total 255616 count 824 [2020-02-28T04:36:35.367+0000][info][GC,metaspace] GC (7897) metaspace: 163065K->163065KCopy the code

The labels GC, PHASES, GC, REF, GC, Phases, REF, GC, TASK, GC, REF, GC, START, GC, REF, START are related to the GC steps. If you want to learn about the GC algorithm, you can view the logs of these labels. To understand the steps and principles of GC

The labelsafepoint

We know that we can’t gc until we get to SafePoints. If we are interested in these SafePoints, we can look at the debug level logs of this tag

2. Class loading is related to runtime compilation

Tags class, preOrder, class,init, class, Load, class, Unload As the name implies, this is the log of class initialization, class load and class unload. Info level information is enough. If you want to learn about JVM class loading, check out the Trace level log of the class tag.

[s] 8.931 [debug] [class, preorder]. Com fasterxml. Jackson. Core. PrettyPrinter source: File: / D: / Repositories/maven/com/fasterxml/Jackson/core/Jackson - core / 2.10.0 / Jackson - core - 2.10.0. Jar [s] 8.931 [info] [class, init] 2740 the Initializing 'com/fasterxml/Jackson/core/PrettyPrinter' (0 x0000000801399220) [s] 8.934 [info] [class, load]. Com fasterxml. Jackson. Core. PrettyPrinter source: File: / D: / Repositories/maven/com/fasterxml/Jackson/core/Jackson - core / 2.10.0 / Jackson - core - 2.10.0. JarCopy the code

The tag JIT compilation,compilation, log level is debug

[the 2020-02-28 T03:01:51. 619 + 0000] [the debug] [jit compilation] 153756! 4 jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes) made zombie [the 2020-02-28 T03:01:51. 620 + 0000] [the debug] [jit compilation] 153219 4 io.lettuce.core.protocol.CommandArgs$IntegerArgument::encode (12 bytes) made zombie [the 2020-02-28 T03:01:51. 623 + 0000] [the debug] [jit compilation] 153192 4 io.lettuce.core.protocol.CommandArgs$StringArgument::writeString (60 bytes) made zombie [the 2020-02-28 T03:01:54. 911 + 0000] [the debug] [jit compilation] 157252! 4 jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes)Copy the code

3. Other runtime related

Tag MonitorInflation Logs related to synchronization locks, usually at the debug level, used to locate deadlocks

[5.033s][debug][MonitorInflation] Deflating Object 0x0000000708310378, Mark 0x0000021cEF446002 Type Java. Lang. Ref. ReferenceQueue $Lock [s] 5.033 [debug] [monitorinflation] Inflating object 0 x0000000708310378, mark 0x0000021cf085c002 , Type Java. Lang. Ref. ReferenceQueue $Lock [s] 5.035 [debug] [monitorinflation] Deflating object 0 x0000000708310378, mark 0x0000021cf085c002 , Type Java. Lang. Ref. ReferenceQueue $Lock [s] 5.035 [debug] [monitorinflation] Inflating object 0 x0000000708310378, mark 0x0000021cef445e02 , type java.lang.ref.ReferenceQueue$LockCopy the code

The tag biasedlocking indicates logs related to biasedlocking. Generally, check the info level. The trace level displays more details about biasedlocking contention, which can be used to learn the implementation principle of biasedlocking

[7.273s][info ][biasedlocking] Revoking bias by walking my own stack:
[7.273s][info ][biasedlocking] Revoking bias of object 0x0000000711b1ca40, mark 0x000001c6d0acc905, type sun.net.www.protocol.jar.URLJarFile, prototype header 0x0000000000000105, allow rebias 0, requesting thread 0x000001c6d0acc800
[7.273s][info ][biasedlocking]   Revoked bias of object biased toward live thread (0x000001c6d0acc800)
[7.273s][trace][biasedlocking]    mon_info->owner (0x00000007022634d8) != obj (0x0000000711b1ca40)
[7.273s][trace][biasedlocking]    mon_info->owner (0x0000000711b200d8) != obj (0x0000000711b1ca40)
[7.273s][trace][biasedlocking]    mon_info->owner (0x0000000711b200d8) != obj (0x0000000711b1ca40)
[7.273s][trace][biasedlocking]    mon_info->owner (0x0000000702970260) != obj (0x0000000711b1ca40)
[7.273s][info ][biasedlocking]   Revoked bias of currently-unlocked object
Copy the code

JVM logging configuration

Configuration format:

-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]
Copy the code

If not configured, the default is:

-Xlog:all=warning:stdout:uptime,level,tags
Copy the code

This is a colon-separated configuration where the first colon is followed by what, the second by output, the third by decorators, and the fourth by comma-separated output-options. The parts that are not configured are the corresponding parts of the default values above. For example, the following sets of configurations are equivalent:

-Xlog:all=warningwith-Xlog::stdoutwith-Xlog::::uptime,level,tagswith-Xlog:all=warning:stdoutwith-Xlog::stdout:uptime,level,tagswith-Xlog:all=warning:stdout:uptime,level,tags
-Xlog:gc*=infowith-Xlog:gc*=info:stdout:uptime,level,tags
-Xlog::file=/project/log/app.log::filecount=50,filesize=100Mwith-Xlog:all=warning:file=/project/log/app.log:uptime,level,tags:filecount=50,filesize=100M

1. what

What contains tags and log levels. For example, you can configure:

-Xlog:gc=infoIndicates that all logs containing only one tag, GC, will be output at the info level.
-Xlog:gc*=infoAll logs containing gc tags will be output at the info level, as described aboveAll tags.
-Xlog:gc+age=debug, means at the same timeInclude and only includeGc and AGE tags are output only at debug level.
-Xlog:gc*=info,gc+heap=debug,gc+heap+region=debug, while settingInclude and only includeThe gc and HEAP tags are debug,Include and only includeGc and heap tags and region tags are set to DEBUG, and the remaining logs containing GC tags are set to info. Since we know that the AGE tag only works with GC tags, we can also write:
-Xlog:gc*=info,age*=debug 和 -Xlog:gc*=info,gc+age=debugIs equivalent to this tag that can be combined,You can see how JVMS merge by modifying log parameters in the dynamic Changing JVM Log Level section below.

Log levels include:

Closed off:
Trace: Contains trace, DEBUG, INFO, Warning, and ERROR logs
Debug: Contains debug, info, warning, and error
Info: contains info, warning, and error
Warning: Contains warning and error
Error: Contains only error

** If the level is not given, the default is info level. ** For example -xlog :gc* and -xlog :gc*=info are equivalent

If the label is incorrectly typed, an error is reported and exit:

[0.005s][error][logging] Invalid tag 'phase' in log selection. Did you mean 'Phases '? Invalid -Xlog option '-Xlog:gc+phase=debug', see error log for details.Copy the code

If there is no such tag combination (or if the tag cannot appear alone), an alarm is raised, but the operation continues:

[0.006s][warning][logging] No tag set matches Selection: GC +add. Did you mean any of the following? Gc * GC +metaspace* GC +ref* GC +stringtable GC +compaction [0.007s][Warning][Logging] No tag set matches Selection: phases. Did you mean any of the following? phases* gc+phases* gc+phases+start* gc+phases+task gc+phases+refCopy the code

2. output

Contains three outputs:

Stdout: standard output
Stderr: Standard error output
File =filename Output to a file

You can configure output-options: filecount=50,filesize=100M To save 50 files, each file is 100M

3. decorators

Tags that can be used:

tag	meaning
Time or t	Current time in ISO-8601 format
Utctime or utc	UTC time
Uptime or u	Time elapsed since startup, to the millisecond
Timemillis or tm	Millisecond timestamp, equivalent to ‘System.currentTimemillis ().
Uptimemillis or um	Milliseconds since startup
Timenanos or tn	Nanosecond timestamp, equivalent to ‘system.nanotime ()’
Uptimenanos or UN	To the nanosecond we have now
The hostname or hn	The host name
Pid or p	Process of no.
Dar or ti	The thread number
Level or l	The level of logging
Tags or tg	Log labels, refer to the log labels section mentioned earlier

Assuming we configure uptime,level,tags, the log would look something like this:

[2020-02-26T08:34:12.823+0000][debug][GC,age] The GC (1661) Desired survivor size 167772160 bytes, new threshold 6 (max threshold 6)Copy the code

4. Convert the log configuration of the old version to that of the new version

Gc:

The original parameters	Equivalent new parameters and description
g1PrintHeapRegions	-Xlog:gc+region=trace
GcLogFileSize and NumberOfgcLogFiles and UsegcLogFileRotation	This is done through the output and output-option mentioned above
PrintTenuringDistribution	-xlog :gc+age*=level, refer to the above gc,age tag to determine the level you want to view
PrintAdaptiveSizePolicy	-xlog :gc+ergo*=level, refer to the gc,ergo TAB section above to determine the log level you want to see
Printgc	-xlog :gc=info or -xlog :gc prints all logs containing only GC labels
PrintgcDetails	` – Xlog: gc * = info ` or ` – Xlog: gc * `
PrintgcApplicationConcurrentTime and PrintgcApplicationStoppedTime	-xlog: Safepoint =log or -xlog :safepoint. The labels are both Safepoint under the new log parameters
PrintgcTaskTimeStamps	-Xlog:gc+task*=debug
PrintHeapAtgc	-Xlog:gc+heap=trace
PrintReferencegc	-Xlog:gc+ref*=debug
PrintStringDeduplicationStatistics	-Xlog:gc+stringdedup*=debug
PrintgcDateStamps	This is currently partially configured through the decorators above, corresponding to time or t
PrintgcCause and PrintgcID	The current GC ID and gc reason are typed by default, so you don’t need to configure this

Other parameters:

The original parameters	Equivalent new parameters and description
TraceExceptions	-xlog: Exceptions =info Prints a log of any error exceptions encountered by the JVM. By default, only the error level is printed
TraceClassLoadingPreorder	-Xlog:class+preorder=debug
TraceClassLoading	-xlog :class+load=info Prints class loading logs. The INFO level is sufficient
TraceClassUnloading	-xlog :class+unload=info Prints class unload logs. The INFO level is sufficient
TraceClassLoadingPreorder	-Xlog:class+preorder=debug
TraceClassInitialization	-Xlog:class+init=info
TraceClassResolution	-Xlog:class+resolve=debug
TraceClassPaths	-Xlog:class+path=info
TraceLoaderConstraints	-Xlog:class+loader+constraints=info
VerboseVerification	-Xlog:verification=info
TraceSafepoint	-Xlog:safepoint=debug
TraceSafepointCleanupTime	-Xlog:safepoint+cleanup=info
TraceMonitorInflation	-Xlog:monitorinflation=debug
TraceBiasedLocking	-xlog: Biasedlocking = Level You can refer to the ‘biasedlocking’ TAB mentioned above and configure the level according to the information you want to see
TraceRedefineClasses	-Xlog:redefine+class*=level

Dynamic change of JVM log levels

The JVM log configuration can be dynamically modified using JCMD. The main command is vm. log. Assuming our JVM process is 22, you can view the format using this command:

jcmd 22  VM.log
Copy the code

Results:

22
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)
Copy the code

View the current log parameter configuration

Let’s assume that the log-related parameters in the startup parameter of our process 22 are configured as follows:

-Xlog:gc*=debug:file=/project/log/gc.log:utctime,level,tags:filecount=50,filesize=100M 
-Xlog:jit+compilation=debug:file=/project/log/jit_compile.log:utctime,level,tags:filecount=10,filesize=100M
Copy the code

Execute the list command:

jcmd 22 VM.log list
Copy the code

Results:

22:

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

#0 and #1 are the default JVM logging configurations we talked about earlier:

#0: stdout all=warning uptime,level,tags // Indicates the warn level logs of all tags in standard output. The format is [uptime][level][tags] Log content #1: Stderr all=off uptime,level,tags // Indicates that no log is output in standard error outputCopy the code

The log parameters we configured in the startup parameters correspond to #2 and #3.

Make the log output from another file

jcmd 22 VM.log rotate

22:
Command executed successfully
Copy the code

As you can see, the logs #2 and #3 are exported in a separate file

Disable all logs and clear log parameters

jcmd 22 VM.log disable

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
Copy the code

As you can see, after executing this command, all logging is closed and the parameters are cleaned up (even the log parameters for the startup parameter configuration)

Added log configuration output

The following parameters and we start – Xlog: gc * = the debug: file = / project/log/gc log: utctime, level, tags: filecount = 50, consistent filesize = 100 m.

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

Results:

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=debug utctime,level,tags filecount=50,filesize=100M (reconfigured)
Copy the code

Because it’s been configured once before, it’s reconfigured.

Modify log configuration output

How do you distinguish logs? Is uniquely differentiated by output (stdout is not specified). If the output_options function is set to an output, the configuration cannot be changed. You can only set the output_options function to disable all logs.

For example, let’s change the configuration level to info:

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

Results:

22:
Command executed successfully

jcmd 22 VM.log list
22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info uptime,level,tags filecount=50,filesize=100M (reconfigured)
Copy the code

Each setting is incremental rather than full. That is, what configured each time is appended to the existing output, as you can see from the following examples

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

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info uptime,level,tags filecount=50,filesize=100M (reconfigured)
Copy the code

Since GC +age actually belongs to GC *, it is incorporated into GC *

jcmd 22 VM.log output=/project/core/log/gc.log what="gc+age=debug"

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info,age*=debug uptime,level,tags filecount=50,filesize=100M (reconfigured)
Copy the code

Set GC +age to debug and merge to GC *=info and AGE *= DEBUG. It can be inferred that age can only be used with GC

jcmd 22 VM.log output=/project/core/log/gc.log what="gc+alloc+region=debug"

22:
Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info,age*=debug,alloc+region*=debug uptime,level,tags filecount=50,filesize=100M (reconfigured)

jcmd 22 VM.log output=/project/core/log/gc.log what="gc+heap=debug,gc+heap+region=debug"

22:

Command executed successfully

jcmd 22 VM.log list

22:

Log output configuration:
 #0: stdout all=off uptime,level,tags
 #1: stderr all=off uptime,level,tags
 #2: file=/project/core/log/gc.log all=off,gc*=info,age*=debug,region*=debug,gc+heap=debug,gc+region=info uptime,level,tags filecount=50,filesize=100M (reconfigured)
Copy the code

Set GC + Alloc +region to DEBUG, merge to GC *=info,age*=debug; Gc +heap=debug, GC +heap+region= info, AGE *= DEBUG,region*=debug, GC +heap=debug, GC +region=info Region There are only two types of regions: GC + Alloc +region and GC +heap+region.

mo4tech.com (Moment For Technology) is a global community with thousands techies from across the global hang out!Passionate technologists, be it gadget freaks, tech enthusiasts, coders, technopreneurs, or CIOs, you would find them all here.

OpenJDK 11 JVM log related parameters parsing and usage

JVM log tags

1. Gc

2. Class loading is related to runtime compilation

3. Other runtime related

JVM logging configuration

1. what

2. output

3. decorators

4. Convert the log configuration of the old version to that of the new version

Dynamic change of JVM log levels

View the current log parameter configuration

Make the log output from another file

Disable all logs and clear log parameters

Added log configuration output

Modify log configuration output

OpenJDK 11 JVM log related parameters parsing and usage

JVM log tags

1. Gc

2. Class loading is related to runtime compilation

3. Other runtime related

JVM logging configuration

1. what

2. output

3. decorators

4. Convert the log configuration of the old version to that of the new version

Dynamic change of JVM log levels

View the current log parameter configuration

Make the log output from another file

Disable all logs and clear log parameters

Added log configuration output

Modify log configuration output

Related Posts

Build a low code platform to help you!

“Tao, Dharma, Art, Instrument” in the eyes of developers

Traefik Configures cipher suites