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();
	}
}
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)
[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]
[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
-verbose:gc -Xloggc:/usr/gclog -XX:+PrintGCDetails XX:+PrintGCTimeStamps

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





转载于: