GC日志分析
程序代码：
1 public class JvmTest { 2 public static void main(String[] args) { 3 4 int m = 1024 * 1024; 5 byte[] b = new byte[2 * m]; 6 System.out.println("allocate 2M"); 7 8 byte[] b1 = new byte[2 * m]; 9 System.out.println("allocate 2M"); 10 11 byte[] b2 = new byte[2 * m]; 12 System.out.println("allocate 2M"); 13 14 byte[] b3 = new byte[2 * m]; 15 System.out.println("allocate 2M"); 16 17 byte[] b4 = new byte[2 * m]; 18 System.out.println("allocate 2M"); 19 20 byte[] b5 = new byte[2 * m]; 21 System.out.println("allocate 2M"); 22 23 byte[] b6 = new byte[2 * m]; 24 System.out.println("allocate 2M"); 25 } 26 }
一、串行GC
1、执行命令如下
java -Xms20m -Xmx20m -Xmn10m -XX:+UseSerialGC -XX:+PrintGCDetails JvmTest
2、GC日志如下：
allocate 2M allocate 2M allocate 2M [GC[DefNew: 6831K->231K(9216K), 0.0064660 secs] 6831K->6375K(19456K), 0.0065000 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] allocate 2M allocate 2M allocate 2M [GC[DefNew: 6547K->6547K(9216K), 0.0000150 secs][Tenured: 6144K->8192K(10240K), 0.0086010 secs] 12691K->12516K(19456K), [Perm : 2585K->2585K(21248K)], 0.0086580 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] allocate 2M Heap def new generation total 9216K, used 6509K [0x00000007f9a00000, 0x00000007fa400000, 0x00000007fa400000) eden space 8192K, 79% used [0x00000007f9a00000, 0x00000007fa05b770, 0x00000007fa200000) from space 1024K, 0% used [0x00000007fa300000, 0x00000007fa300000, 0x00000007fa400000) to space 1024K, 0% used [0x00000007fa200000, 0x00000007fa200000, 0x00000007fa300000) tenured generation total 10240K, used 8192K [0x00000007fa400000, 0x00000007fae00000, 0x00000007fae00000) the space 10240K, 80% used [0x00000007fa400000, 0x00000007fac000c8, 0x00000007fac00200, 0x00000007fae00000) compacting perm gen total 21248K, used 2592K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000) the space 21248K, 12% used [0x00000007fae00000, 0x00000007fb088230, 0x00000007fb088400, 0x00000007fc2c0000) No shared spaces configured.
如上显示首先分配了6M内存后，进行了一次YGC；然后再分配6M内存后进行了一次整个堆的GC。
上面蓝色字体展示的是第一次YGC的日志，其中 6831K->231K(9216K) 表示年青代的区域大小由6831K较少到231K，即回收了6831-231 = 6600K，9216K表示了年青代占用区域的大小（因为启动参数设置为-Xmn10m，即年青代大小为10M，默认eden和survivor的比例为8:1，所以eden区域为8M，每个survivor区域为1M）。整个堆的大小由6831K减少到6375K，即回收了6831-6375 = 456K。19456K代表了整个年老代、Eden区和一个survivor区域。本次回收共计使用了0.0065000秒。最后一段中user表示YGC用户耗时，sys表示系统耗时，real表示实际耗时。
下面暗红色的字体展示了整个堆GC，一次YGC和一次PermGC。YGC日志同上。此处Tenured内存没有减少，是因为年青代GC后再分配2M内存，此时年青代中的eden区域为6547K，而eden总大小为8*1024=8192K，如果再分配2M，即6547K+2048K=8595K > 8192K，因此不能在年青代分配内存，只能在年老代分配内存，因此年老大由6144K+2048K=8192K。此时Perm也进行了一次GC，但是没有内存减少。
二、并行GC
A:UseparallelGC
1、执行命令如下：
java -Xms20m -Xmx20m -Xmn10m -XX:+UseParallelGC -XX:+PrintGCDetails JvmTest
2、GC日志如下
allocate 2M allocate 2M allocate 2M [GC [PSYoungGen: 6831K->352K(9216K)] 6831K->6496K(19456K), 0.0072050 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] [Full GC [PSYoungGen: 352K->0K(9216K)] [ParOldGen: 6144K->6373K(10240K)] 6496K->6373K(19456K) [PSPermGen: 2585K->2584K(21504K)], 0.0129170 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] allocate 2M allocate 2M allocate 2M [Full GC [PSYoungGen: 6315K->4096K(9216K)] [ParOldGen: 6373K->8420K(10240K)] 12689K->12516K(19456K) [PSPermGen: 2584K->2584K(21504K)], 0.0101690 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] allocate 2M Heap PSYoungGen total 9216K, used 6281K [0x00000007ff600000, 0x0000000800000000, 0x0000000800000000) eden space 8192K, 76% used [0x00000007ff600000,0x00000007ffc22660,0x00000007ffe00000) from space 1024K, 0% used [0x00000007ffe00000,0x00000007ffe00000,0x00000007fff00000) to space 1024K, 0% used [0x00000007fff00000,0x00000007fff00000,0x0000000800000000) ParOldGen total 10240K, used 8420K [0x00000007fec00000, 0x00000007ff600000, 0x00000007ff600000) object space 10240K, 82% used [0x00000007fec00000,0x00000007ff4391d8,0x00000007ff600000) PSPermGen total 21504K, used 2591K [0x00000007f9a00000, 0x00000007faf00000, 0x00000007fec00000) object space 21504K, 12% used [0x00000007f9a00000,0x00000007f9c87e60,0x00000007faf00000)
如上GC日志所示，JVM进行了3次GC，一次YGC和两次FGC。YGC的日志分析同SerialGC。
第一次FGC，年青代的大小由352K减少到了0K，因此回收了352K。而年老代由6144K变为6373K，增加了229K(是否为从年青代晋升的对象呢？)。整个堆的大小从6496K减少到6373K，共计回收了6494K-6373K=121K。 Perm区域大小由2585K减少到2584K，共计回收了1K。
第二次FGC，年青代的大小由6315K减少到4096K，回收了6315K-4096K=2219K。年老代由6373K增加到8420K，增加了2047K，整个堆的大小由12689K减少到12516K，共计回收了12689K-12516K=173K。Perm区域的大小无变化。
B、UseParallelOldGC
日志同parallelGC。
UseParallelGC和UseParallelOldGC唯一的不同为：
-XX:+UseParallelGC用在年青代多线程，年老代单线程，-XX:+UseParallelOldGC用在年青代和年老代都是多线程。
三、CMS GC
1、命令如下：
java -Xms20m -Xmx20m -Xmn10m -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails JvmTest
2、日志如下：
[GC[ParNew: 6831K->257K(9216K), 0.0078490 secs] 6831K->6403K(19456K), 0.0079190 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] [GC[ParNew: 6573K->6573K(9216K), 0.0000550 secs][CMS: 6146K->8192K(10240K), 0.0139330 secs] 12719K->12517K(19456K), [CMS Perm : 2588K->2587K(21248K)], 0.0140560 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] [GC [1 CMS-initial-mark: 8192K(10240K)] 14565K(19456K), 0.0004510 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC[YG occupancy: 7510 K (9216 K)][Rescan (parallel) , 0.0004280 secs][weak refs processing, 0.0000140 secs][scrub string table, 0.0001790 secs] [1 CMS-remark: 9216K(10240K)] 16726K(19456K), 0.0006900 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC[ParNew: 7510K->7510K(9216K), 0.0000300 secs][CMS: 9216K->9216K(10240K), 0.0088070 secs] 16726K->16615K(19456K), [CMS Perm : 2619K->2619K(21248K)], 0.0089500 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [Full GC[CMS: 9216K->9216K(10240K), 0.0062390 secs] 16615K->16603K(19456K), [CMS Perm : 2619K->2619K(21248K)], 0.0062830 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
CMS GC的日志多了CMS各个阶段的标识，日志的内容和串行及并行无大区别。
