0
点赞
收藏
分享

微信扫一扫

38 一次 younggc fullgc 的调试

8052cf60ff5c 03-13 17:15 阅读 1


前言

最近 有一个想法就是, 调试一下 DefNewGeneration 里面的晋升失败的情况 

呵呵 因此写了一个测试用例来调试这个场景, 但是 和我最开始的想法 差的有点远, 不过 还是有很大的收货, 这块的代码 虽然调试了很多次了, 但是 对于细节的把控 还是差的很多 

比如 这次的这个测试用例, 就和我心中的期望 差距很大  

以下代码, 截图 基于 jdk9 

测试代码

package com.hx.test07;

import org.openjdk.jol.vm.VM;
import org.openjdk.jol.vm.VirtualMachine;

import java.lang.management.ManagementFactory;
import java.lang.management.MemoryPoolMXBean;
import java.util.List;

/**
 * PromitionFailed
 *
 * @author Jerry.X.He 
 * @version 1.0
 * @date 2020-08-09 14:40
 */
public class Test30PromotionFailed {

  // Test30PromotionFailed
  // -Xmx32M -XX:+UseSerialGC -XX:NewRatio=1 -XX:MaxTenuringThreshold=2 -XX:+PrintGCDetails -cp .:/Users/jerry/.m2/repository/org/openjdk/jol/jol-core/0.8/jol-core-0.8.jar com.hx.test07.Test30PromotionFailed
  // young : 13 + 1.5 + 1.5, old : 16
  public static void main(String[] args) throws Exception {

    VirtualMachine vm = VM.current();
    int _1M = 1 * 1024 * 1204;

    byte[] alreadyInOld = new byte[7 * _1M];
    // young
    System.out.println(vm.addressOf(alreadyInOld));
    touchMinorGc();
    touchMinorGc();
    // old
    System.out.println(vm.addressOf(alreadyInOld));
    System.out.println(" ------------ alreadyInOld ------------ ");

    byte[] promotionToOld01 = new byte[3 * _1M];
    byte[] promotionToOld02 = new byte[3 * _1M];
    // young
    System.out.println(vm.addressOf(promotionToOld01));
    // young
    System.out.println(vm.addressOf(promotionToOld02));
    touchMinorGc();
    touchMinorGc();
    // old
    System.out.println(vm.addressOf(promotionToOld01));
    // young
    System.out.println(vm.addressOf(promotionToOld02));
    System.out.println(" ------------ promotionToOldXX ------------ ");

    byte[] allocatedInYoung = new byte[7 * _1M];
    byte[] allocatedInOld = new byte[(int) (1.6 * _1M)];

    // young
    System.out.println(vm.addressOf(allocatedInYoung));
    // old
    System.out.println(vm.addressOf(allocatedInOld));
    System.out.println(" ------------ allocatedInXXX ------------ ");

  }

  /**
   * touchMinorGc
   *
   * @return void
   * @author Jerry.X.He<9 7 0 6 5 5 1 4 7 @ qq.com>
   * @date 2020-05-02 21:20
   */
  public static void touchMinorGc() throws Exception {
    int _1M = 1 * 1024 * 1024;
    MemoryPoolMXBean eden = getMemoryInfo("Eden Space");
    long used = eden.getUsage().getUsed();
    long max = eden.getUsage().getMax();

    int loopByM = (int) ((max - used) / _1M) + 1;
    System.out.println(String.format("max : %sM, used : %sM, touchMinorGc created %s byte[1M] ", (max / _1M), (used / _1M), loopByM));
    for (int i = 0; i < loopByM; i++) {
      byte[] bytes = new byte[_1M];
    }
  }

  /**
   * 获取 给定的模块的内存信息
   *
   * @param name name
   * @return java.lang.management.MemoryPoolMXBean
   * @author Jerry.X.He
   * @date 2020-08-16 10:15
   */
  public static MemoryPoolMXBean getMemoryInfo(String name) {
    List<MemoryPoolMXBean> mxbs = ManagementFactory.getMemoryPoolMXBeans();
    for (MemoryPoolMXBean mxb : mxbs) {
      if (mxb.getName().equals(name)) {
        return mxb;
      }
    }
    return null;
  }

}

执行结果如下 

[0.018s][warning][gc] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead.
Signal: SIGSEGV (signal SIGSEGV)
Signal: SIGSEGV (signal SIGSEGV)
[5.136s][info   ][gc] Using Serial
[5.136s][info   ][gc,heap,coops] Heap address: 0x00000007be000000, size: 32 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
Signal: SIGSEGV (signal SIGSEGV)
Signal: SIGSEGV (signal SIGSEGV)
# WARNING: Unable to get Instrumentation. Dynamic Attach failed: null. You may add this JAR as -javaagent manually.
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.openjdk.jol.vm.sa.ServiceabilityAgentSupport (file:/Users/jerry/.m2/repository/org/openjdk/jol/jol-core/0.8/jol-core-0.8.jar) to field sun.management.RuntimeImpl.jvm
WARNING: Please consider reporting this to the maintainers of org.openjdk.jol.vm.sa.ServiceabilityAgentSupport
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
# WARNING: Unable to attach Serviceability Agent. You can try again with escalated privileges. Two options: a) use -Djol.tryWithSudo=true to try with sudo; b) echo 0 | sudo tee /proc/sys/kernel/yama/ptrace_scope
[16.481s][info   ][gc,start     ] GC(0) Pause Young (Allocation Failure)
[17.965s][info   ][gc,heap      ] GC(0) DefNew: 13184K->1600K(14784K)
[17.965s][info   ][gc,heap      ] GC(0) Tenured: 0K->467K(16384K)
[17.965s][info   ][gc,metaspace ] GC(0) Metaspace: 11261K->11261K(1060864K)
[17.965s][info   ][gc           ] GC(0) Pause Young (Allocation Failure) 12M->2M(30M) 1484.081ms
[17.965s][info   ][gc,cpu       ] GC(0) User=0.07s Sys=0.00s Real=1.49s
33253872248
max : 12M, used : 9M, touchMinorGc created 4 byte[1M] 
[18.283s][info   ][gc,start     ] GC(1) Pause Young (Allocation Failure)
[19.535s][info   ][gc,heap      ] GC(1) DefNew: 14749K->391K(14784K)
[19.535s][info   ][gc,heap      ] GC(1) Tenured: 467K->10478K(16384K)
[19.535s][info   ][gc,metaspace ] GC(1) Metaspace: 12029K->12029K(1060864K)
[19.535s][info   ][gc           ] GC(1) Pause Young (Allocation Failure) 14M->10M(30M) 1252.055ms
[19.535s][info   ][gc,cpu       ] GC(1) User=0.09s Sys=0.00s Real=1.26s
max : 12M, used : 1M, touchMinorGc created 12 byte[1M] 
[19.539s][info   ][gc,start     ] GC(2) Pause Young (Allocation Failure)
[20.281s][info   ][gc,start     ] GC(3) Pause Full (Allocation Failure)
[20.282s][info   ][gc,phases,start] GC(3) Phase 1: Mark live objects
[20.408s][info   ][gc,phases      ] GC(3) Phase 1: Mark live objects 125.934ms
[20.408s][info   ][gc,phases,start] GC(3) Phase 2: Compute new object addresses
[20.422s][info   ][gc,phases      ] GC(3) Phase 2: Compute new object addresses 13.798ms
[20.422s][info   ][gc,phases,start] GC(3) Phase 3: Adjust pointers
[20.477s][info   ][gc,phases      ] GC(3) Phase 3: Adjust pointers 54.699ms
[20.477s][info   ][gc,phases,start] GC(3) Phase 4: Move objects
[20.486s][info   ][gc,phases      ] GC(3) Phase 4: Move objects 9.085ms
[20.516s][info   ][gc             ] GC(3) Pause Full (Allocation Failure) 22M->10M(30M) 235.137ms
[20.516s][info   ][gc,heap        ] GC(2) DefNew: 12934K->0K(14784K)
[20.516s][info   ][gc,heap        ] GC(2) Tenured: 10478K->10850K(16384K)
[20.516s][info   ][gc,metaspace   ] GC(2) Metaspace: 12029K->12029K(1060864K)
[20.518s][info   ][gc             ] GC(2) Pause Young (Allocation Failure) 22M->10M(30M) 978.757ms
[20.518s][info   ][gc,cpu         ] GC(2) User=0.23s Sys=0.00s Real=0.98s
33270015464
 ------------ alreadyInOld ------------ 
33253753264
33257451968
max : 12M, used : 8M, touchMinorGc created 5 byte[1M] 
[20.524s][info   ][gc,start       ] GC(4) Pause Young (Allocation Failure)
[23.637s][info   ][gc,start       ] GC(5) Pause Full (Allocation Failure)
[23.640s][info   ][gc,phases,start] GC(5) Phase 1: Mark live objects
[23.746s][info   ][gc,phases      ] GC(5) Phase 1: Mark live objects 106.201ms
[23.746s][info   ][gc,phases,start] GC(5) Phase 2: Compute new object addresses
[23.758s][info   ][gc,phases      ] GC(5) Phase 2: Compute new object addresses 12.103ms
[23.758s][info   ][gc,phases,start] GC(5) Phase 3: Adjust pointers
[23.809s][info   ][gc,phases      ] GC(5) Phase 3: Adjust pointers 50.188ms
[23.809s][info   ][gc,phases,start] GC(5) Phase 4: Move objects
[23.817s][info   ][gc,phases      ] GC(5) Phase 4: Move objects 8.673ms
[23.842s][info   ][gc             ] GC(5) Pause Full (Allocation Failure) 22M->17M(30M) 204.634ms
[23.842s][info   ][gc,heap        ] GC(4) DefNew: 12600K->3612K(14784K)
[23.842s][info   ][gc,heap        ] GC(4) Tenured: 10850K->14462K(16384K)
[23.842s][info   ][gc,metaspace   ] GC(4) Metaspace: 12029K->12029K(1060864K)
[23.843s][info   ][gc             ] GC(4) Pause Young (Allocation Failure) 22M->17M(30M) 3318.487ms
[23.843s][info   ][gc,cpu         ] GC(4) User=0.20s Sys=0.00s Real=3.31s
max : 12M, used : 4M, touchMinorGc created 9 byte[1M] 
33280330152
33252442112
 ------------ promotionToOldXX ------------ 
[23.855s][info   ][gc,start       ] GC(6) Pause Full (Allocation Failure)
[23.856s][info   ][gc,phases,start] GC(6) Phase 1: Mark live objects
[23.971s][info   ][gc,phases      ] GC(6) Phase 1: Mark live objects 114.603ms
[23.971s][info   ][gc,phases,start] GC(6) Phase 2: Compute new object addresses
[23.985s][info   ][gc,phases      ] GC(6) Phase 2: Compute new object addresses 13.631ms
[23.985s][info   ][gc,phases,start] GC(6) Phase 3: Adjust pointers
[24.033s][info   ][gc,phases      ] GC(6) Phase 3: Adjust pointers 48.121ms
[24.033s][info   ][gc,phases,start] GC(6) Phase 4: Move objects
[24.040s][info   ][gc,phases      ] GC(6) Phase 4: Move objects 7.080ms
[24.066s][info   ][gc,heap        ] GC(6) DefNew: 14109K->3612K(14784K)
[24.066s][info   ][gc,heap        ] GC(6) Tenured: 14462K->14462K(16384K)
[24.066s][info   ][gc,metaspace   ] GC(6) Metaspace: 12029K->12029K(1060864K)
[24.070s][info   ][gc             ] GC(6) Pause Full (Allocation Failure) 27M->17M(30M) 215.309ms
[24.070s][info   ][gc,cpu         ] GC(6) User=0.22s Sys=0.01s Real=0.21s
[24.072s][info   ][gc,start       ] GC(7) Pause Full (Allocation Failure)
[24.072s][info   ][gc,phases,start] GC(7) Phase 1: Mark live objects
[24.170s][info   ][gc,phases      ] GC(7) Phase 1: Mark live objects 97.441ms
[24.170s][info   ][gc,phases,start] GC(7) Phase 2: Compute new object addresses
[24.180s][info   ][gc,phases      ] GC(7) Phase 2: Compute new object addresses 10.502ms
[24.180s][info   ][gc,phases,start] GC(7) Phase 3: Adjust pointers
[24.232s][info   ][gc,phases      ] GC(7) Phase 3: Adjust pointers 52.238ms
[24.232s][info   ][gc,phases,start] GC(7) Phase 4: Move objects
[24.243s][info   ][gc,phases      ] GC(7) Phase 4: Move objects 10.908ms
[24.269s][info   ][gc,heap        ] GC(7) DefNew: 12040K->12040K(14784K)
[24.269s][info   ][gc,heap        ] GC(7) Tenured: 14462K->14123K(16384K)
[24.269s][info   ][gc,metaspace   ] GC(7) Metaspace: 11916K->11916K(1060864K)
[24.270s][info   ][gc             ] GC(7) Pause Full (Allocation Failure) 25M->25M(30M) 197.628ms
[24.270s][info   ][gc,cpu         ] GC(7) User=0.20s Sys=0.00s Real=0.20s
33256140904
33283682056
 ------------ allocatedInXXX ------------ 
[24.278s][info   ][gc,heap,exit   ] Heap
[24.278s][info   ][gc,heap,exit   ]  def new generation   total 14784K, used 12893K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
[24.278s][info   ][gc,heap,exit   ]   eden space 13184K,  97% used [0x00000007be000000, 0x00000007bec974b8, 0x00000007bece0000)
[24.278s][info   ][gc,heap,exit   ]   from space 1600K,   0% used [0x00000007bece0000, 0x00000007bece0000, 0x00000007bee70000)
[24.278s][info   ][gc,heap,exit   ]   to   space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
[24.278s][info   ][gc,heap,exit   ]  tenured generation   total 16384K, used 16050K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
[24.278s][info   ][gc,heap,exit   ]    the space 16384K,  97% used [0x00000007bf000000, 0x00000007bffac8b8, 0x00000007bffaca00, 0x00000007c0000000)
[24.278s][info   ][gc,heap,exit   ]  Metaspace       used 11922K, capacity 12564K, committed 13056K, reserved 1060864K
[24.278s][info   ][gc,heap,exit   ]   class space    used 1271K, capacity 1406K, committed 1536K, reserved 1048576K
[24.284s][info   ][gc,verify,start] Verifying 
[24.418s][info   ][gc,verify      ] Verifying  133.629ms

第一次gc

再分配 alreadyInOld 之前, young 的空间不够了, 触发了一次 young gc 

[16.481s][info   ][gc,start     ] GC(0) Pause Young (Allocation Failure)
[17.965s][info   ][gc,heap      ] GC(0) DefNew: 13184K->1600K(14784K)
[17.965s][info   ][gc,heap      ] GC(0) Tenured: 0K->467K(16384K)
[17.965s][info   ][gc,metaspace ] GC(0) Metaspace: 11261K->11261K(1060864K)
[17.965s][info   ][gc           ] GC(0) Pause Young (Allocation Failure) 12M->2M(30M) 1484.081ms
[17.965s][info   ][gc,cpu       ] GC(0) User=0.07s Sys=0.00s Real=1.49s
33253872248

gc 之前 heap 的详细信息如下 

def new generation   total 14784K, used 13184K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
  eden space 13184K, 100% used [0x00000007be000000, 0x00000007bece0000, 0x00000007bece0000)
  from space 1600K,   0% used [0x00000007bece0000, 0x00000007bece0000, 0x00000007bee70000)
  to   space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
 tenured generation   total 16384K, used 0K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
   the space 16384K,   0% used [0x00000007bf000000, 0x00000007bf000000, 0x00000007bf000200, 0x00000007c0000000)
 Metaspace       used 11320K, capacity 12090K, committed 12160K, reserved 1060864K
  class space    used 1213K, capacity 1379K, committed 1408K, reserved 1048576K

从主线程的情况来看, 是在分配一个 "[Ljava.util.HashMap$Node;" 的时候 young 空间不够了, 触发了一次 young gc

38 一次 younggc fullgc 的调试_System

第二次 gc

这一次 gc 是由 touchMinorGc 触发的 

创建了 alreadyInOld 之后 eden 空间为 9M, 为了触发 young gc, 创建了 4个 1m 的字节数组 

gc 之后 young 约为 400K, old 约为 10M

max : 12M, used : 9M, touchMinorGc created 4 byte[1M] 
[18.283s][info   ][gc,start     ] GC(1) Pause Young (Allocation Failure)
[19.535s][info   ][gc,heap      ] GC(1) DefNew: 14749K->391K(14784K)
[19.535s][info   ][gc,heap      ] GC(1) Tenured: 467K->10478K(16384K)
[19.535s][info   ][gc,metaspace ] GC(1) Metaspace: 12029K->12029K(1060864K)
[19.535s][info   ][gc           ] GC(1) Pause Young (Allocation Failure) 14M->10M(30M) 1252.055ms
[19.535s][info   ][gc,cpu       ] GC(1) User=0.09s Sys=0.00s Real=1.26s

gc 之前 heap 的详细信息如下 

def new generation   total 14784K, used 14748K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
  eden space 13184K,  99% used [0x00000007be000000, 0x00000007becd73f8, 0x00000007bece0000)
  from space 1600K, 100% used [0x00000007bee70000, 0x00000007bf000000, 0x00000007bf000000)
  to   space 1600K,   0% used [0x00000007bece0000, 0x00000007bece0000, 0x00000007bee70000)
 tenured generation   total 16384K, used 466K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
   the space 16384K,   2% used [0x00000007bf000000, 0x00000007bf074af0, 0x00000007bf074c00, 0x00000007c0000000)
 Metaspace       used 12032K, capacity 12844K, committed 13056K, reserved 1060864K
  class space    used 1302K, capacity 1466K, committed 1536K, reserved 1048576K

这一次 gc 之后 alreadyInOld 因为 to 放不下, 因此 放到了 old 里面 

可以看到是在处理 栈帧中的强引用 alreadyInOld 的时候把对象复制到存活区, 由于 to 空间放不下, 因此吧 alreadyInOld 放到了 old 里面 

38 一次 younggc fullgc 的调试_System_02

第三次gc

这一次 gc 是由 touchMinorGc 触发的 

eden 使用约为 1m, 为了触发 young gc, 创建了 12个 1m 的字节数组 

这一次 gc 触发的意义, 我最开始是设想的是 吧 alreadyInOld 升到2级, 放到 old 里面, 然后 上面的这一次 gc 已经把 alreadyInOld 放到 old 里面去了, 虽然这个知识点是知道, 但是 自己所分析的时候细节还是不够阿  

old 不能担保 young 的所有的对象, 因此 触发了一次 full gc 

这一次 gc 最终是吧 young 和 old 的存活对象都放到了 old 里面, old 增加了 400k 左右 

此时 alreadyInOld 还是在 old 里面, 因此可以看到 后面的 old 的地址是 3327 开头的 

gc 之后 young 约为 0K, old 约为 15.6M

max : 12M, used : 1M, touchMinorGc created 12 byte[1M]
[19.539s][info   ][gc,start     ] GC(2) Pause Young (Allocation Failure)
[20.281s][info   ][gc,start     ] GC(3) Pause Full (Allocation Failure)
[20.282s][info   ][gc,phases,start] GC(3) Phase 1: Mark live objects
[20.408s][info   ][gc,phases      ] GC(3) Phase 1: Mark live objects 125.934ms
[20.408s][info   ][gc,phases,start] GC(3) Phase 2: Compute new object addresses
[20.422s][info   ][gc,phases      ] GC(3) Phase 2: Compute new object addresses 13.798ms
[20.422s][info   ][gc,phases,start] GC(3) Phase 3: Adjust pointers
[20.477s][info   ][gc,phases      ] GC(3) Phase 3: Adjust pointers 54.699ms
[20.477s][info   ][gc,phases,start] GC(3) Phase 4: Move objects
[20.486s][info   ][gc,phases      ] GC(3) Phase 4: Move objects 9.085ms
[20.516s][info   ][gc             ] GC(3) Pause Full (Allocation Failure) 22M->10M(30M) 235.137ms
[20.516s][info   ][gc,heap        ] GC(2) DefNew: 12934K->0K(14784K)
[20.516s][info   ][gc,heap        ] GC(2) Tenured: 10478K->10850K(16384K)
[20.516s][info   ][gc,metaspace   ] GC(2) Metaspace: 12029K->12029K(1060864K)
[20.518s][info   ][gc             ] GC(2) Pause Young (Allocation Failure) 22M->10M(30M) 978.757ms
[20.518s][info   ][gc,cpu         ] GC(2) User=0.23s Sys=0.00s Real=0.98s

gc 之前 heap 的详细信息如下 

def new generation   total 14784K, used 13065K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
  eden space 13184K,  96% used [0x00000007be000000, 0x00000007bec607e8, 0x00000007bece0000)
  from space 1600K,  24% used [0x00000007bece0000, 0x00000007bed41fa8, 0x00000007bee70000)
  to   space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
 tenured generation   total 16384K, used 10477K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
   the space 16384K,  63% used [0x00000007bf000000, 0x00000007bfa3b7f0, 0x00000007bfa3b800, 0x00000007c0000000)
 Metaspace       used 12032K, capacity 12844K, committed 13056K, reserved 1060864K
  class space    used 1302K, capacity 1466K, committed 1536K, reserved 1048576K

第四, 五次gc

这一次 gc 是由 touchMinorGc 触发的 

这一次 gc 触发的意义, 我原本是设想 promotionToOld01, promotionToOld02 经历两次 minor gc, 升级到 old, 但是 old 最开始我期望又是剩余空间只能容纳 promotionToOld01 或者 promotionToOld02, 然后 没有考虑到的是, old 不能担保 young 的所有的对象, 因此 触发了一次 full gc 

在此之前, 分配了两个对象 promotionToOld01, promotionToOld02, 地址是 3325 开头的, 都在 young 

分配之后 young 占用 8M, 为了触发 young gc, 创建了 5个 1m 的字节数组 

old 不能担保 young 的所有的对象, 因此 触发了一次 full gc 

可以看到下面的 "max : 12M, used : 4M, touchMinorGc created 9 byte[1M]" 是没有触发 gc 的, 可以猜测的是 touchMinorGc 里面最后 1M 的对象是由 from 来进行分配的 

这次 gc 之后, promotionToOld01 复制到了 old, promotionToOld02 因为 old 空间不够, 因此 还是存放在 young 

33253753264
33257451968
max : 12M, used : 8M, touchMinorGc created 5 byte[1M]
[20.524s][info   ][gc,start       ] GC(4) Pause Young (Allocation Failure)
[23.637s][info   ][gc,start       ] GC(5) Pause Full (Allocation Failure)
[23.640s][info   ][gc,phases,start] GC(5) Phase 1: Mark live objects
[23.746s][info   ][gc,phases      ] GC(5) Phase 1: Mark live objects 106.201ms
[23.746s][info   ][gc,phases,start] GC(5) Phase 2: Compute new object addresses
[23.758s][info   ][gc,phases      ] GC(5) Phase 2: Compute new object addresses 12.103ms
[23.758s][info   ][gc,phases,start] GC(5) Phase 3: Adjust pointers
[23.809s][info   ][gc,phases      ] GC(5) Phase 3: Adjust pointers 50.188ms
[23.809s][info   ][gc,phases,start] GC(5) Phase 4: Move objects
[23.817s][info   ][gc,phases      ] GC(5) Phase 4: Move objects 8.673ms
[23.842s][info   ][gc             ] GC(5) Pause Full (Allocation Failure) 22M->17M(30M) 204.634ms
[23.842s][info   ][gc,heap        ] GC(4) DefNew: 12600K->3612K(14784K)
[23.842s][info   ][gc,heap        ] GC(4) Tenured: 10850K->14462K(16384K)
[23.842s][info   ][gc,metaspace   ] GC(4) Metaspace: 12029K->12029K(1060864K)
[23.843s][info   ][gc             ] GC(4) Pause Young (Allocation Failure) 22M->17M(30M) 3318.487ms
[23.843s][info   ][gc,cpu         ] GC(4) User=0.20s Sys=0.00s Real=3.31s
max : 12M, used : 4M, touchMinorGc created 9 byte[1M]
33280330152
33252442112

gc 之前 heap 的详细信息如下 

def new generation   total 14784K, used 12599K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
  eden space 13184K,  95% used [0x00000007be000000, 0x00000007bec4de40, 0x00000007bece0000)
  from space 1600K,   0% used [0x00000007bece0000, 0x00000007bece0000, 0x00000007bee70000)
  to   space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
 tenured generation   total 16384K, used 10798K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
   the space 16384K,  65% used [0x00000007bf000000, 0x00000007bfa8b8e0, 0x00000007bfa8ba00, 0x00000007c0000000)
 Metaspace       used 11827K, capacity 12344K, committed 13056K, reserved 1060864K
  class space    used 1240K, capacity 1354K, committed 1536K, reserved 1048576K

我们来看一下 promotionToOld01 的处理, 可以看出 promotionToOld01 是会复制到 old(看 cp->space)

计算一下 old 剩余的空间 (0x7c0000000 - 0x7bfe1f768) / 1024 大约是 1922 kb 

38 一次 younggc fullgc 的调试_Real_03

我们再来看一下 promotionToOld02 的处理 

old 里面空间不够了, 因此在 cp->space->forward 里面切换了使用的空间, promotionToOld02 分配到了 young 里面 

38 一次 younggc fullgc 的调试_sed_04

切换 cp->space  

38 一次 younggc fullgc 的调试_sed_05

第六次gc

这一次 是由 allocatedInYoung 的分配触发的 

之所以这一次 gc, 和第七次gc 都是直接触发的 full gc, 是因为 上一次 gc, old 已经不能担保 young 的所有的对象了, 并且 gc 之后 old 确实没有能担保 young 的所有的存活对象(full gc 之后, young 不为空) 

[23.855s][info   ][gc,start       ] GC(6) Pause Full (Allocation Failure)
[23.856s][info   ][gc,phases,start] GC(6) Phase 1: Mark live objects
[23.971s][info   ][gc,phases      ] GC(6) Phase 1: Mark live objects 114.603ms
[23.971s][info   ][gc,phases,start] GC(6) Phase 2: Compute new object addresses
[23.985s][info   ][gc,phases      ] GC(6) Phase 2: Compute new object addresses 13.631ms
[23.985s][info   ][gc,phases,start] GC(6) Phase 3: Adjust pointers
[24.033s][info   ][gc,phases      ] GC(6) Phase 3: Adjust pointers 48.121ms
[24.033s][info   ][gc,phases,start] GC(6) Phase 4: Move objects
[24.040s][info   ][gc,phases      ] GC(6) Phase 4: Move objects 7.080ms
[24.066s][info   ][gc,heap        ] GC(6) DefNew: 14109K->3612K(14784K)
[24.066s][info   ][gc,heap        ] GC(6) Tenured: 14462K->14462K(16384K)
[24.066s][info   ][gc,metaspace   ] GC(6) Metaspace: 12029K->12029K(1060864K)
[24.070s][info   ][gc             ] GC(6) Pause Full (Allocation Failure) 27M->17M(30M) 215.309ms
[24.070s][info   ][gc,cpu         ] GC(6) User=0.22s Sys=0.01s Real=0.21s

查看一下 主线程的栈帧信息, 发现是 分配 7 * 1M 的数组(allocatedInYoung) 触发的 gc 

38 一次 younggc fullgc 的调试_System_06

gc 之前 heap 的详细信息如下, 可以看到 from 的空间占用情况, 1600 * 64% = 1M, 刚好是 1M 

因此 上面 "max : 12M, used : 4M, touchMinorGc created 9 byte[1M]" 没有触发 gc 是因为 最后 1M 的空间由 from 来承担了 

def new generation   total 14784K, used 14109K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
  eden space 13184K,  99% used [0x00000007be000000, 0x00000007becc7548, 0x00000007bece0000)
  from space 1600K,  64% used [0x00000007bece0000, 0x00000007bede0010, 0x00000007bee70000)
  to   space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
 tenured generation   total 16384K, used 14462K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
   the space 16384K,  88% used [0x00000007bf000000, 0x00000007bfe1f978, 0x00000007bfe1fa00, 0x00000007c0000000)
 Metaspace       used 12024K, capacity 12848K, committed 13056K, reserved 1060864K
  class space    used 1302K, capacity 1466K, committed 1536K, reserved 1048576K

看一下 allocatedInYoung 的空间分配 

38 一次 younggc fullgc 的调试_System_07

第七次gc

这一次 是由 allocatedInOld 的分配触发的 

young 的 eden 和 from 均不能够分配 这个 allocatedInOld 了, 因此 放到了 old 来分配 

[24.072s][info   ][gc,phases,start] GC(7) Phase 1: Mark live objects
[24.170s][info   ][gc,phases      ] GC(7) Phase 1: Mark live objects 97.441ms
[24.170s][info   ][gc,phases,start] GC(7) Phase 2: Compute new object addresses
[24.180s][info   ][gc,phases      ] GC(7) Phase 2: Compute new object addresses 10.502ms
[24.180s][info   ][gc,phases,start] GC(7) Phase 3: Adjust pointers
[24.232s][info   ][gc,phases      ] GC(7) Phase 3: Adjust pointers 52.238ms
[24.232s][info   ][gc,phases,start] GC(7) Phase 4: Move objects
[24.243s][info   ][gc,phases      ] GC(7) Phase 4: Move objects 10.908ms
[24.269s][info   ][gc,heap        ] GC(7) DefNew: 12040K->12040K(14784K)
[24.269s][info   ][gc,heap        ] GC(7) Tenured: 14462K->14123K(16384K)
[24.269s][info   ][gc,metaspace   ] GC(7) Metaspace: 11916K->11916K(1060864K)
[24.270s][info   ][gc             ] GC(7) Pause Full (Allocation Failure) 25M->25M(30M) 197.628ms
[24.270s][info   ][gc,cpu         ] GC(7) User=0.20s Sys=0.00s Real=0.20s
33256140904
33283682056



查看一下 主线程的栈帧信息, 发现是 分配 1.6 * 1M 的数组(allocatedInOld) 触发的 gc

38 一次 younggc fullgc 的调试_Real_08

gc 之前 heap 的详细信息如下 

def new generation   total 14784K, used 12172K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
  eden space 13184K,  92% used [0x00000007be000000, 0x00000007bebe3018, 0x00000007bece0000)
  from space 1600K,   0% used [0x00000007bece0000, 0x00000007bece0000, 0x00000007bee70000)
  to   space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
 tenured generation   total 16384K, used 14462K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
   the space 16384K,  88% used [0x00000007bf000000, 0x00000007bfe1f978, 0x00000007bfe1fa00, 0x00000007c0000000)
 Metaspace       used 11911K, capacity 12564K, committed 13056K, reserved 1060864K
  class space    used 1269K, capacity 1406K, committed 1536K, reserved 1048576K

再来看一下 allocatedInOld 的空间分配 

在 young 中尝试空间分配, 但是分配不了了, 然后在 old 尝试分配, 分配成功 

38 一次 younggc fullgc 的调试_System_09

完 

举报

相关推荐

0 条评论