求你了,GC 日志打印别再瞎配置了(Please, stop configuring GC log printing)

生产环境上,或者其他要测试 GC 问题的环境上,一定会配置上打印GC日志的参数,便于分析 GC 相关的问题。但是可能很多人配置的都不够“完美”,要么是打印的内容过少,要么是输出到控制台,要么是一个大文件被覆盖,要么是……本文带你一步一步,配置一个完美的 GC 日志打印策略打印内容为了保留足够多的“现场证据”,最好是把 GC 相关的信息打印的足够完整。而且你的程序真的不差你GC时打印日志I/O消耗的那点性能打印基本 GC 信息打印 GC 日志的第一步,就是开启 GC 打印的参数了,也是最基本的参数。

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

打印对象分布为了分析 GC 时的晋升情况和晋升导致的高暂停,不看对象年龄分布日志怎么行

-XX:+PrintTenuringDistribution

输出内容示例:

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 后打印堆数据每次发生 GC 时,对比一下 GC 前后的堆内存情况,更直观

-XX:+PrintHeapAtGC

输出内容示例:

{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
}

打印 STW 时间暂停时间是 GC 最重要的指标,肯定不能少

-XX:+PrintGCApplicationStoppedTime

输出内容示例:

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

打印 safepoint 信息进入STW阶段之前,需要要找到一个合适的 safepoint ,这个指标一样很重要(非必选,出现 GC 问题时最好加上此参数调试)

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

输出内容示例:

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   

打印 Reference 处理信息强引用/弱引用/软引用/虚引用/finalize 方法万一有问题,不得打印出来看看?

-XX:+PrintReferenceGC

输出内容示例:

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]

完整参数

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

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

输出方式上面只是定义了打印的内容,默认情况下,这些日志会输出到控制台(标准输出)。那如果你的程序日志也输出到控制台呢,这个日志内容就会很乱,分析起来很麻烦。如果你是追加的方式(比如 tomcat 的 catalina.out 就是追加),这个文件会越来越大,分析起来就要命了。所以需要一种分割日志的机制,这个机制嘛……JVM自然是提供的。JVM 的日志分割JVM提供了几个用于分割 GC 日志的参数:

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

按照这个参数,每个GC日志只要超过20M就会进行分割,最多分割5个文件,文件名依次是gc.log.0,gc.log.1,gc.log.2,gc.log.3,gc.log.4, …..看似很美好,几行配置就搞定了输出文件的问题。但是这种方式有一些问题:-Xloggc 方式指定的日志文件,是覆盖写的方式,每次启动都会覆盖,历史日志会丢失当超过最大分割数后,会从第0个文件开始重新写入,而且是覆盖-XX:NumberOfGCLogFiles 并不能设置为无限这个覆盖的问题就有点恶心了,每次启动覆盖之前的历史日志……这谁能忍?使用时间戳命名文件于是有另一种解决方案。不使用 JVM 提供的日志分割功能,而是每次启动用时间戳命名日志文件,这样可以每次启动都使用不同的文件,就不会出现覆盖的问题了。

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

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

可是这样就完美吗?虽然没有覆盖的问题,但由于没有日志分割的功能,每次启动后只有一个GC日志文件,单个日志文件可能会非常巨大。过大的日志文件分析起来是很麻烦的,必须得分割。二者结合这里只需要稍微调整一下策略,将 JVM 分割和时间戳命名两种方案结合,就可以得到最优的方式了。

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

配置时间戳作文 GC 日志文件名的同时,也配置JVM的GC日志分割策略。这样一来,既保证了 GC 文件不会被覆盖,又保证了单个 GC 文件的大小不会过大,完美!最终得到的日志文件名会像这个样子:

  • 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
  • ….

最佳实践 – 完整参数

# 必备
-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

总结

在生产环境的JVM参数配置一定要多思考,需要打印什么信息。

————————

On the production environment or 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 “perfect”, either too little content is printed, or 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 < strong > printing content < / strong > in order to retain enough “on-site evidence”, It is best to print the GC related information completely enough. Moreover, your program is really not bad at the performance of I / O consumption when printing logs during GC < strong > printing basic GC information < / strong > the first step in printing GC logs is to enable GC printing parameters, which are also the most basic parameters.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

< strong > print object distribution < / strong > in order to analyze the promotion during GC and the high pause caused by promotion, do not look at the object age distribution log

-XX:+PrintTenuringDistribution

< strong > output content example: < / strong >

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

< strong > Print heap data after GC < / strong > each time a GC occurs, compare the heap memory before and after GC, which is more intuitive

-XX:+PrintHeapAtGC

< strong > output content example: < / strong >

{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
}

< strong > Print STW time < / strong > pause time is the most important indicator of GC, which must be included

-XX:+PrintGCApplicationStoppedTime

Example of output content:

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

< strong > Print safepoint information < / strong > 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 for debugging in case of GC problems)

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

Example of output content:

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   

< strong > Print reference processing information < / strong > strong reference / weak reference / soft reference / virtual reference / finalize method in case of any problem, do not print it out?

-XX:+PrintReferenceGC

Example of output content:

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]

< strong > complete parameters < / strong >

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

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

< strong > output method < / strong > only the print content is defined above. By default, these logs will be output to the console (standard output). If your program log is also output to the console, the log content will be messy and troublesome to analyze. If you append (for example, catalina.out of Tomcat is append), the file will become larger and larger, which will be fatal for analysis. Therefore, we need a mechanism to split logs. The JVM naturally provides this mechanism< Strong > log splitting of JVM < / strong > the 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, as long as each GC log exceeds 20m, it will be divided into 5 files at most. The file names are GC. Log. 0, GC. Log. 1, GC. Log. 2, GC. Log. 3, GC. Log. 4,… It seems very beautiful. A few lines of configuration can solve the problem of output files. However, there are some problems with this method: – the log file specified in the xloggc method is overwritten. It will be overwritten every time it is started, and the historical log will be lost. When the maximum number of partitions is exceeded, it will be rewritten from the 0th file, and the overwriting – XX: numberofgclogfiles cannot be set to infinite. This problem of overwriting is a little disgusting, The history log before each startup overwrite… Who can bear this< Strong > name the file with a timestamp < / strong > so there is another solution. Instead of using the log splitting function provided by the JVM, the log file is named with a timestamp every time it is started, so that different files can be used every 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 that perfect? Although there is no coverage problem, due to the lack of log segmentation function, there is only one GC log file after each startup, and a single log file may be very large. Too large log files are troublesome to analyze and must be segmented< Strong > combination of the two < / strong > here, you only need to adjust the strategy slightly and combine the JVM segmentation and timestamp naming schemes to get the optimal method.

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

Configure the GC log partition policy of the JVM as well as the timestamp and GC log file name. 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:

  • 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
  • ….

< strong > Best Practices – full parameters < / strong >

# 必备
-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

总结

You must think more about the JVM parameter configuration in the production environment and what information needs to be printed.