62 一次 Promotion failed 的调试

前言 

最近 有一个想法就是, 调试一下 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 <[e-mail]>* @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 的调试