JAVA开发中GC日志打印简单通用的配置详解

如何配置一个完美的JVM日志打印信息
打印内容
打印基本的GC信息
打印对象分布情况
GC后打印堆数据
打印STW时间
打印safepoint信息
打印Reference处理信息
综上所述，最终的参数如下：
还有哪些问题呢？是不是有文件输出更好？
打印日志
最佳实践-完整参数
先点赞，在收藏，养成良好一键三连白嫖习惯hhhh

本文记录下在学习和生产中如何打印和测试GC问题，那么一定会配置打印GC日志参数，因此配置一个全面且通用的GC日志打印就尤为重要了。

打印内容
为了保留足够多的“现场证据”，最好是 GC 相关的信息打印完整。而且你的程序真的不差你GC时打印日志I/O消耗的那点性能。

打印基本的GC信息配置

打印GC日志第一步，就是开启打印GC参数，也就是最基本的参数

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

打印对象分布情况

为了分析GC时晋升情况和晋升导致的高暂停，不看对象年龄分布日志怎么可以呢?

-XX:PrintTenuringDistrution

输出内容实例

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后查看下堆前后的内存情况，更直观

{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 1056768Kclass 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 1056768Kclass space used
371K, capacity 388K, committed 512K, reserved 1048576K }

打印STW时间

-XX:+PrintGCApplicationStoppedTime

打印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 spacevmop                    [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]

综上所述，最终的参数如下：

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

还有哪些问题呢？是不是有文件输出更好？

上面只是定义了打印的内容，默认情况下，这些日志会输出到控制台（标准输出）。那如果你的程序日志也输出到控制台呢，这个日志内容就会很乱，分析起来很麻烦。如果你是追加的方式（比如 tomcat 的 catalina.out 就是追加），这个文件会越来越大，分析起来就要命了。

所以需要一种分割日志的机制，这个机制嘛……JVM自然是提供的。

打印日志

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

最佳实践-完整参数

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

windows 测试环境下jvm 参数配置

-Xms1m -Xmx1m -XX:+PrintGC -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=e:\mydoc\heapdump-%t.hprof -Xloggc:e:/mydoc/gc-%t.log

生成gc 日志文件和dump 异常时候的文件目录如下

GC日志内容分析

读懂GC日志

垃圾回收器的种类不同gc的日志打印格式也不一样，不过日志的格式含义其实差不多；一般的含义如下

读懂linux jstat -gc的命令日志

jstat -gcutil 6404 1000

jstat -gcutil pid 打印时间间隔 次数
jstat -gcutil 6404 1000 5