收集日志

添加gc收集相关java启动参数
如 -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:${PINPOINT_AGENT_PATH}/gc.log

如果启动服务后无gc.log文件，查看日志，是否出现can not open file

在jar包前的是vm options 在jar包后的是program arguments

gc相关参数

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径
-XX:+PrintReferenceGC 打印年轻代各个引用的数量以及时长
-verbose:gc
-XX:+UseGCLogFileRotation：是否启用 GC 日志文件自动转储, GC 日志文件按大小切割时需要设置
-XX:GCLogFileSize：控制 GC 日志文件的大小, 用于 GC 日志的切割, 不宜设置太大, 太大由于写日志需要进行 I/O 操作, I/O 操作需要在用户态和和心态之间切换, 会直接影响 user time 大小和 sys time 大小, 最终影响到 real time 大小, real time 就是 GC 耗费的时间。例如：-XX:GCLogFileSize=50M
-XX:NumberOfGCLogFiles：GC 日志文件最多保存的个数。例如：-XX:NumberOfGCLogFiles=10
-XX:+PrintGCApplicationStopedTime ：查看GC造成的应用暂停时间
-XX:+PrintTenuringDistribution:对象晋升的日志
-XX:+HeapDumpOnOutOfMemoryError:内存溢出时输出 dump 文件

-XX:+PrintGC与-verbose:gc

如果想开启GC日志的信息，可以通过设置如下的参数任一参数：

-XX:+PrintGC
-XX:+PrintGCDetails 
-Xloggc:gc.log

如果只设置-XX:+PrintGC那么打印的日志如下所示：

[GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

GC 表示是一次YGC（Young GC）
Allocation Failure 表示是失败的类型
68896K->5080K 表示年轻代从68896K降为5080K
256000K表示整个堆的大小
0.0041139 secs表示这次GC总计所用的时间

在JDK 8中，-verbose:gc是-XX:+PrintGC一个别称，日志格式等价与：-XX:+PrintGC。

不过在JDK 9中 -XX:+PrintGC被标记为deprecated。

-verbose:gc是一个标准的选项， -XX:+PrintGC是一个实验的选项，建议使用-verbose:gc替代-XX:+PrintGC

-XX:+PrintGCDetails

[GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]

GC 表示是一次YGC（Young GC）
Allocation Failure 表示是失败的类型
PSYoungGen 表示年轻代大小
53248K->2176K 表示年轻代占用从53248K降为2176K
59392K表示年轻带的大小
58161K->7161K 表示整个堆占用从53248K降为2176K
256000K表示整个堆的大小
0.0039189 secs 表示这次GC总计所用的时间
[Times: user=0.02 sys=0.01, real=0.00 secs] 分别表示，用户态占用时长，内核用时，真实用时。时间保留两位小数，四舍五入。

-XX:+PrintGCTimeStamps

1.963: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

如果加上-XX:+PrintGCTimeStamps那么日志仅仅比1.1介绍的最前面多了一个时间戳： 1.963，表示从JVM启动到打印GC时刻用了1.963秒。

-XX:+PrintGCDateStamps

2019-03-05T16:56:15.108+0800: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

如果加上-XX:+PrintGCDateStamps那么日志仅仅比1.1介绍的最前面多了一个日期时间： 2019-03-05T16:56:15.108+0800，表示打印GC的时刻的时间是2019-03-05T16:56:15.108+0800。+0800表示是东8区。

-XX:+PrintHeapAtGC

这个参数开启后，
使用如下参数-verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M
打印日志如下：

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 100% used [0x00000000fc000000,0x00000000ff000000,0x00000000ff000000)
  from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
  to   space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
 ParOldGen       total 196608K, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0000000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 0% used [0x00000000fc000000,0x00000000fc000000,0x00000000ff000000)
  from space 8192K, 29% used [0x00000000ff000000,0x00000000ff258020,0x00000000ff800000)
  to   space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
 ParOldGen       total 196608K, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0004000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
}

由此可以看出在，打印如下日志前后

[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]

详细打印出了日志信息
invocations 表示GC的次数，每次GC增加一次，每次GC前后的invocations相等
1、Heap before GC invocations=1 表示是第1次GC调用之前的堆内存状况
2、{Heap before GC invocations=1 (full 0): 表示是第1次GC调用之后的堆内存状况

-Xloggc:gc.log

如果使用该参数-Xloggc则默认开启如下两个参数

-XX:+PrintGC -XX:+PrintGCTimeStamps

如果启动参数如下：-Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M则日志格式如下所示

0.318: [GC (Allocation Failure)  49152K->2384K(253952K), 0.0038675 secs]

gc.log也可以指定绝对的路径。
在gc.log最前面还会默认打印系统的JDK版本与启动的参数

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 16287104k(1657700k free), swap 16636924k(15826632k free)
CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:NewSize=67108864 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC

-XX:+PrintReferenceGC

此设置 -XX:+PrintReferenceGC可以打印出SoftReference，WeakReference，FinalReference，PhantomReference，JNI Weak Reference几种引用的数量，以及清理所用的时长，该参数在进行YGC调优时可以排上用场。

[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000119 secs][WeakReference, 499 refs, 0.0000370 secs][FinalReference, 1045 refs, 0.0002313 secs][PhantomReference, 0 refs, 0 refs, 0.0000039 secs][JNI Weak Reference, 0.0000290 secs][PSYoungGen: 53456K->4880K(57344K)] 53496K->4928K(253952K), 0.0037199 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]

日志格式

新生代回收的日志

2020-04-22T14:54:04.384+0800: 1.698: [GC (Allocation Failure) [PSYoungGen: 17378K->3056K(17408K)] 20149K->7337K(99328K), 0.0044101 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

老年代回收的日志

2020-04-22T14:54:09.024+0800: 6.338: [Full GC (Metadata GC Threshold) [PSYoungGen: 416K->0K(17408K)] [ParOldGen: 20881K->14282K(81920K)] 21297K->14282K(99328K), [Metaspace: 33570K->33567K(1079296K)], 0.2979061 secs] [Times: user=0.55 sys=0.03, real=0.30 secs]

gceasy

可通过gceasy上传并分析日志

gcviewer

运行

git clone代码，在本地打包后执行java -jar gcviewer-1.37-SNAPSHOT.jar

打开收集的gclog

WX20200427-105905@2x

chart

Full GC Lines:（full gc）Black vertical line at every Full GC
Inc GC Lines：（增量GC）Cyan vertical line at every Incremental GC
GC Times Line：（gc 时间）Green line that shows the length of all GCs
GC Times Rectangles：（gc时间区域）
- black rectangle at every Full GC
- blue rectangle at every inital mark event
- orange rectangle at every remark event
- red rectangle at every vm operation event ("application stopped...")
- Grey rectangle at every ‘normal‘ GC
- Light grey rectangle at every Incremental GC
Total Heap：(总堆大小)Red line that shows heap size
Tenured Generation：（老年代）Magenta area that shows the size of the tenured generation (not available without PrintGCDetails)
Young Generation：（年轻代）Orange area that shows the size of the young generation (not available without PrintGCDetails)
Used Heap：（堆使用量）Blue line that shows used heap size
Initial mark level：（cms或g1垃圾回收算法初始标记事件）Yellow line that shows the heap usage at "initial-mark" event (only available when the gc algorithm uses concurrent collections, which is the case for CMS and G1)
Concurrent collections：（cms或g1垃圾回收并发收集周期）Cyan vertical line for every begin (concurrent-mark-start) andpink vertical line for every end (CMS-concurrent-reset / G1: concurrent-cleanup-end) of a concurrent collection cycle

WX20200427-134759@2x

问题

Cannot open file

OpenJDK 64-Bit Server VM warning: Cannot open file /opt/pinpoint-agent/logs/gc.log due to No such file or directory
原因是无logs目录，创建logs目录后正常

配置了XX:GCLogFileSize但是未分割文件

GC文件滚动大小，需配置UseGCLogFileRotation；通过java -XX:+PrintFlagsFinal发现该参数默认为false,启动jar包时添加-XX:+UseGCLogFileRotation

附

参考

java gc log收集及分析