前言
最近 有一个想法就是, 调试一下 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 {
// identStr
private 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 one
return;
}第三次 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 的调试
