奇怪的GC (Allocation Failure)日志

今天在玩JVM的GC日志时,遇到了一个奇怪的现象。目前的知识还没找到原因,先记录下。找到原因有再补充~。

环境是:JDK8

1. 先上构造场景的代码。

/**
 * @Auther: jx
 * @Date: 2018/7/28 16:37
 * @Description: GC测试2
 * -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */
public class TestGC2 {
    private static final int _1MB = 1024 * 1024;
    public static void main(String[] args) {
        test();
    }

    private static void test() {
        byte[] a1, a2, a3, a4;
        a1= new byte[2*_1MB];
        a2= new byte[2*_1MB];
        a3= new byte[2*_1MB];
        a4= new byte[4*_1MB];
    }
}

代码比较简单,创建4个数组对象空间。

2. JVM 配置

2.1配置内容
VM配置信息
-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC
2.2 配置说明
配置 说明
-verbose:gc 显示GC的情况
-Xms20M 设置堆初始大小20M
-Xmx20M 设置堆最大大小20M
-Xmn10M 设置堆中 new Generation 新生代的大小为10M
-XX:+PrintGCDetails 输出GC的详细日志
-XX:ServivorRatio=8 设置 New Generation新生代中的 Eden区与Servivor区比例是8:1
-XX:+UseSerialGC 设置GC回收器模式是串型垃圾回收器
2.3 配置结果

这里需要对配置后,进行说明Java堆中各个区域的空间情况。如下:

  • Java堆,共有 20M
  • 新生代,有10M
    • Eden区,8M
    • Servivor From ,1M
    • Servior To ,1M
  • 老年代,有10M

堆内存模型如下:


内存模型

3. 推导内存分配

  • a1,a2, a3 分配时
    因为分配a1,a2,a3大小为2M,Eden区的大小够a1,a2,a3申请。申请后的内存情况如下:

    a1,a2,a3申请空间后的情况

    黄色代表已使用,空着代表未使用。

    • a4 申请分配时
      这里详细步骤如下。
      • ① 因为a4需要申请4M空间,但现在Eden区只有2M Free的空间
      • ② From区还有1M空间,也无法满足 a4的申请。
      • ③ 故此需要执行一次MinorGC才能够给 Allocation分配 a4的4M空间.
      • ④ MinorGC 开始执行,首先会开始处理a1,a2,a3的空间。
      • ⑤ 因为a1,a2,a3有2M的空间,同时大于From区 1M的空间。
      • ⑥ 故此,会将a1,a2,a3移到Tenured老年代区域。
        执行后的内存空间模型如下:


        Minor GC执行后

4. 推导GC日志

通过上面的内存模型分析,推测GC日志可能如下:

[GC (Allocation Failure) [DefNew: 6144K->0K(9216K), 0.0040708 secs] 0K->0K(19456K), 0.0041138 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 9216K, used 4456K [0, 4, 9)
  eden space 8192K,  50% used [0, 4, 8)
  from space 1024K,   0% used [0, 1, 1)
  to   space 1024K,   0% used [0, 0, 0)
 tenured generation   total 10240K, used 6144K [0, 6, 10)
   the space 10240K,  60% used [0, 6, 6, 10)
 Metaspace       used 224K, capacity 2280K, committed 2368K, reserved 4480K

解释说明:

  • 1.GC信息
    [GC (Allocation Failure) [DefNew: 6144K->0K(9216K), 0.0040708 secs] 0K->0K(19456K), 0.0041138 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
    一次分配失败GC,处理新生代从6144K到0 k空间(新生代共9216K空间),堆 共19456K空间)
    1. GC结束后 + a4申请完后的,堆信息-新生代。
      def new generation total 9216K, used 4456K [0, 4, 9)
      新生代共9216k,使用了4456K。(4456K是a4使用的)
      1. 新生代中的eden区、from区、to区的堆信息
eden space 8192K,  50% used [0, 4, 8)
# eden区空间共8192K,使用50%。
  from space 1024K,   0% used [0, 1, 1)
# from区空间共1024K,使用0%
  to   space 1024K,   0% used [0, 0, 0)
# to 区空间共1024K,使用0%
    1. 元空间信息
 Metaspace       used 224K, capacity 2280K, committed 2368K, reserved 4480K

5. 实际GC日志

实际情况却让我有点不明白,先看结果。

[GC (Allocation Failure) [DefNew: 7177K->1024K(9216K), 0.0040750 secs] 7177K->5207K(19456K), 0.0041222 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 7408K [0x05200000, 0x05c00000, 0x05c00000)
  eden space 8192K,  77% used [0x05200000, 0x0583c210, 0x05a00000)
  from space 1024K, 100% used [0x05b00000, 0x05c00000, 0x05c00000)
  to   space 1024K,   0% used [0x05a00000, 0x05a00000, 0x05b00000)
 tenured generation   total 10240K, used 4183K [0x05c00000, 0x06600000, 0x06600000)
   the space 10240K,  40% used [0x05c00000, 0x06015ec0, 0x06016000, 0x06600000)
 Metaspace       used 224K, capacity 2280K, committed 2368K, reserved 4480K
  • 首先,new generation 共9M,使用了7M.
    • eden,共8M,用了77%,大概是6M.
    • from,共1M,用了100%,是1M.
  • Tenuerd Generation 共10M,使用了4M.

看到这个结果,有点懵...有以下几个疑惑:

  • 问题1. a1,a2,a3,a4总共申请的空间是2+2+2+4 =10M。
    而为什么使用 New Generation + Tenuerd Generation = 11M ?哪里多出来了1M?(见鬼了...)
  • 问题2. New Generation 为什么是使用了7M?
    其中,eden区为什么是6M?
    From区又为什么会被使用?而且是使用了全部的1M.
  • 问题3. Tenuerd Generation 为什么只有4M?
初步整理
    1. 空间分配担保?
      空间使用多出来了1M,分析可能是因为【空间分配担保】。可是这块好像挺复杂的,等再详细了解后,进一步写。
    1. Java8?
      原先还在想,因为《深入理解Java虚拟机》的环境是Java7 。是否因环境Java8 导致?但实际测试Java7 一样有此问题。排除了Java8的环境因素。
    1. 不知名隐藏规则?
      应该是还有一些JVM的规则机制没有搞明白。

End...写在最后

    1. 看书很好,但要动手,总能发现不一样的东西。
    1. 问题多了,知识也就多了。
    1. 还需要进一步深入理解...
      《深入理解Java虚拟机》看一遍神书是不够的!!!
  • 最后,等我找答案...
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,590评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 86,808评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,151评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,779评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,773评论 5 367
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,656评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,022评论 3 398
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,678评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 41,038评论 1 299
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,659评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,756评论 1 330
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,411评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,005评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,973评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,053评论 2 350
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,495评论 2 343

推荐阅读更多精彩内容