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 codeThe 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 codeThis 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 codeAs you can see, the default JVM logs include:
[Startup elapsed time][Log level][Log label, which may contain multiple] Log contentCopy the codeOne 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 codeThe 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 codeThis 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 codeNote 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 codeThe 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 codeIf 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 codeTags, 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 codeThe 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 codeThe 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 code3. 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 codeThe 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 codeJVM logging configuration
Configuration format:
-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]
Copy the codeIf not configured, the default is:
-Xlog:all=warning:stdout:uptime,level,tags
Copy the codeThis 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 codeIf 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 code2. 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 code4. 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 codeResults:
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 codeView 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 codeExecute the list command:
jcmd 22 VM.log list
Copy the codeResults:
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 codeThe 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 codeAs 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 codeAs 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 codeResults:
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 codeBecause 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 codeResults:
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 codeEach 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 codeSince 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 codeSet 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 codeSet 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.