前言 

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

呵呵 对于这块的代码上面, 看着感觉有一些疑问的地方, 因此想通过 实际的调试, 来验证一下 实际的情况 

然后 之前写了一个用例, 但是 和心中的期望差距甚大, 当然 主要的问题 还是自己对于 细节的把控不足, 参见 一次 younggc fullgc 的调试 

因此 这次又来了, 当然 这个用例 在 vm 层面上做了一定的修改, 以方便 调试 "Promotion failed"

以下代码, 截图 基于 jdk9 

一下调试可能是来自于多次调试, 因此 地址信息, 内存大小信息 未必能够对上  

测试用例

package com.hx.test08;import org.openjdk.jol.vm.VM;
import org.openjdk.jol.vm.VirtualMachine;import static com.hx.test07.Test30PromotionFailed.touchMinorGc;/*** Test01PromotionFailed** @author Jerry.X.He <970655147@qq.com>* @version 1.0* @date 2020-08-16 15:43*/
public class Test01PromotionFailed {// identStrprivate String identStr = "identStr";public Test01PromotionFailed(String identStr) {this.identStr = identStr;}// Test01PromotionFailed// -Xmx32M -XX:+UseSerialGC -XX:NewRatio=1 -XX:MaxTenuringThreshold=1 -XX:+PrintGCDetails -cp .:/Users/jerry/.m2/repository/org/openjdk/jol/jol-core/0.8/jol-core-0.8.jar// 需要运行时 调整 DefNewGeneration 的相关代码, 这个示例 还需要在稍微调整一下, 能够体现出关系的public static void main(String[] args) throws Exception {VirtualMachine vm = VM.current();int _1M = 1 * 1024 * 800;Test01PromotionFailed[] alreadyInOld = new Test01PromotionFailed[3 * _1M];alreadyInOld[0] = new Test01PromotionFailed("alreadyInOld[0]");System.out.println("alreadyInOld : " + vm.addressOf(alreadyInOld));System.out.println("alreadyInOld[0] : " + vm.addressOf(alreadyInOld[0]));touchMinorGc();System.out.println("alreadyInOld : " + vm.addressOf(alreadyInOld));System.out.println("alreadyInOld[0] : " + vm.addressOf(alreadyInOld[0]));System.out.println(" ------------ alreadyInOld ------------ ");Test01PromotionFailed[] promotionFailed = new Test01PromotionFailed[3 * _1M];promotionFailed[0] = new Test01PromotionFailed("promotionFailed[0]");promotionFailed[1] = alreadyInOld[0];System.out.println("promotionFailed : " + vm.addressOf(promotionFailed));System.out.println("promotionFailed[0] : " + vm.addressOf(promotionFailed[0]));touchMinorGc();System.out.println("promotionFailed : " + vm.addressOf(promotionFailed));System.out.println("promotionFailed[0] : " + vm.addressOf(promotionFailed[0]));System.out.println("alreadyInOld : " + vm.addressOf(alreadyInOld));System.out.println("alreadyInOld[0] : " + vm.addressOf(alreadyInOld[0]));System.out.println(" ------------ promotionFailed ------------ ");}}

执行之后 日志如下 

[0.025s][warning][gc] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead.
Signal: SIGSEGV (signal SIGSEGV)
[2.545s][info   ][gc] Using Serial
[2.545s][info   ][gc,heap,coops] Heap address: 0x00000007be000000, size: 32 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
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
[15.909s][info   ][gc,start     ] GC(0) Pause Young (Allocation Failure)
max_promotion_in_bytes = 1 = (size_t) 1
[20.978s][info   ][gc,heap      ] GC(0) DefNew: 13184K->1600K(14784K)
[20.979s][info   ][gc,heap      ] GC(0) Tenured: 0K->468K(16384K)
[20.979s][info   ][gc,metaspace ] GC(0) Metaspace: 11260K->11260K(1060864K)
[20.985s][info   ][gc           ] GC(0) Pause Young (Allocation Failure) 12M->2M(30M) 5069.789ms
[20.985s][info   ][gc,cpu       ] GC(0) User=0.10s Sys=0.21s Real=5.08s
alreadyInOld : 33253750272
alreadyInOld[0] : 33253505256
max : 12M, used : 10M, touchMinorGc created 4 byte[1M] 
[21.304s][info   ][gc,start     ] GC(1) Pause Young (Allocation Failure)
max_promotion_in_bytes = 1 = (size_t) 1
[22.969s][info   ][gc,heap      ] GC(1) DefNew: 14781K->391K(14784K)
[22.969s][info   ][gc,heap      ] GC(1) Tenured: 468K->11651K(16384K)
[22.969s][info   ][gc,metaspace ] GC(1) Metaspace: 12040K->12040K(1060864K)
[22.969s][info   ][gc           ] GC(1) Pause Young (Allocation Failure) 14M->11M(30M) 1665.263ms
[22.969s][info   ][gc,cpu       ] GC(1) User=0.11s Sys=0.00s Real=1.67s
alreadyInOld : 33270016504
alreadyInOld[0] : 33266216512------------ alreadyInOld ------------ 
promotionFailed : 33254801960
promotionFailed[0] : 33254540032
max : 12M, used : 11M, touchMinorGc created 3 byte[1M] 
[22.996s][info   ][gc,start     ] GC(2) Pause Young (Allocation Failure)
max_promotion_in_bytes = 1 = (size_t) 1
[23.969s][info   ][gc,promotion ] Promotion failed
[24.825s][info   ][gc,start     ] GC(3) Pause Full (Allocation Failure)
[24.827s][info   ][gc,phases,start] GC(3) Phase 1: Mark live objects
[25.017s][info   ][gc,phases      ] GC(3) Phase 1: Mark live objects 190.929ms
[25.017s][info   ][gc,phases,start] GC(3) Phase 2: Compute new object addresses
[25.031s][info   ][gc,phases      ] GC(3) Phase 2: Compute new object addresses 13.600ms
[25.031s][info   ][gc,phases,start] GC(3) Phase 3: Adjust pointers
[25.145s][info   ][gc,phases      ] GC(3) Phase 3: Adjust pointers 113.455ms
[25.145s][info   ][gc,phases,start] GC(3) Phase 4: Move objects
[25.153s][info   ][gc,phases      ] GC(3) Phase 4: Move objects 8.183ms
[25.178s][info   ][gc             ] GC(3) Pause Full (Allocation Failure) 24M->21M(30M) 353.170ms
[25.178s][info   ][gc,heap        ] GC(2) DefNew: 13320K->9600K(14784K)
[25.178s][info   ][gc,heap        ] GC(2) Tenured: 11651K->12026K(16384K)
[25.178s][info   ][gc,metaspace   ] GC(2) Metaspace: 12040K->12040K(1060864K)
[25.179s][info   ][gc             ] GC(2) Pause Young (Allocation Failure) 24M->21M(30M) 2183.003ms
[25.179s][info   ][gc,cpu         ] GC(2) User=0.40s Sys=0.00s Real=2.18s
promotionFailed : 33252442112
promotionFailed[0] : 33262272528
alreadyInOld : 33270016504
alreadyInOld[0] : 33281179280------------ promotionFailed ------------ 
[25.184s][info   ][gc,heap,exit   ] Heap
[25.184s][info   ][gc,heap,exit   ]  def new generation   total 14784K, used 12163K [0x00000007be000000, 0x00000007bf000000, 0x00000007bf000000)
[25.184s][info   ][gc,heap,exit   ]   eden space 13184K,  92% used [0x00000007be000000, 0x00000007bebe0d00, 0x00000007bece0000)
[25.184s][info   ][gc,heap,exit   ]   from space 1600K,   0% used [0x00000007bee70000, 0x00000007bee70000, 0x00000007bf000000)
[25.184s][info   ][gc,heap,exit   ]   to   space 1600K,   0% used [0x00000007bece0000, 0x00000007bece0000, 0x00000007bee70000)
[25.184s][info   ][gc,heap,exit   ]  tenured generation   total 16384K, used 12026K [0x00000007bf000000, 0x00000007c0000000, 0x00000007c0000000)
[25.184s][info   ][gc,heap,exit   ]    the space 16384K,  73% used [0x00000007bf000000, 0x00000007bfbbea60, 0x00000007bfbbec00, 0x00000007c0000000)
[25.184s][info   ][gc,heap,exit   ]  Metaspace       used 12046K, capacity 12844K, committed 13056K, reserved 1060864K
[25.184s][info   ][gc,heap,exit   ]   class space    used 1305K, capacity 1466K, committed 1536K, reserved 1048576K
[25.189s][info   ][gc,verify,start] Verifying 
[25.570s][info   ][gc,verify      ] Verifying  381.932ms

从上面可以看到, 整个过程中 总共是触发了 四次 gc 

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

然后 之后 alreadyInOld 之后的 touchMinorGc 触发了一次 young gc, 吧 alreadyInOld 放到了 old(to空间不够, promotion 到了 old)

然后 promotionFailed 之后又触发了一次 gc, 这次 young gc 发生了 "Promotion failed ", 然后 之后 又触发了一次 full gc 

我们这里 核心需要关注的是 第三次 gc, 也就是 发生了 "Promotion failed " 的这一次 

第一次 gc 的触发时机 

第二次 gc, alreadyInOld 的去向

上面日志中有一行 "max_promotion_in_bytes = 1 = (size_t) 1", 这个是为了 更轻松的构造 "Promotion failed ", 运行时修改了一个条件, 修改的是 如下的 collection_attempt_is_safe() 

  // If the next generation is too full to accommodate promotion// from this generation, pass on collection; let the next generation// do it.if (!collection_attempt_is_safe()) {log_trace(gc)(":: Collection attempt not safe ::");gch->set_incremental_collection_failed(); // Slight lie: we did not even attempt onereturn;}

第三次 gc, Promotion failed

我们这里主要关注几个东西, alreadyInOld[0], promotionFailed, promotionFailed[0] 这三个引用对应的 oop, 以及这三个引用本身  

alreadyInOld 在这里并不是那么重要, 仅仅是一个 占用 old 的 dummy 

首先来看一下 promotionFailed 

[Lcom.hx.test08.Test01PromotionFailed; 
{0x00000007be33f6f8} - klass: 'com/hx/test08/Test01PromotionFailed'[]- length: 2457600-   0 : a 'com/hx/test08/Test01PromotionFailed'{0x00000007be200300}-   1 : a 'com/hx/test08/Test01PromotionFailed'{0x00000007bed22ef8}-   2 : NULL-   3 : NULL

结合日志 发现这里的地址是对上的 

alreadyInOld : 33270017464
alreadyInOld[0] : 33266216696------------ alreadyInOld ------------ 
promotionFailed : 33255847672
promotionFailed[0] : 33254540032

我们再来看一下 对于 promotionFailed 的处理 

promotionFailed 的 age 为 0, to 里面分配不了空间, 因此尝试 promotion 到 old, old 里面也分配不了空间, 然后 记录了一下 "Promotion failed ", 最后返回的是  promotionFailed 对应的 oop 的地址, 所以 young gc 之后 promotionFailed  对应的 oop 是没有变化的 

promotionFailed 这个引用本身, 也没有变化, 也还是 0x00000007be33f6f8 

再来看一下 promotionFailed[0]

com.hx.test08.Test01PromotionFailed 
{0x00000007be200300} - klass: 'com/hx/test08/Test01PromotionFailed'- ---- fields (total size 2 words):- private 'identStr' 'Ljava/lang/String;' @12  "promotionFailed[0]"{0x00000007be200310} (f7c40062 5)

再来看一下 promotionFailed[0] 的处理, 通过 刚才 "Promotion failed " 的 promotionFailed 找到了 promotionFailed[0]

吧 promotionFailed[0] 复制到了 to, 因此 promotionFailed[0] 被复制到了 to 

promotionFailed[0] 这个引用 也指向了 新的地址 

再来看一下 alreadyInOld[0]/promotionFailed[1]

com.hx.test08.Test01PromotionFailed 
{0x00000007bed22ef8} - klass: 'com/hx/test08/Test01PromotionFailed'- ---- fields (total size 2 words):- private 'identStr' 'Ljava/lang/String;' @12  "alreadyInOld[0]"{0x00000007becea2e0} (f7d9d45c d)

再来看一下 alreadyInOld[0] 的处理, 通过 刚才 "Promotion failed " 的 promotionFailed 找到了 alreadyInOld[0]

吧 alreadyInOld[0] 复制到了 to, 因此 alreadyInOld[0] 被复制到了 to 

alreadyInOld[0] 这个引用 也指向了 新的地址 

最后, 来到这一次 gc 的末尾, 我们看一下 各个地址的情况 

可以看懂 promotionFailed 最后还是在该对象原来的位置, promotionFailed[0], promotionFailed[1] 指向的是 这两个 oop 复制之后的位置

promotionFailed[0], promotionFailed[1] 这两个 oop 之前的位置的数据还在, 因为 "Promotion failed " 不能清理空间, 但是已经没有 引用引用 这两个 oop 了 

[1145.114s][info   ][gc,promotion ] Promotion failed
[Lcom.hx.test08.Test01PromotionFailed; 
{0x00000007be33f6f8} - klass: 'com/hx/test08/Test01PromotionFailed'[]- length: 2457600-   0 : a 'com/hx/test08/Test01PromotionFailed'{0x00000007bee70000}-   1 : a 'com/hx/test08/Test01PromotionFailed'{0x00000007bfb680a8}-   2 : NULL-   3 : NULL- 省略掉预览的其他 251 个 oop 的展示- <2457344 more elements, increase MaxElementPrintSize to print>
com.hx.test08.Test01PromotionFailed 
{0x00000007be200300} - klass: 'com/hx/test08/Test01PromotionFailed'- ---- fields (total size 2 words):- private 'identStr' 'Ljava/lang/String;' @12  "promotionFailed[0]"{0x00000007be200310} (f7c40062 5)
com.hx.test08.Test01PromotionFailed 
{0x00000007bed22ef8} - klass: 'com/hx/test08/Test01PromotionFailed'- ---- fields (total size 2 words):- private 'identStr' 'Ljava/lang/String;' @12  "alreadyInOld[0]"{0x00000007becea2e0} (f7d9d45c 5)
com.hx.test08.Test01PromotionFailed 
{0x00000007bee70000} - klass: 'com/hx/test08/Test01PromotionFailed'- ---- fields (total size 2 words):- private 'identStr' 'Ljava/lang/String;' @12  "promotionFailed[0]"{0x00000007bee70028} (f7dce005 d)
com.hx.test08.Test01PromotionFailed 
{0x00000007bed22ef8} - klass: 'com/hx/test08/Test01PromotionFailed'- ---- fields (total size 2 words):- private 'identStr' 'Ljava/lang/String;' @12  "alreadyInOld[0]"{0x00000007becea2e0} (f7d9d45c 5)

第四次 gc 

上面的调试输出是 第三次 gc 期间的运行时的数据 

第四次 之后的日志 便是上面的, 当然 我们这里 并不是那么关心, 因此 不多赘述 

promotionFailed : 33252442112
promotionFailed[0] : 33262272528
alreadyInOld : 33270017464
alreadyInOld[0] : 33281179816

 第四次 gc 触发的时机 

完 

参考

一次 younggc fullgc 的调试