[TOC]
1、如何收集GC日志
1.1、 配置JVM启动参数：
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<file-path>
示例：
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/opt/app/gc.log
1.2、 GC相关启动参数说明
1.2.1、简单日志模式
-XX:+PrintGC 或者 -verbose:gc
日志输出示例:
[GC 246656K->243120K(376320K), 0,0929090 secs]
[Full GC 243120K->241951K(629760K), 1,5589690 secs]
1.2.2、详细日志格式
-XX:+PrintGCDetails
日志输出示例：
[GC [PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K), 0,0935090 secs] [Times: user=0,55 sys=0,10, real=0,09 secs]
[Full GC [PSYoungGen: 10752K->9707K(142848K)] [ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K) [PSPermGen: 3162K->3161K(21504K)], 1,5265450 secs] [Times: user=10,96 sys=0,06, real=1,53 secs]
1.2.3、日志中添加时间标志（日志每行开头显示自从JVM启动以来的时间，���������单位为秒）
-XX:+PrintGCTimeStamps
日志输出示例：
0,185: [GC 66048K->53077K(251392K), 0,0977580 secs]
0,323: [GC 119125K->114661K(317440K), 0,1448850 secs]
1.2.4、日志中添加日期标志（日志每行开头显示绝日期及时间，���������单位为秒）
-XX:+PrintGCDateStamps
日志输出示例：
2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0,0959470 secs]
2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0,1421720 secs]
1.2.5、 打印GC前后的详细堆栈信息
-XX:+PrintHeapAtGC
日志输出示例：
Heap after GC invocations=1 (full 0):
par new generation total 943744K, used 54474K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000)
eden space 838912K, 0% used [0x0000000757000000, 0x0000000757000000, 0x000000078a340000)
from space 104832K, 51% used [0x00000007909a0000, 0x0000000793ed2ae0, 0x0000000797000000)
to space 104832K, 0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000)
concurrent mark-sweep generation total 1560576K, used 0K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000)
concurrent-mark-sweep perm gen total 159744K, used 38069K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000)
}
1.2.6、查看每次minor GC后新的存活周期的阈值
-XX:+PrintTenuringDistribution
日志输出示例：
Desired survivor size 53673984 bytes, new threshold 4 (max 6)
- age 1: 9165552 bytes, 9165552 total
- age 2: 2493880 bytes, 11659432 total
- age 3: 6817176 bytes, 18476608 total
- age 4: 36258736 bytes, 54735344 total
: 899459K->74786K(943744K), 0.0654030 secs] 1225769K->401096K(2504320K), 0.0657530 secs] [Times: user=0.55 sys=0.00, real=0.07 secs]
2、GC文件格式说明
2.1、 GC文件图解
Java GC文件图解
2.2、GC文件格式详解
2014-11-18T16:39:37.728-0800: 88.808: [Full GC [PSYoungGen: 116544K->12164K(233024K)] [PSOldGen: 684832K->699071K(699072K)] 801376K->711236K(932096K) [PSPermGen: 2379K->2379K(21248K)], 3.4230220 secs] [Times: user=3.40 sys=0.02, real=3.42 secs]
每部分说明如下:
2014-11-18T16:39:37.728-0800 – GC运行的绝对时间.
Full GC – GC类型，可以是‘Full GC’ 或 ‘GC’。
[PSYoungGen: 116544K->12164K(233024K)] – 运行新生代GC后，新生代空间从116544k 减少到 12164k 。 总计分配的新生代空间为233024k。
[PSOldGen: 684832K->699071K(699072K)] – 运行年老代GC后, 年老代空间从 684832k 减少到 699071k 。 总计分配的年老代空间为669072k。
801376K->711236K(932096K) – 运行GC后, 整个内存空间从 801376k 减少到 711236k 。 总计分配的内存空间 932096k。
[PSPermGen: 2379K->2379K(21248K)] – 运行GC后, 持久代空间从 2379K 减少到 2379K 。 没有回收持久代空间。
3.4230220 secs – 此次GC运行了3.42秒。
[Times: user=3.40 sys=0.02, real=3.42 secs] –
Real - 是调用从开始到结束的实际持续时间。 这是所有持续的时间，包括其他进程消耗的时间片和进程花费在阻塞等待（比如等待I/O完成）上的时间。
User - 是进程用户模式（user-mode）代码(非内核模式)消耗的CPU时间。这只是运行这个进程所消耗的CPU时间。其他进程及进程花费在阻塞等待上的时间不包括在内。
Sys - 是进程内核模式（执行内核代码）消耗的CPU时间。 只包括内核中系统调用消耗的CPU时间，不包括执行库代码（library code)的时间。和 'user' 一样，只统计这个进程自己消耗的时间。
User+Sys 告诉你你的进程实际消耗的CPU时间。注意这个时间是所有CPUs时间总和，所以如果进程是多线程执行，那么 User+Sys 可能大于 Real 。
并行GC示例：
[Times: user=11.53 sys=1.38, real=1.03 secs]
串行GC示例：
[Times: user=0.09 sys=0.00, real=0.09 secs]
3、GC分析工具
3.1、在线GC分析
4、参考资料
https://dzone.com/articles/understanding-garbage-collection-log
https://blog.tier1app.com/2016/04/06/gc-logging-user-sys-real-which-time-to-use/
https://blog.codecentric.de/en/2014/01/useful-jvm-flags-part-8-gc-logging/
http://www.codeceo.com/article/twitter-jvm-performance.html#0-tsina-1-26634-397232819ff9a47a7b7e80a40613cfe1
http://www.cnblogs.com/redcreen/archive/2011/05/04/2037057.html
http://darktea.github.io/notes/2013/09/08/java-gc.html
