Java的一大特色就是支持自动垃圾回收（GC），每一个Java开发人员都需要了解虚拟机的垃圾回收机制，本文，就来介绍下如何通过虚拟机的GC日志了解垃圾回收的情况。

最简单的一个GC参数是-XX:+PrintGC（在JDK9、JDK10中建议使用-Xlog:gc），使用这个参数启动Java虚拟机后，只要遇到GC，就会打印日志，如下所示：

[GC 4793K->377K(15872K), 0.0006926 secs][GC 4857K->377K(15936K), 0.0003595 secs][GC 4857K->377K(15936K), 0.0001755 secs][GC 4857K->377K(15936K), 0.0001957 secs]377K(15872K), 0.0006926 secs][GC 4857K->377K(15936K), 0.0003595 secs][GC 4857K->377K(15936K), 0.0001755 secs][GC 4857K->377K(15936K), 0.0001957 secs]

该日志显示，一共进行了4次GC，每次GC占用一行，在GC前，堆空间使用量约为4MB，在GC后，堆空间使用量为377KB，当前可用的堆空间总和约为16MB（15936KB）。最后，显示的是本次GC所花的时间。

JDK9、JDK10默认使用G1作为垃圾回收器，使用参数-Xlog:gc来打印GC日志，如下所示：

[0.012s][info][gc] Using G1[0.107s][info][gc] GC(0) Pause Full (System.gc()) 16M->7M(34M) 23.511msinfo][gc] Using G1[0.107s][info][gc] GC(0) Pause Full (System.gc()) 16M->7M(34M) 23.511ms

该日志显示，一共进行了1次GC，在GC前，堆空间使用量为16MB，在GC后，堆空间使用量为7MB，当前可用的堆空间总和为34MB。最后，显示的是本次GC所花的时间，为23.511ms。

如果需要更加详细的信息，可以使用-XX:+PrintGCDetails参数。JDK8（JDK9、JDK10建议使用-Xlog:gc*，后面讲述）中的输出可能如下：

[GC[DefNew: 8704K->1087K(9792K), 0.0665590 secs] 22753K->17720K(31680K), 0.0666180 secs] [Times: user=0.06 sys=0.00, real=0.06 secs][GC[DefNew: 9791K->9791K(9792K), 0.0000350 secs][Tenured: 16632K->13533K(21888K),0.4063120 secs] 26424K->13533K(31680K), [Perm : 2583K->2583K(21248K)], 0.4064710 secs] [Times: user=0.41 sys=0.00, real=0.40 secs][GC[DefNew: 8704K->1087K(9792K), 0.0574610 secs] 22237K->16688K(31680K), 0.0575180 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]Heapdef new generation total 9792K, used 4586K [0x00000000f8e00000, 0x00000000f98a0000, 0x00000000f98a0000)eden space 8704K, 40% used [0x00000000f8e00000, 0x00000000f916a8e0, 0x00000000f9680000)from space 1088K, 99% used [0x00000000f9680000, 0x00000000f978ffe0, 0x00000000f9790000)to space 1088K, 0% used [0x00000000f9790000, 0x00000000f9790000, 0x00000000f98a0000)tenured generation total 21888K, used 15600K [0x00000000f98a0000, 0x00000000fae00000, 0x00000000fae00000) the space 21888K, 71% used [0x00000000f98a0000, 0x00000000fa7dc278,0x00000000fa7dc400, 0x00000000fae00000)compacting perm gen total 21248K, used 2591K [0x00000000fae00000, 0x00000000fc2c0000, 0x0000000100000000) the space 21248K, 12% used [0x00000000fae00000, 0x00000000fb087ca8,0x00000000fb087e00, 0x00000000fc2c0000)No shared spaces configured.1087K(9792K), 0.0665590 secs] 22753K->17720K(31680K), 0.0666180 secs] [Times: user=0.06 sys=0.00, real=0.06 secs][GC[DefNew: 9791K->9791K(9792K), 0.0000350 secs][Tenured: 16632K->13533K(21888K),0.4063120 secs] 26424K->13533K(31680K), [Perm : 2583K->2583K(21248K)], 0.4064710 secs] [Times: user=0.41 sys=0.00, real=0.40 secs][GC[DefNew: 8704K->1087K(9792K), 0.0574610 secs] 22237K->16688K(31680K), 0.0575180 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]Heapdef new generation total 9792K, used 4586K [0x00000000f8e00000, 0x00000000f98a0000, 0x00000000f98a0000)eden space 8704K, 40% used [0x00000000f8e00000, 0x00000000f916a8e0, 0x00000000f9680000)from space 1088K, 99% used [0x00000000f9680000, 0x00000000f978ffe0, 0x00000000f9790000)to space 1088K, 0% used [0x00000000f9790000, 0x00000000f9790000, 0x00000000f98a0000)tenured generation total 21888K, used 15600K [0x00000000f98a0000, 0x00000000fae00000, 0x00000000fae00000) the space 21888K, 71% used [0x00000000f98a0000, 0x00000000fa7dc278,0x00000000fa7dc400, 0x00000000fae00000)compacting perm gen total 21248K, used 2591K [0x00000000fae00000, 0x00000000fc2c0000, 0x0000000100000000) the space 21248K, 12% used [0x00000000fae00000, 0x00000000fb087ca8,0x00000000fb087e00, 0x00000000fc2c0000)No shared spaces configured.

从这个输出中可以看到，系统经历了3次GC，第1次仅为新生代GC，回收的效果是新生代从回收前的8MB左右降低到1MB。整个堆从22MB左右降低到17MB。

第2次（加粗部分）为Full GC，它同时回收了新生代、老年代和永久区。日志显示，新生代在这次GC中没有释放空间（严格来说，这是GC日志的一个小bug，事实上，在这次Full GC完成后，新生代被清空，由于GC日志输出时机的关系，各个版本JDK的日志多少有些不太精确的地方，读者需要留意），老年代从16MB降低到13MB。整个堆大小从26MB左右降低为13MB左右（这个大小完全与老年代实际大小相等，因此也可以推断，新生代实际上已被清空）。永久区的大小没有变化。日志的最后显示了GC所花的时间，其中user表示用户态CPU耗时，sys表示系统CPU耗时，real表示GC实际经历的时间。

参数-XX:+PrintGCDetails还会使虚拟机在退出前打印堆的详细信息，详细信息描述了当前堆的各个区间的使用情况。如上输出所示，当前新生代（new generation）总大小为9792KB，已使用4586KB。紧跟其后的3个16进制数字表示新生代的下界、当前上界和上界。

[0x00000000f8e00000, 0x00000000f98a0000, 0x00000000f98a0000)0x00000000f98a0000, 0x00000000f98a0000)

使用上界减去下界就能得到当前堆空间的最大值，使用当前上界减去下界，就是当前虚拟机已经为程序分配的空间。如果当前上界等于下界，说明当前的堆空间已经没有扩大的可能性。在本例中（0x00000000f98a0000-0x00000000f8e00000）/1024=10880KB。这块空间正好等于eden+from+to的总和。而可用的新生代9792KB为eden+from(to)的总和，对于两者出现差异的原因，读者可以参考本书第4章。

除了新生代，详细的堆日志中还显示了老年代（tenuredgeneration）和永久区（compactingperm gen）的使用情况，其格式和新生代相同。

JDK9、JDK10使用参数-Xlog:gc*来打印更加详细的GC日志，如下所示：

[0.010s][info][gc,heap]Heap region size: 1M[0.012s][info][gc ] Using G1[0.013s][info][gc,heap,coops]Heap address: 0x00000000fe000000, size: 32 MB, Compressed Oops mode: 32-bit[5.335s][info][gc,start ]GC(0) Pause Young (G1 Evacuation Pause)[5.336s][info][gc,task ]GC(0) Using 8 workers of 8 for evacuation[5.339s][info][gc,phases ]GC(0) Pre Evacuate Collection Set:0.0ms[5.340s][info][gc,phases ]GC(0) Evacuate Collection Set: 3.3ms[5.341s][info][gc,phases ]GC(0) Post Evacuate Collection Set:0.1ms[5.341s][info][gc,phases ]GC(0) Other: 0.6ms[5.341s][info][gc,heap ]GC(0) Eden regions: 14->0(17)[5.341s][info][gc,heap ]GC(0) Survivor regions: 0->2(2)[5.342s][info][gc,heap ]GC(0) Old regions: 0->0[5.342s][info][gc,heap ]GC(0) Humongous regions: 0->0[5.342s][info][gc,metaspace] GC(0) Metaspace: 3418K->3418K(1056768K)[5.342s][info][gc ]GC(0) Pause Young (G1 Evacuation Pause) 14M->1M(32M) 7.028ms[5.342s][info][gc,cpu ]GC(0) User=0.05s Sys=0.00s Real=0.01sinfo][gc,heap]Heap region size: 1M[0.012s][info][gc ] Using G1[0.013s][info][gc,heap,coops]Heap address: 0x00000000fe000000, size: 32 MB, Compressed Oops mode: 32-bit[5.335s][info][gc,start ]GC(0) Pause Young (G1 Evacuation Pause)[5.336s][info][gc,task ]GC(0) Using 8 workers of 8 for evacuation[5.339s][info][gc,phases ]GC(0) Pre Evacuate Collection Set:0.0ms[5.340s][info][gc,phases ]GC(0) Evacuate Collection Set: 3.3ms[5.341s][info][gc,phases ]GC(0) Post Evacuate Collection Set:0.1ms[5.341s][info][gc,phases ]GC(0) Other: 0.6ms[5.341s][info][gc,heap ]GC(0) Eden regions: 14->0(17)[5.341s][info][gc,heap ]GC(0) Survivor regions: 0->2(2)[5.342s][info][gc,heap ]GC(0) Old regions: 0->0[5.342s][info][gc,heap ]GC(0) Humongous regions: 0->0[5.342s][info][gc,metaspace] GC(0) Metaspace: 3418K->3418K(1056768K)[5.342s][info][gc ]GC(0) Pause Young (G1 Evacuation Pause) 14M->1M(32M) 7.028ms

[5.342s][info][gc,cpu ]GC(0) User=0.05s Sys=0.00s Real=0.01s

从这个输出中可以看到，堆的最大可用大小为32MB，系统经历了1次GC，为新生代GC，回收的效果是整个堆从14MB左右降低到了1MB。在JDK9、JDK10中，除了新生代、老年代，还新增了一个巨型区域，即上述输出中的Humongousregions。

另外，日志中有详细的时间信息，第一列显示Java程序运行的时间，PauseYoung (G1 Evacuation Pause) 14M->1M(32M) 7.028ms 表示新生代垃圾回收花了7.028ms。

Pre Evacuate Collection Set、Evacuate Collection Set、Post Evacuate Collection Set、Other代表G1垃圾回收标记—清除算法不同阶段所花费的时间。

最后一行的时间信息跟JDK8相同，不再赘述。

如果需要更全面的堆信息，还可以使用参数-XX:+PrintHeapAtGC（考虑到兼容性，从JDK9开始已经删除此参数，查看堆信息可以使用VisualVM，第6章将会讲述）。它会在每次GC前、后分别打印堆的信息，就如同-XX:+PrintGCDetails的最后输出一样。下面就是-XX:+PrintHeapAtGC的输出样式，限于篇幅，只给出部分输出：

{Heap before GC invocations=8 (full 3): def new generation total 8576K, used 8575K [0x32680000,0x32fc0000, 0x33120000) eden space 7680K, 100% used [0x32680000, 0x32e00000, 0x32e00000) from space 896K, 99% used[0x32ee0000, 0x32fbffc0, 0x32fc0000) to space 896K, 0% used [0x32e00000, 0x32e00000, 0x32ee0000) tenured generation total 18880K, used 12353K [0x33120000,0x34390000, 0x34680000)省略部分输出 [GC[DefNew:8575K->895K(8576K), 0.0017210 secs] 20929K->14048K(27456K), 0.0017756secs] [Times: user=0.00 sys=0.00, real=0.00 secs]Heap after GC invocations=9 (full 3): def new generation total 8576K, used 895K [0x32680000,0x32fc0000, 0x33120000) eden space 7680K, 0% used[0x32680000, 0x32680000, 0x32e00000) from space 896K, 99% used[0x32e00000, 0x32edffc0, 0x32ee0000) to space 896K, 0% used [0x32ee0000, 0x32ee0000, 0x32fc0000) tenured generation total 18880K, used 13152K [0x33120000,0x34390000, 0x34680000) the space 18880K, 69% used[0x33120000, 0x33df8288, 0x33df8400, 0x34390000)省略部分输出}3):

 def new generation total 8576K, used 8575K [0x32680000,0x32fc0000, 0x33120000)

 eden space 7680K, 100% used [0x32680000, 0x32e00000, 0x32e00000)

 from space 896K, 99% used[0x32ee0000, 0x32fbffc0, 0x32fc0000)

 to space 896K, 0% used [0x32e00000, 0x32e00000, 0x32ee0000)

 tenured generation total 18880K, used 12353K [0x33120000,0x34390000, 0x34680000)

省略部分输出

 [GC[DefNew:8575K->895K(8576K), 0.0017210 secs] 20929K->14048K(27456K), 0.0017756secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Heap after GC invocations=9 (full 3):

 def new generation total 8576K, used 895K [0x32680000,0x32fc0000, 0x33120000)

 eden space 7680K, 0% used[0x32680000, 0x32680000, 0x32e00000)

 from space 896K, 99% used[0x32e00000, 0x32edffc0, 0x32ee0000)

 to space 896K, 0% used [0x32ee0000, 0x32ee0000, 0x32fc0000)

 tenured generation total 18880K, used 13152K [0x33120000,0x34390000, 0x34680000)

 the space 18880K, 69% used[0x33120000, 0x33df8288, 0x33df8400, 0x34390000)

省略部分输出

}

可以看到，在使用-XX:+PrintHeapAtGC后，在GC日志输出前、后都有详细的堆信息输出，分别表示GC回收前和GC回收后的堆信息，使用这个参数，可以很好地观察GC对堆空间的影响。

如果需要分析GC发生的时间，还可以使用-XX:+PrintGCTimeStamps（JDK9、JDK10中使用-Xlog:gc*已经默认打印出时间，前文关于-Xlog:gc*已经有讲述，这里不再赘述）参数，该参数会在每次GC时，额外输出GC发生的时间，该输出时间为虚拟机启动后的时间偏移量。如下代码表示在系统启动后0.08s、0.088s、0.094s发生了GC。

0.080:[GC0.080: [DefNew: 4416K->512K(4928K), 0.0055792 secs]4416K->3889K(15872K), 0.0057061 secs] [Times:user=0.00 sys=0.00, real=0.01 secs]0.088:[GC0.088: [DefNew: 4928K->511K(4928K), 0.0044292 secs]8305K->7751K(15872K), 0.0045321 secs] [Times:user=0.00 sys=0.00, real=0.00 secs]0.094: [GC0.094: [DefNew: 4927K->511K(4928K), 0.0044136 secs]0.099:[Tenured: 11238K->11327K(11328K), 0.0113929 secs] 12167K->11750K(16256K),[Perm : 142K->142K(12288K)], 0.0160228 secs] [Times: user=0.02 sys=0.00, real=0.02secs][GC0.080: [DefNew: 4416K->512K(4928K), 0.0055792 secs]4416K->3889K(15872K), 0.0057061 secs] [Times:user=0.00 sys=0.00, real=0.01 secs]0.088:[GC0.088: [DefNew: 4928K->511K(4928K), 0.0044292 secs]8305K->7751K(15872K), 0.0045321 secs] [Times:user=0.00 sys=0.00, real=0.00 secs]0.094: [GC0.094: [DefNew: 4927K->511K(4928K), 0.0044136 secs]0.099:[Tenured: 11238K->11327K(11328K), 0.0113929 secs] 12167K->11750K(16256K),[Perm : 142K->142K(12288K)], 0.0160228 secs] [Times: user=0.02 sys=0.00, real=0.02secs]

由于GC会引起应用程序停顿，因此还需要特别关注应用程序的执行时间和停顿时间。使用参数-XX:+PrintGCApplicationConcurrentTime可以打印应用程序的执行时间，使用参数-XX:+PrintGCApplicationStoppedTime可以打印应用程序由于GC而产生的停顿时间，如下所示：

Application time:0.0026770 secondsTotal time for whichapplication threads were stopped: 0.0091600 secondsApplication time:0.0039006 secondsTotal time for whichapplication threads were stopped: 0.0024330 secondstime:0.0026770 secondsTotal time for whichapplication threads were stopped: 0.0091600 secondsApplication time:0.0039006 secondsTotal time for whichapplication threads were stopped: 0.0024330 seconds

如果想跟踪系统内的软引用、弱引用、虚引用和Finallize队列，可以打开-XX:+PrintReferenceGC（考虑到兼容性，从JDK9开始已经删除此参数，查看堆信息可以使用VisualVM，第6章将会讲述）开关，结果如下：

[GC[DefNew[SoftReference, 0 refs, 0.0000212 secs][WeakReference, 7 refs, 0.0000046 secs][FinalReference, 4 refs, 0.0000056secs][PhantomReference, 0 refs,0.0000036 secs][JNI Weak Reference, 0.0000056 secs]: 2752K->320K(3072K),0.0031630 secs] 2752K->2574K(9920K), 0.0031937 secs] [Times: user=0.00sys=0.00, real=0.00 secs]0.0000212 secs][WeakReference, 7 refs, 0.0000046 secs][FinalReference, 4 refs, 0.0000056secs][PhantomReference, 0 refs,0.0000036 secs][JNI Weak Reference, 0.0000056 secs]: 2752K->320K(3072K),0.0031630 secs] 2752K->2574K(9920K), 0.0031937 secs] [Times: user=0.00sys=0.00, real=0.00 secs]

默认情况下，GC的日志会在控制台中输出，这不便于后续分析和定位问题。所以，虚拟机允许将GC日志以文件的形式输出，可以使用参数-Xloggc指定。比如使用参数-Xloggc:log/gc.log（在JDK9、JDK10中建议使用-Xlog:gc:log/gc.log）启动虚拟机，可以在当前目录的log文件夹下的gc.log文件中记录所有的GC日志。JDK9、JDK10生成的文件与JDK8相同，不再赘述。

文末福利

本文节选自 《实战Java虚拟机———JVM故障诊断与性能优化（第2版）》一书，葛一鸣著，电子工业出版社出版。本书涵盖JDK 7到JDK 10，通过200余示例详解Java虚拟机中各种参数配置、故障排查、性能监控以及性能优化，技术全面，通俗易懂。

本书刚刚上市，第一时间送出5本给到大家。

参与方式：请扫描下方二维码关注我的小号[Java之道]，公众号对话回复：送书，即可参与抽奖。

如果你喜欢本文,

请长按二维码，关注 Hollis.

转发至朋友圈，是对我最大的支持。