On

In the production environment, or other environments where GC issues are to be tested, the parameters for printing GC logs must be configured to facilitate the analysis of GC-related issues.

But probably many people don’t configure it “perfectly”, either too little is printed, or output to the console, or a large file is overwritten, or…

This article takes you step by step, configuring a perfect GC log printing strategy

to print

content

in order to retain enough “live evidence”, it is best to print GC-related information complete enough. And your program is really not bad for the performance of your GC when printing log I/O consumptionPrinting

basic GC

informationThe

first step in printing GC logs is to open the parameters of GC printing, which is also the most basic parameter. 

-XX:+PrintGCDetails -XX:+PrintGCDateStampsPrint

Object Distribution

In order to analyze the promotion situation at GC and the high pause caused by promotion, do not look at the

object age distribution log -XX: +PrintTenuringDistribution

output example:

 Desired survivor size 59244544 bytes, new threshold 15 (max 15)- age   1:     963176 bytes,     963176 total- age   2:     791264 bytes,    1754440 total- age   3:     210960 bytes,    1965400 total- age   4:     167672 bytes,    2133072 total- age   5:     172496 bytes,    2305568 total- age   6:     107960 bytes,    2413528 total- age   7:     205440 bytes,    2618968 total- age   8:     185144 bytes,    2804112  total- age   9:     195240 bytes,    2999352 total- age  10:     169080 bytes,    3168432 total- age  11:     114664 bytes,    3283096 total- age  12:     168880 bytes,    3451976 total- age  13:     167272  bytes, 3619248 total- age 14: 387808 bytes, 4007056 total- age 15: 168992 bytes, 4176048 total

GC

print heap data

Every time GC occurs, compare the heap memory before and after GC, more intuitive

 -XX: +PrintHeapAtGC

output example:

 {Heap before GC invocations=0 (full 0): garbage-first heap   total 1024000K, used 324609K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)  region size 1024K, 6 young (6144K), 0 survivors (0K) Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K  class space    used 371K, capacity 388K, committed 512K, reserved 1048576KHeap after GC invocations=1 ( full 1): garbage-first heap   total 1024000K, used 21755K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)  region size 1024K, 0 young (0K), 0 survivors (0K) Metaspace       used 3420K, 

capacity 4500K, committed 4864K, reserved 1056768K class space used 371K, capacity 388K, committed 512K, reserved 1048576K}

Print STW

time

pause time is the most important indicator of GC, certainly not less

-XX:+PrintGCApplicationStoppedTime

Output example:

Total time for which  application threads were stopped: 0.0254260 seconds, Stopping threads took: 0.0000218 seconds

Before printing

safepoint information

enters the STW phase, you need to find a suitable safepoint. This indicator is also very important (not required, it is best to add this parameter to debug when there is a GC problem)

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1Output

example:

          vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count0.371: ParallelGCFailedAllocation       [      10          0              0    ]      [     0     0     0     0     7    ]  0   Execute full gc... dataList has been promoted to cms old space         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count0.379: ParallelGCSystemGC               [      10          0              0    ]      [     0     0     0     0    16    ]  0            vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count0.396: no vm operation                  [       9          1              1    ]      [ 0 0 0 0 341 ] 0

Print Reference Processing InformationStrong

Reference

/Weak Reference/Soft Reference/Virtual Reference/Finalize Method If there is a problem, must it not be printed out to see? 

-XX:+PrintReferenceGC

output example:

 2021-02-19T12:41:30.462+0800: 5072726.605: [SoftReference, 0 refs, 0.0000521 secs]2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs]2021-02-19T12 :41:30.462+0800: 5072726.605: [FinalReference, 0 refs, 0.0000056 secs]2021-02-19T12:41:30.462+0800: 5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs]2021-02-19T12 :41:30.462+0800:5072726.605: [JNI Weak Reference, 0.0000131 secs], 0.4635293 secs]

Full parameter

# requireds -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime
# optional 
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

output

Just what is printed is defined above, and by default, these logs are output to the console (standard output). So if your program log is also output to the console, the log content will be very messy, and it will be very troublesome to analyze. If you append (e.g. tomcat’s catalina.out is append), the file will get bigger and bigger, and the analysis will be fatal.

So there needs to be a mechanism for dividing the log, this mechanism… JVM is naturally provided.

JVM’s

log

splittingJVM provides several parameters for splitting GC logs

: # File path of 

GC log output -Xloggc:/path/to/gc
.log# Enable log file splitting
 -XX:+ UseGCLogFileRotation # 
Split up to a few files, after which you write from scratch
 -XX:NumberOfGCLogFiles=14
# Maximum size per file, exceeding which triggers splitting
 -XX:GCLogFileSize=100M

According to this parameter, each GC log will be split as long as it exceeds 20M, and up to 5 files will be split, and the file names are

gc.log.0, gc.log.1, gc.log.2, gc.log.3, gc.log.4, …….

It seems very beautiful, but a few lines of configuration solve the problem of the output file. But there are some problems with this method:

the log file specified by the

    -Xloggc mode is the way to overwrite the write, which will be overwritten every time it is started, and the history log will be lost When the maximum number of splits is exceeded, it will be rewritten from

  • the 0th
    file, and it is overwritten
  • -XX: NumberOfGCLogFiles can’t be set to infinite

The problem of this override is a bit disgusting, the history log before each startup overwrite… Who can endure this?

Naming files with timestamps

has another solution. Instead of using the log splitting feature provided by the JVM, the log file is named with a timestamp for each boot, so that a different file is used for each boot and there is no overwriting problem.

# Use -%t as the log file name -XX:+

PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc-%t.log# The generated file name is this: gc-2021-03-29_20-41-47.
 Is log

perfect?

While there is

no overriding issue, since there is no log splitting feature, there is only one GC log file after each boot, and a single log file can be very large. Large log files are cumbersome to analyze and must be divided.

The combination of

the two

here only needs to adjust the strategy slightly, and combine the two schemes of JVM segmentation and timestamp naming to get the optimal way. 

# The file path of GC log output - Xloggc:/path/to/gc-%t
.log# Enable log file splitting-XX
:+UseGCLogFileRotation 
# Split up to a few files, after which you can write from scratch 
-XX:NumberOfGCLogFiles=14
# The maximum size of each file, if it exceeds it, it triggers splitting-XX
:GCLogFileSize=100M

Configure the timestamp composition GC log file name and also configure the GC log segmentation policy of JVM. In this way, it not only ensures that the GC file will not be overwritten, but also ensures that the size of a single GC file will not be too large, perfect!

The resulting log file name would look like this:

    gc-2021-03-29_20-41-47

  • .log.0 gc-2021-03-29_20-41-47.log.1
  • gc-2021-03-29_20-41-47.log.2
  • gc-2021-03-29_20-41-47.log.3
  • ….

Best Practice – Full Parameters

# Required -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime
# Optional
 -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1# File path of GC log 
output
 -Xloggc:/path/to/gc-%t
.log# Turn on log file splitting
 -XX:+ UseGCLogFileRotation # 
Split up to several files, after which you start writing -
XX:NumberOfGCLogFiles=14
# Maximum size of each file, exceeding which triggers splitting

 -XX:GCLogFileSize=100M