关于担保分配的日志问题

miroku 2014-03-17
请R大解释一个奇怪的现象
 /** 
     * VM参数:-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:-HandlePromotionFailure 
     */  
    @SuppressWarnings("unused")  
    public static void testHandlePromotion() {  
        byte[] allocation1, allocation2, allocation3, allocation4, allocation5, allocation6, allocation7;  
        allocation1 = new byte[2 * _1MB];  
        allocation2 = new byte[2 * _1MB];  
        allocation3 = new byte[2 * _1MB];  
        allocation1 = null;  
        allocation4 = new byte[2 * _1MB];  
        allocation5 = new byte[2 * _1MB];  
        allocation6 = new byte[2 * _1MB];  
        allocation4 = null;  
        allocation5 = null;  
        allocation6 = null;  
        allocation7 = new byte[2 * _1MB];  
    }  
}  


这里,会触发担保分配失败,日志如下:

[GC [DefNew: 6651K->148K(9216K), 0.0078936 secs] 6651K->4244K(19456K), 0.0079192 secs] [Times: user=0.00 sys=0.02, real=0.02 secs]
[GC [DefNew: 6378K->6378K(9216K), 0.0000206 secs][Tenured: 4096K->4244K(10240K), 0.0042901 secs] 10474K->4244K(19456K), [Perm : 2104K->2104K(12288K)], 0.0043613 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]


可以看到,yang 区大小几乎没有变化,而回收后,整个堆减少了大约6m。请问下R大:
1、GC日志打印的时机是什么。
2、如上,为什么DefNew那里内存大小无变化,而整个堆却减少了。

希望R大详细解释。
RednaxelaFX 2014-03-17
JDK版本多少?32还是64位?记得看你的Eclipse项目配置到哪个JDK上了。
看起来是bug了…
miroku 2014-03-17
32位的  jdk6-015
RednaxelaFX 2014-03-17
miroku 写道
32位的  jdk6-015

以后请直接复制java -version的输出发出来。
您说的是Sun JDK 1.6.0 update 15而不是OpenJDK 6 build 15对吧?后者正好不存在所以可以猜。
回头跑下你的代码试试看。
miroku 2014-03-17
是的  是Sun JDK 1.6.0 update 15   因为这个现象不是自己机器上出现的,所以没有复制  java -version
RednaxelaFX 2014-03-17
miroku 写道
是的  是Sun JDK 1.6.0 update 15   因为这个现象不是自己机器上出现的,所以没有复制  java -version

嗯嗯,我知道原本问题是谁问的了。刚下好那个对应版本的JDK来验证一下现象。
miroku 2014-03-17
既然R大在,就2案并查吧
public class BubbleSort {
	
	public int[] sort(int[] a) {
		long icount=0;
		for (int i = 0; i < a.length; i++) {
			for (int j = 0; j < a.length; ++j) {//两个代码就是这里有不同
				if (a[i] > a[j]) {
					int temp = a[i];
					a[i] = a[j];
					a[j] = temp;
					icount++;
				}
			}
		}
		System.out.println("执行交换次数:"+icount);
		return a;
	}
	
	public int[] sort2(int[] a) {
		long icount=0;
		for (int i = 0; i < a.length; i++) {
			for (int j = i; j < a.length; ++j) {//两个代码就是这里有不同
				if (a[i] > a[j]) {
					int temp = a[i];
					a[i] = a[j];
					a[j] = temp;
					icount++;
				}
			}
		}
		System.out.println("执行交换次数:"+icount);
		return a;
	}
	
	public static void main(String[] args) {
		int i[]=new int[100000];
		int icopy[]=new int[100000];
		Random r=new Random(System.currentTimeMillis());
		for (int j = 0; j < 100000; j++) {
			int temp=(int)(r.nextInt());
			i[j]=temp;
			icopy[j]=temp;
		}
		BubbleSort bubble=new BubbleSort();
		long start1=System.currentTimeMillis();
		bubble.sort(i);
		long stop1=System.currentTimeMillis();
		System.out.println(stop1-start1);
		
		long start2=System.currentTimeMillis();
		bubble.sort2(icopy);
		long stop2=System.currentTimeMillis();
		System.out.println(stop2-start2);
	}

}

本来是写个排序的但是第一段sort方法是不小心写错了的,最后排过序以后是从大的小,后面的sort2是从小到大,其实这个都 不是什么问题,问题是两段代码执行效率相差一倍,其实代码不同的地方就一个不同一个是for (int j = 0; j < a.length; ++j) 另外一个是for (int j = i; j < a.length; ++j)照理来说应该是 sort2方法的(int j = i; j < a.length; ++j)还少执行几次,现在反而效率要低很多,现在代码里面执行的数组元素交换次数也打印了,且相差不错,不知道在哪里有效率的问题,居然能相差如此之多的效率?

我的JDK版本
java version "1.7.0_07"
Java(TM) SE Runtime Environment (build 1.7.0_07-b10)
Java HotSpot(TM) 64-Bit Server VM (build 23.3-b01, mixed mode)
miroku 2014-03-17
据猜测,是cache line miss导致但是无法证实
RednaxelaFX 2014-03-18
RednaxelaFX 写道
miroku 写道
是的  是Sun JDK 1.6.0 update 15   因为这个现象不是自己机器上出现的,所以没有复制  java -version

嗯嗯,我知道原本问题是谁问的了。刚下好那个对应版本的JDK来验证一下现象。

毫无疑问楼主观察到的现象是个bug。
因为实现上有问题,-XX:-HandlePromotionFailure 参数在JDK 6 update 24开始已经不再支持了。
JDK-6896603: CMS/GCH: collection_attempt_is_safe() ergo should use more recent data
Summary: Deprecated HandlePromotionFailure, removing the ability to turn off that feature, did away with one epoch look-ahead when deciding if a scavenge is likely to fail, relying on current data.
http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/a7214d79fcf1

所以说要问JVM的某些奇怪行为的问题的话,指出非常具体的版本、环境信息很重要。
miroku 2014-03-18
多谢R大,不知道R大有时间帮忙看看这个 jvm crash日志么,关键部分如下:

Heap
PSYoungGen      total 246464K, used 246428K [0x00000000f0000000, 0x0000000100000000, 0x0000000100000000)
  eden space 240640K, 100% used [0x00000000f0000000,0x00000000feb00000,0x00000000feb00000)
  from space 5824K, 99% used [0x00000000feb00000,0x00000000ff0a7070,0x00000000ff0b0000)
  to   space 10944K, 83% used [0x00000000ff550000,0x00000000ffe3f748,0x0000000100000000)
PSOldGen        total 262144K, used 110250K [0x00000000e0000000, 0x00000000f0000000, 0x00000000f0000000)
  object space 262144K, 42% used [0x00000000e0000000,0x00000000e6baa838,0x00000000f0000000)
PSPermGen       total 262144K, used 127293K [0x00000000d0000000, 0x00000000e0000000, 0x00000000e0000000)
  object space 262144K, 48% used [0x00000000d0000000,0x00000000d7c4f600,0x00000000e0000000)

在to区竟然会有占用,我的记忆中to区是应该为0啊?

Global site tag (gtag.js) - Google Analytics