PrintGCDetails 参数

-XX:+PrintGCDetails 是在启动 java 时，添加的 VM 参数，用来在控制台中输出 GC 的详情。
用这个参数可以详细的查看 GC 的回收操作，一般会将 GC 的输出，单独单到一个 log 文件当中进行查看。

添加启动参数

java -XX:+PrintGCDetails -jar Demo.jar

GC日志示例

1
2
0.098: [GC (Allocation Failure) [PSYoungGen: 1022K->490K(1536K)] 1022K->522K(30208K), 0.0007804 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.959: [Full GC (Ergonomics) [PSYoungGen: 384K->0K(1536K)] [ParOldGen: 28064K->11941K(28672K)] 28448K->11941K(30208K), [Metaspace: 3382K->3382K(1056768K)], 0.0063741 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

这个用来理解每个日志的意义。

1.Allocation Failure 分配 失败
2.promotion Failure: 晋升 失败，进行Minor GC时，survivor space放不下, 对象只能放入老年代，而此时老年代也放不下造成的；
3.concurrent mode failure：是在执行CMS GC的过程中同时有对象要放入老年代，而此时老年代空间不足造成的

日志说明

0.098: 运行时间
GC (Allocation Failure): [GC类型 (原因)]
[PSYoungGen: 1022K->490K(1536K)]: [收集器类型: GC前该内存区域已经使用容量->GC后该内存区域已使用容量(该内存区域总容量)],执行时间 secs
[Times: user=0.00 sys=0.00, real=0.00 secs]: user=用户线程使用时间 sys=系统执行使用时间, real=真正回收时间

连起来看
运行时间: [GC类型 (原因)] [收集器类型: GC前该内存区域已经使用容量->GC后该内存区域已使用容量(该内存区域总容量)] GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）, 执行时间 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

2.jvm 执持时间

0.098、0.143 都是 jvm 启动后的时间，从 0 开始

3.GC 和 Full (GC 回收类型)

以 GC 和 Full GC 开头的说明了这次回收的停顿为型。
而不是用来区分新生代GC还是老年代GC的。
如果有”Full GC”，说明这次GC是发生了Stop-The-World的。

4.[PSYoungGen、[ParOldGen、[Metaspace表示GC发生的区域

这里显示的区域名称与使用的GC收集器是密切相关的，
例如上面的PSYoungGen表示采用Parallel Scavenge收集器，
ParOldGen表示采用Parallel Old收集器。
如果使用Serial收集器显示[DefNew，如果使用ParNew收集器显示[ParNew。

5.括号中的含义

后面方括号内部的1022K->490K(1536K)含义是:
“GC前该内存区域已经使用容量->GC后该内存区域已使用容量（该内存区域总容量）”。
而在方括号之外的1022K->522K(30208K)表示：
“GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）”。
再往后的 0.0007804 secs 表示该内存区域GC所占用的时间，单位是秒。

[Times: user=0.00 sys=0.00, real=0.00 secs]
表示:
user、sys、real 与 Linux 的 time 命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU时间 和 操作从开始到结束所经过的墙钟时间（Wall Clock Time）。
CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘IO、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到 user 或 sys 时间超过 real 时间是完全正常的。

1
2
3
4
5
6
7
8
9
10
0.098: [GC (Allocation Failure) [PSYoungGen: 1022K->490K(1536K)] 1022K->522K(30208K), 0.0007804 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.143: [GC (Allocation Failure) [PSYoungGen: 1514K->490K(1536K)] 1546K->797K(30208K), 0.0014763 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.154: [GC (Allocation Failure) [PSYoungGen: 1466K->490K(1536K)] 1773K->1064K(30208K), 0.0021920 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.179: [GC (Allocation Failure) [PSYoungGen: 1514K->490K(1536K)] 2088K->1224K(30208K), 0.0014370 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.212: [GC (Allocation Failure) [PSYoungGen: 1514K->490K(1536K)] 2248K->1534K(30208K), 0.0013529 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
0.257: [GC (Allocation Failure) [PSYoungGen: 1513K->490K(1536K)] 2556K->1664K(30208K), 0.0082179 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.957: [GC (Allocation Failure) [PSYoungGen: 769K->384K(1536K)] 28567K->28448K(30208K), 0.0016967 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.959: [Full GC (Ergonomics) [PSYoungGen: 384K->0K(1536K)] [ParOldGen: 28064K->11941K(28672K)] 28448K->11941K(30208K), [Metaspace: 3382K->3382K(1056768K)], 0.0063741 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
3.621: [GC (Allocation Failure) [PSYoungGen: 20K->32K(1536K)] 28346K->28357K(30208K), 0.0012428 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
3.622: [Full GC (Ergonomics) [PSYoungGen: 32K->0K(1536K)] [ParOldGen: 28325K->11936K(28672K)] 28357K->11936K(30208K), [Metaspace: 3386K->3386K(1056768K)], 0.0038742 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]