PrintGCDetails 参数
-XX:+PrintGCDetails 是在启动 java 时,添加的 VM 参数,用来在控制台中输出 GC 的详情。 用这个参数可以详细的查看 GC 的回收操作,一般会将 GC 的输出,单独单到一个 log 文件当中进行查看。
添加启动参数
java -XX:+PrintGCDetails -jar Demo.jar
GC日志示例
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 时间是完全正常的。
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]