OpenJDK 11 is the first long-term support version after OpenJDK 8. This version has changed a lot in JVM log configuration, mainly standardization and unification. In OpenJDK 8, there are many status bits in the log configuration, which is confusing and difficult to maintain and further iterate. In OpenJDK 11, the JVM log related configuration is finally standardized and unified. This article will make a basic explanation and analysis of these configurations.
1, JVM log label
The JVM log is similar to the log in our java code. In Java code, we usually use slf4j to record logs, for example:
Logger logger = LogFactory.getLooger("core-logger"); logger.info("this is core logger log");
Then the output in the log is similar to:
2020-02-05 10:50:52.670 INFO [core-logger] [22] [pool-13-thread-1]: this is core logger log
It includes time stamp, log level, core logger and log content. The JVM log also includes these elements. for instance:
[0.182s][debug][jit,compilation] 1 3 java.lang.StringLatin1::hashCode (42 bytes) [0.183s][debug][jit,compilation] 2 3 java.lang.Object::<init> (1 bytes) [0.183s][debug][jit,compilation] 3 3 java.lang.String::hashCode (49 bytes)
As you can see, the default JVM logs include:
[start time] [log level] [log label, may contain multiple] log contents
One line of logs may contain multiple labels. Later, the configuration related to JVM logs is also around these labels. Most of the tags are for JVM developers, and some of them are for JVM parameter tuning and code tuning by people who use the JVM. So what tags do we need to care about? According to the function, I divide the tags we need to care about into the following categories
1. gc correlation
gc logs have many tags and combinations, most of which start with gc tags and mix with other tags. In general, we often use the following labels:
Tag gc
gc describes the log as a whole. Generally, set the info level to check the gc occurrence time, consumption time and memory size. For example: pause young (normal) (G1 evaluation pause) 3480m - > 1565m (5120m) 15.968ms includes gc type, gc reason, collected memory size, duration and other information
Tags gc,age
Age related information in gc, objects with high age will enter the old age. If it is trace level, it will output the total size of all objects occupied by each age, as well as the size of all ages lower than this age. debug level will only output the highest level of age and the expected size, not the current total size, for example:
[2020-02-26T08:34:12.823+0000][debug][gc,age ] 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 total
gc,alloc, gc,alloc,region
These two parameters are only valid for g1 gc gc,alloc when gc is finished, print trace level log to record which thread triggered gc and the returned gc result address; this log is generally only needed when debugging gc. gc, alloc and region count the Regions of each gc and print the debug level log.
[2020-02-28T02:14:02.694+0000][trace][gc,alloc ] sdk-27692-2-amqp-t-4: Successfully scheduled collection returning 0x00000007ffc00000 [2020-02-28T02:16:00.372+0000][debug][gc,alloc,region ] gc(7848) Mutator Allocation stats, regions: 677, wasted size: 63832B ( 0.0%)
Tags gc,cpu This is the log that needs to be viewed for most gc problem location. It really takes time for info level to print each gc:
[2020-02-28T01:59:46.406+0000][info ][gc,cpu ] gc(7841) User=0.10s 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.04s
Note that there may be differences between this and JFR statistics. The gc time of JFR statistics is from the start of schedule gc to the start of gc, and here the time is from the start of the start tag.
gc,ergo, gc,ergo,cset, gc,ergo,ihop, gc,ergo,refine
This is the log related to Adaptive Size Policy. If you want to learn the algorithm in detail, you can use trace level. General debug level information is enough
[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 ] gc(7841) 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 time: 6.800ms, update_rs buffers: 397, update_rs goal time: 19.998ms [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.13ms 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 ] gc(7842) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 172.70 [2020-02-28T02: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 time: 6.303ms, update_rs buffers: 305, update_rs goal time: 19.997ms [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.15ms 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 ] gc(7843) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 118.04 [2020-02-28T02: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 time: 6.929ms, update_rs buffers: 364, update_rs goal time: 19.997ms [2020-02-28T02:04:36.121+0000][debug][gc,ergo,refine ] gc(7843) Updated Refinement Zones: green: 572, yellow: 1716, red: 2860
Tag gc,heap, gc,heap,region
The debug level of gc and heap will show the general situation of the heap at gc time. For the trace level of G1 gc,heap and region, the details of each region will be printed. This is generally used for gc debugging.
Generally, we only need to care about GC and 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), 5 survivors (20480K) [2020-02-28T06:01:20.787+0000][debug][gc,heap ] gc(7922) Metaspace used 163068K, capacity 166731K, committed 169728K, reserved 1198080K[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-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 0|0x0000000600000000, 0x0000000600400000, 0x0000000600400000|100%| O| |TAMS 0x0000000600400000, 0x0000000600000000| Untracked [2020-02-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 1|0x0000000600400000, 0x0000000600800000, 0x0000000600800000|100%| O| |TAMS 0x0000000600800000, 0x0000000600400000| Untracked [2020-02-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 2|0x0000000600800000, 0x0000000600c00000, 0x0000000600c00000|100%| O| |TAMS 0x0000000600c00000, 0x0000000600800000| Untracked [2020-02-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 3|0x0000000600c00000, 0x0000000601000000, 0x0000000601000000|100%| O| |TAMS 0x0000000601000000, 0x0000000600c00000| Untracked [2020-02-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 4|0x0000000601000000, 0x0000000601400000, 0x0000000601400000|100%| O| |TAMS 0x0000000601400000, 0x0000000601000000| Untracked [2020-02-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 5|0x0000000601400000, 0x0000000601800000, 0x0000000601800000|100%| O| |TAMS 0x0000000601800000, 0x0000000601400000| Untracked [2020-02-28T06:01:20.787+0000][trace][gc,heap,region ] gc(7922) | 6|0x0000000601800000, 0x0000000601c00000, 0x0000000601c00000|100%| O| |TAMS 0x0000000601c00000, 0x0000000601800000| Untracked
gc,humongous If you are using g1 gc, and you often have evaluation failure or Humongous Allocation, and you don't know what the reason is, you can consider looking at the logs related to this tag:
[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
Tags GC, metaface, GC, metaface, freelist, GC, metaface, freelist, blocks Check the gc logs related to metaface. The info level of gc and metaface will output the memory changes of metaface involved in each gc. If there are changes, the detailed changes will be output through the trace level of gc, metaface, freelist, gc, metaface, freelist, blocks.
[2020-02-28T04:32:13.123+0000][info ][gc,metaspace ] gc(7896) Metaspace: 163062K->163062K(1198080K) [2020-02-28T04: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. [2020-02-28T04: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 [2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist,blocks] returning block at 0x00007fdd95575b68 size = 19 [2020-02-28T04:35:44.956+0000][trace][gc,metaspace,freelist ] SpaceManager::added chunk: [2020-02-28T04: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->163065K(1198080K)
Tags gc,phases, gc,phases,ref, gc,phases,task, gc,ref, gc,start,gc,ref,start These tags are related to gc steps. If you want to learn the gc algorithm, you can check the logs of these tags to understand the steps and principles of gc
safepoint
We know that only when we reach the safepoint can we start gc. If we are interested in these safepoints, we can view the debug level log of this tag
2. Class loading is related to runtime compilation
Tag class,preorder, class,init, class,load, class,unload As the name implies, this is class initialization, class loading and class unloading logs, and info level information is enough. If you want to learn the JVM class loading process, you can view the trace level log of the class tag.
[8.931s][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 [8.931s][info][class,init ] 2740 Initializing 'com/fasterxml/jackson/core/PrettyPrinter' (0x0000000801399220) [8.934s][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.jar
jit,compilation In general, we only need to look at jit compilation log for immediate compilation optimization. The corresponding label is jit,compilation, and the log level is debug
[2020-02-28T03:01:51.619+0000][debug][jit,compilation] 153756 ! 4 jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes) made zombie [2020-02-28T03:01:51.620+0000][debug][jit,compilation] 153219 4 io.lettuce.core.protocol.CommandArgs$IntegerArgument::encode (12 bytes) made zombie [2020-02-28T03:01:51.623+0000][debug][jit,compilation] 153192 4 io.lettuce.core.protocol.CommandArgs$StringArgument::writeString (60 bytes) made zombie [2020-02-28T03:01:54.911+0000][debug][jit,compilation] 157252 ! 4 jdk.internal.reflect.GeneratedConstructorAccessor161::newInstance (49 bytes)
3. Other runtime related
Tag monitorinformation For synchronization lock related logs, generally check the debug level, which can be used to locate deadlocks
[5.033s][debug][monitorinflation] Deflating object 0x0000000708310378 , mark 0x0000021cef446002 , type java.lang.ref.ReferenceQueue$Lock [5.033s][debug][monitorinflation] Inflating object 0x0000000708310378 , mark 0x0000021cf085c002 , type java.lang.ref.ReferenceQueue$Lock [5.035s][debug][monitorinflation] Deflating object 0x0000000708310378 , mark 0x0000021cf085c002 , type java.lang.ref.ReferenceQueue$Lock [5.035s][debug][monitorinflation] Inflating object 0x0000000708310378 , mark 0x0000021cef445e02 , type java.lang.ref.ReferenceQueue$Lock
Label The log related to biased lock can be viewed at info level. The trace level displays more detailed details of biased lock contention, which can be used to learn the implementation principle of biased lock
[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
2, JVM log configuration
Configuration format:
-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]
If not configured, the default is:
-Xlog:all=warning:stdout:uptime,level,tags
This is a colon split configuration. The first colon is followed by what, the second is output, the third is decorators, and the fourth is comma split output options. The unconfigured part is the corresponding part of the above default values. For example, the following configurations are equivalent:
- -Xlog:all=warning and - Xlog::stdout and - xlog::: uptime, level, tags and - Xlog:all=warning:stdout and - Xlog::stdout:uptime,level,tags and - Xlog:all=warning:stdout:uptime,level,tags
- -Xlog:gc*=info and - Xlog:gc*=info:stdout:uptime,level,tags
- -Xlog::file=/project/log/app.log::filecount=50,filesize=100M and - 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=info, which means all logs containing only one gc tag will be output at info level.
- -Xlog:gc*=info, which means all logs containing gc tags will be output at info level, that is, all gc related tags mentioned above.
- -Xlog:gc+age=debug, which means that the debug level will output only if it contains both gc and age tags.
- -Xlog:gc*=info,gc+heap=debug,gc+heap+region=debug. At the same time, set debug to include and only contain the two tags of gc and heap. Set debug to include and only contain the three tags of gc, heap and region. The remaining log level containing the gc tag is info And since we know that the age tag is only matched with the gc tag, we can also write as follows:
- -Xlog:gc*=info,age*=debug and - Xlog:gc*=info,gc+age=debug are equivalent For this kind of tags that can be merged, you can refer to the later chapter of dynamically modifying the JVM log level to see how the JVM is merged by modifying the log parameters.
Log levels include:
- off: shut down
- Trace: including trace, debug, info, warning and error logs
- Debug: including debug, info, warning, error
- Info: including info, warning, error
- Warning: including warning, error
- Error: error only
**If no level is given, the info level is configured by default. **For example - Xlog:gc * and - Xlog:gc*=info are equivalent
If the tag is wrong, it will report an error 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.
If there is no combination of such labels (or the labels cannot appear separately), an alarm will be given, but the operation will continue:
[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+ref
2. output
There are three types of output:
-
stdout: standard output
-
stderr: standard error output
-
file=filename output to file
For output to file, you can configure output options: filecount=50,filesize=100M, which means 50 files are reserved, 100M for each file
3. decorators
Tags available:
| sign | Meaning |
|---|---|
| time or t | Current time, ISO-8601 format |
| utc me or utc | UTC time |
| uptime or u | Time from Startup to now, accurate to milliseconds |
| timemillis or tm | Millisecond timestamp, equivalent to System.currentTimeMillis() |
| uptimemillis or um | Millisecond time from Startup to now |
| timenanos or tn | Nanosecond timestamp, equivalent to System.nanoTime() |
| uptimenanos or un | Nanosecond time from Startup to now |
| hostname or hn | Host name |
| pid or p | Process number |
| tid or ti | Thread number |
| level or l | log level |
| tags or tg | Log label, refer to the previous section of log label |
If we configure uptime, level and tags, the log will look like this:
[2020-02-26T08:34:12.823+0000][debug][gc,age ] gc(1661) Desired survivor size 167772160 bytes, new threshold 6 (max threshold 6)
4. Convert the old version of log configuration to the new version of log configuration
gc related:
| Original parameter | Equivalent new parameters and description |
|---|---|
| g1PrintHeapRegions | -Xlog:gc+region=trace |
| gcLogFileSize and numberofglogfiles and UsegcLogFileRotation | Through the output and output option mentioned above |
| PrintTenuringDistribution | -Xlog:gc+age*=level, refer to the GC and age tags above to determine the level you want to view |
| PrintAdaptiveSizePolicy | -Xlog:gc+ergo*=level. Refer to the GC and ergo tabs above to determine the log level you want to see |
| Printgc | -Xlog:gc=info or - Xlog:gc, print all logs containing only gc Tags |
| PrintgcDetails | -Xlog:gc*=info or - Xlog:gc* |
| PrintgcApplicationConcurrentTime and PrintgcApplicationStoppedTime | -Xlog:safepoint=log or - Xlog:safepoint. It was originally separate. Under the new log parameters, the labels are all safepoints |
| PrintgcTaskTimeStamps | -Xlog:gc+task*=debug |
| PrintHeapAtgc | -Xlog:gc+heap=trace |
| PrintReferencegc | -Xlog:gc+ref*=debug |
| PrintStringDeduplicationStatistics | -Xlog:gc+stringdedup*=debug |
| PrintgcDateStamps | This is currently configured through the decorators section above, which corresponds to time or t |
| PrintgcCause and PrintgcID | At present, the gc ID and the gc reason will be printed by default. You do not need to configure this |
Other parameters:
| Original parameter | Equivalent new parameters and description |
|---|---|
| TraceExceptions | -Xlog:exceptions=info prints any error exception logs encountered by the JVM. By default, only error level |
| TraceClassLoadingPreorder | -Xlog:class+preorder=debug |
| TraceClassLoading | -Xlog:class+load=info print class load log, info level is enough |
| TraceClassUnloading | -Xlog:class+unload=info prints the unloading log of the class, and the info level is enough |
| 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 refer to the above biasedlocking tab, and configure the level according to the information you want to see |
| TraceRedefineClasses | -Xlog:redefine+class*=level |
3, Dynamically modify the JVM log level
You can dynamically modify the JVM log configuration through jcmd. The main command is VM.log. If our JVM process is 22, you can view the format through this command:
jcmd 22 VM.log
Result:
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)
View current log parameter configuration
Suppose that the log related parameters in the startup parameters of our 22 process 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
Execute the list command:
jcmd 22 VM.log list
Result:
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
The following two are the default JVM log configurations we mentioned earlier:
#0: stdout all=warning uptime,level,tags / / represents the warn level log of all tags in standard output, with the format of [uptime][level][tags] log content #1: stderr all=off uptime,level,tags / / indicates that no log is output in standard error output
The log parameters that we configured in the startup parameters correspond to ා 2 and ා 3.
Let the log start another file output
jcmd 22 VM.log rotate
22: Command executed successfully
You can see that the logs corresponding to ා 2 and ා 3 start another file and continue to output
Close all logs and clean up log related 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
It can be seen that after this command is executed, all logs are closed and the parameters are cleared (even the log parameters configured for startup parameters are no exception)
New log configuration output
The following parameters are consistent with - xlog: GC * = debug: file = / project / log / GC. Log: UTC, level, tags: filecount = 50, filesize = 100m of our startup parameters.
jcmd 22 VM.log output=/project/core/log/gc.log output_options="filecount=50,filesize=100M" decorators="utctime,level,tags" what="gc*=debug"
Result:
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)
Since it has been configured once before, there are (reconfigured)
Modify log configuration output
How to distinguish logs? It is only distinguished by output (stdout is not specified). To keep consistent with an existing output is to modify the configuration, but as long as the output "options are set, they cannot be changed. You can only disable all logs and then reset them.
For example, let's change the configuration level just to info:
jcmd 22 VM.log output=/project/core/log/gc.log what="gc*=info"
Result:
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)
Among them, those labeled as containing relationships will be merged automatically. Each setting is incremental rather than full. That is to say, what configured each time will be attached to the existing output, as can be seen 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)
Because gc+age actually belongs to gc *, it is merged 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)
Set gc+age to debug level and merge to gc*=info,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)
Set gc+alloc+region as debug, and merge it into gc*=info,age*=debug; add gc+heap=debug,gc+heap+region=debug, and merge it into gc*=info,age*=debug,region*=debug,gc+heap=debug,gc+region=info. It can be seen that there are only two regions matching gc+alloc+region and gc+heap+region.