Please, stop configuring GC log printing

Like it first, then watch it, develop a good habit

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

However, many people may not configure it as "perfect". Either the printed content is too little, or it is output to the console, or a large file is overwritten, or...

This article takes you step by step to configure a perfect GC log printing strategy

Print content

In order to retain enough "field evidence", it is best to print out GC-related information in full. and your program is really not bad at the performance of printing log I/O consumption when you GC

Print basic GC information

The first step in printing the GC log is to enable the GC printing parameters, which is also the most basic parameter.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

Print object distribution

In order to analyze the during GC and the high suspension caused by promotion , how to do it regardless of the age distribution log of the object

-XX:+PrintTenuringDistribution

output:

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

Print heap data after GC

Every time a GC occurs, it is more intuitive to compare the heap memory situation before and after the GC

-XX:+PrintHeapAtGC

output content:

{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 1048576K
Heap 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:

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

Print safepoint information

Before entering the STW stage, 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=1

output:

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.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_count
0.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_count
0.396: no vm operation                  [       9          1              1    ]      [     0     0     0     0   341    ]  0   

Print Reference processing information

Strong quotation/weak quotation/soft quotation/phantom quotation/finalize method in case there is a problem, can’t print it out to see?

-XX:+PrintReferenceGC

output:

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 parameters

# requireds
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

output method

The above just defines the content to be printed. By default, these logs will be output to the console (standard output). Then if your program log is also output to the console, the content of the log will be messy and it will be troublesome to analyze. If you are appending (for example, tomcat's catalina.out is appending), this file will become larger and larger, and it will be fatal to analyze.

So we need a mechanism to split the log, this mechanism... JVM naturally provides it.

JVM log segmentation

JVM provides several parameters for splitting GC logs:

# GC日志输出的文件路径
-Xloggc:/path/to/gc.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation 
# 最多分割几个文件，超过之后从头开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小，超过就触发分割
-XX:GCLogFileSize=100M

According to this parameter, each GC log will be split as long as it exceeds 20M, up to 5 files are split, and the file name is gc.log.0,gc.log.1,gc.log.2,gc.log.3,gc.log.4, .....

It seems very beautiful, a few lines of configuration solve the problem of the output file. But this approach has some problems:

1. The log file specified by the -Xloggc method is an overwrite method, which will be overwritten every time it is started, and the historical log will be lost
2. When the maximum number of divisions is exceeded, it will be rewritten from the 0th file, and it is overwritten
3. -XX:NumberOfGCLogFiles cannot be set to unlimited

This overwriting problem is a bit disgusting, every time you start overwriting the previous history log...Who can bear this?

Use timestamp to name files

So there is another solution. Instead of using the log splitting function provided by the JVM, the log file is named with a timestamp each time it is started, so that a different file can be used each time it is started, and the problem of overwriting will not occur.

# 使用-%t作为日志文件名
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc-%t.log

# 生成的文件名是这种：gc-2021-03-29_20-41-47.log

But is this perfect?

Although there is no coverage problem, because there is no log splitting function, there is only one GC log file after each startup, and a single log file may be very large. Log files that are too large are troublesome to analyze and must be divided.

Combine the two

Here only need to tweak the strategy, the JVM division and naming two programs combined with a timestamp, you can get best way up.

# GC日志输出的文件路径
-Xloggc:/path/to/gc-%t.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation 
# 最多分割几个文件，超过之后从头开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小，超过就触发分割
-XX:GCLogFileSize=100M

While configuring the time stamp composition GC log file name, it also configures the JVM GC log segmentation strategy. 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 final log file name will look like this:

1. gc-2021-03-29_20-41-47.log.0
2. gc-2021-03-29_20-41-47.log.1
3. gc-2021-03-29_20-41-47.log.2
4. gc-2021-03-29_20-41-47.log.3
5. ....

Best practice-full parameters

# 必备
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# 可选
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

# GC日志输出的文件路径
-Xloggc:/path/to/gc-%t.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation 
# 最多分割几个文件，超过之后从头文件开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小，超过就触发分割
-XX:GCLogFileSize=100M

Originality is not easy, unauthorized reprinting is prohibited. If my article is helpful to you, please like/favorite/follow to encourage and support it ❤❤❤❤❤❤