GC log 解读

gc log 是 java 程序在出现内存问题时候最好的查看问题的有利日志。下面我们来一步一步分析 gc log。

首先，默认 java 程序是不会开启 gc log，我们可以在给 jvm 参数加上-XX:+PrintGCDetails （这个只是我们在本地调试使用，在生成环境下不可使用。

下面我们可以模拟一个程序，来查看日志。

public class GcLog {
	static final int MB = 1024 * 1024;
	static void printGC() {

		byte[] b1, b2, b3, b4;
		b1 = new byte[MB];
		b2 = new byte[MB];
		b3 = new byte[MB];
		b4 = new byte[2*MB];
	}
	public static void main(String[] args) {
		// TODO Auto-generated method stub
		printGC();
	}
}

可以给可以 jvm 加上如下的启动参数:-Xmx10M -Xms10M -Xmn6M -XX:+PrintGCDetails -XX:SurvivorRatio=7

从代码，可以看到 jvm 分配的内存大小一共为 10M,其中老变态 4M，年轻态 6M，同时针对年轻态 eden 和 Survivor 共享 6M，分配的比例为 7:1:1，其中 eden 大小为 4.6M，Survivor 的两个区域各自为 0.6M

这里我们默认采用 CMS 垃圾回收,下面我们运行程序，会看到如下的日志

[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), 0.0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 def new generation   total 5504K, used 2391K [0x33e60000, 0x34460000, 0x34460000)
  eden space 4864K,  46% used [0x33e60000, 0x34090b28, 0x34320000)
  from space 640K,  23% used [0x343c0000, 0x343e5418, 0x34460000)
  to   space 640K,   0% used [0x34320000, 0x34320000, 0x343c0000)
 tenured generation   total 4096K, used 3072K [0x34460000, 0x34860000, 0x34860000)
   the space 4096K,  75% used [0x34460000, 0x34760030, 0x34760200, 0x34860000)
 compacting perm gen  total 12288K, used 376K [0x34860000, 0x35460000, 0x38860000)
   the space 12288K,   3% used [0x34860000, 0x348be298, 0x348be400, 0x35460000)
    ro space 10240K,  55% used [0x38860000, 0x38de3320, 0x38de3400, 0x39260000)
    rw space 12288K,  55% used [0x39260000, 0x39906128, 0x39906200, 0x39e60000)

下面来从程序的角度分析日志的。

程序中按照顺序申请了 1M-->1M--->1M--->2M 的内存

当第一次申请 1M 的时候，新生态空间足够直接放入

当第二次申请 1M 的时候，新生态空间依然足够，直接放入

当第三次申请 1M 的时候，新生态空间依然足够，直接放入

当第四次申请 1M 的时候，新生态空间不足开始 GC，而此时有 3 个 1M 的对象，而 Survivor 区域不满 1M，所以直接进入老年态，这是原来的 3 个 1M 对象进入老年态，2M 的对象进入 eden

[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), 0.0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

看一下这行：

DefNew 表示新生态:3298K->149K(5504K), 0.0053498 secs

表示新生态由 3298K 回收变成了 149K，即之前的 3M 回收了，5504K 表示该区域的总内存大小

3298K->3221K(9600K), 0.0053750 secs] 表示整个 jvm 堆的大小由于没有可以回收的对象，所以总大小本质没发生改变，9600K 是 java 的总堆大小 9600K。(虽然分配 10M，其中还有持久态等其他内存区域)

[Times: user=0.00 sys=0.00, real=0.01 secs] 表示 gc 所花费的系统资源

-------------------------------------------------------------------------------华丽分割线---------------------------------------------------------------------------------------------------------

再来看看这堆详细的信息

Heap
def new generation total 5504K, used 2391K [0x33e60000, 0x34460000, 0x34460000)-------------> 新生态的大小，total，used
eden space 4864K, 46% used [0x33e60000, 0x34090b28, 0x34320000)
from space 640K, 23% used [0x343c0000, 0x343e5418, 0x34460000)-------------> 本例中由于该区域很小，无法放入对象，所以其实没使用到。
to space 640K, 0% used [0x34320000, 0x34320000, 0x343c0000)
tenured generation total 4096K, used 3072K [0x34460000, 0x34860000, 0x34860000)-------------> 老年态
the space 4096K, 75% used [0x34460000, 0x34760030, 0x34760200, 0x34860000)
compacting perm gen total 12288K, used 376K [0x34860000, 0x35460000, 0x38860000)-------------> 由于老年态共 4M，已经放入 3M 了，所以开启了压缩。
the space 12288K, 3% used [0x34860000, 0x348be298, 0x348be400, 0x35460000)
ro space 10240K, 55% used [0x38860000, 0x38de3320, 0x38de3400, 0x39260000)
rw space 12288K, 55% used [0x39260000, 0x39906128, 0x39906200, 0x39e60000)

对于生成环境下的 java 程序可以加上来生成 gc log，方便出现问题的时候去排查

-verbose:gc -Xloggc:/usr/gclog -XX:+PrintGCDetails XX:+PrintGCTimeStamps

暂时先到这边，jvm 内存模型这里就不多说了，后续我会写一些 jvm 优化已经在线调试线上系统的工具。