44 UseParallelGC的场景下 只发生了 minorgc, oldGen 里面却被占用了空间

前言

呵呵 最近在某交流群里面 有同学提到了这样的一个问题  

最开始 我没有怎么注意, 但是 问题持续了两天, 呵呵 然后 花了一些时间看了一下 

Nerazzurri : 我看了个测试环境上部的应用的GC日志，看到有些信息不太明白，第一次YGC，堆占用空间和年轻代一样，那是说老年代没有被占用，第二次YGC就不一样，年轻代比堆少8K，第三次少16K，第三次少32K，不知道这些少的，是不是在老年代，而且这些数还是2的倍数，不知道是什么原因，不能仅仅是巧合吧，
然后第五次GC原因,GCLocker Initiated GC指什么？
然后后面的第一次FullGC ,是由于元空间不够触发的吗？看着年轻代占用并不多 

North : 这个怎么解释

North : 这24k数据是怎么进去的呢

然后 之后洗了一个 case, 来测试一下, 问题 果然复现了 

问题的原因虽然找到了, 但是 这个问题的原因的更细节的东西, 就了解的少之又少了 

以下测试用例截图基于 jdk9 调试 

另外有一篇类似的问题, 也和本文的内容有一些关联 UseConcMarkSweepGC 的情况下 PrintTenuringDistribution 和 PrintGCDetails 的对象空间占用不一致的问题

测试用例 

/**
 * Test11OldUnknown8Kb
 *
 * @author Jerry.X.He <970655147@qq.com>
 * @version 1.0
 * @date 2021-10-27 19:09
 */
public class Test11OldUnknown8Kb {
 
    // Test11OldUnknown8Kb
    // -Xmx100M -XX:+UseParallelGC -XX:ParallelGCThreads=10 -XX:OldPLABSize=10240 -XX:+PrintHeapAtGC -XX:+PrintGCDetails
    public static void main(String[] args) throws Exception {
 
        for (int i = 0; i < 70; i++) {
            byte[] dummy = new byte[1 * 1024 * 1024];
        }
 
        System.in.read();
 
    }
 
}

然后配置 vm 参数, 运行, 大致会得到日志如下 

可以参照 HeapBefore, HeapAfter, 发现 第二次 minor gc 之后 oldGen 增加了 80k, 第三次 minor gc 的时候 oldGen 又增加了 80k 

这里的差异是 80k, 上面的对话差异是 8k, 这里先剧透一下, 是和 OldPLABSize 的参数配置有关系 

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 29696K, used 25207K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 98% used [0x00000007bdf00000,0x00000007bf79de48,0x00000007bf800000)
  from space 4096K, 0% used [0x00000007bfc00000,0x00000007bfc00000,0x00000007c0000000)
  to   space 4096K, 0% used [0x00000007bf800000,0x00000007bf800000,0x00000007bfc00000)
 ParOldGen       total 68608K, used 0K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c00000,0x00000007bdf00000)
 Metaspace       used 3075K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 392K, committed 512K, reserved 1048576K
[GC (Allocation Failure) [PSYoungGen: 25207K->2524K(29696K)] 25207K->2524K(98304K), 0.0034964 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 29696K, used 2524K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 0% used [0x00000007bdf00000,0x00000007bdf00000,0x00000007bf800000)
  from space 4096K, 61% used [0x00000007bf800000,0x00000007bfa77250,0x00000007bfc00000)
  to   space 4096K, 0% used [0x00000007bfc00000,0x00000007bfc00000,0x00000007c0000000)
 ParOldGen       total 68608K, used 0K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c00000,0x00000007bdf00000)
 Metaspace       used 3075K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 392K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=2 (full 0):
 PSYoungGen      total 29696K, used 27602K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 97% used [0x00000007bdf00000,0x00000007bf77d6d8,0x00000007bf800000)
  from space 4096K, 61% used [0x00000007bf800000,0x00000007bfa77250,0x00000007bfc00000)
  to   space 4096K, 0% used [0x00000007bfc00000,0x00000007bfc00000,0x00000007c0000000)
 ParOldGen       total 68608K, used 0K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c00000,0x00000007bdf00000)
 Metaspace       used 3085K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 392K, committed 512K, reserved 1048576K
[GC (Allocation Failure) [PSYoungGen: 27602K->1613K(29696K)] 27602K->1693K(98304K), 0.0016530 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap after GC invocations=2 (full 0):
 PSYoungGen      total 29696K, used 1613K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 0% used [0x00000007bdf00000,0x00000007bdf00000,0x00000007bf800000)
  from space 4096K, 39% used [0x00000007bfc00000,0x00000007bfd93658,0x00000007c0000000)
  to   space 4096K, 0% used [0x00000007bf800000,0x00000007bf800000,0x00000007bfc00000)
 ParOldGen       total 68608K, used 80K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c14000,0x00000007bdf00000)
 Metaspace       used 3085K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 392K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=3 (full 0):
 PSYoungGen      total 29696K, used 26933K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 98% used [0x00000007bdf00000,0x00000007bf7ba130,0x00000007bf800000)
  from space 4096K, 39% used [0x00000007bfc00000,0x00000007bfd93658,0x00000007c0000000)
  to   space 4096K, 0% used [0x00000007bf800000,0x00000007bf800000,0x00000007bfc00000)
 ParOldGen       total 68608K, used 80K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c14000,0x00000007bdf00000)
 Metaspace       used 3086K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 392K, committed 512K, reserved 1048576K
[GC (Allocation Failure) [PSYoungGen: 26933K->1469K(29696K)] 27013K->1629K(98304K), 0.0017334 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap after GC invocations=3 (full 0):
 PSYoungGen      total 29696K, used 1469K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 0% used [0x00000007bdf00000,0x00000007bdf00000,0x00000007bf800000)
  from space 4096K, 35% used [0x00000007bf800000,0x00000007bf96f668,0x00000007bfc00000)
  to   space 4096K, 0% used [0x00000007bfc00000,0x00000007bfc00000,0x00000007c0000000)
 ParOldGen       total 68608K, used 160K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c28000,0x00000007bdf00000)
 Metaspace       used 3086K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 324K, capacity 392K, committed 512K, reserved 1048576K
}
Disconnected from the target VM, address: '127.0.0.1:51462', transport: 'socket'
Heap
 PSYoungGen      total 29696K, used 15785K [0x00000007bdf00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 25600K, 55% used [0x00000007bdf00000,0x00000007becfaea8,0x00000007bf800000)
  from space 4096K, 35% used [0x00000007bf800000,0x00000007bf96f668,0x00000007bfc00000)
  to   space 4096K, 0% used [0x00000007bfc00000,0x00000007bfc00000,0x00000007c0000000)
 ParOldGen       total 68608K, used 160K [0x00000007b9c00000, 0x00000007bdf00000, 0x00000007bdf00000)
  object space 68608K, 0% used [0x00000007b9c00000,0x00000007b9c28000,0x00000007bdf00000)
 Metaspace       used 3093K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 325K, capacity 392K, committed 512K, reserved 1048576K

基于 hprof 的调试 

 jmap dump 堆dump文件, 然后使用 jhat 解析 如下, 总共有 20774 个 oop 

然后使用 UseConcMarkSweepGC 的情况下 PrintTenuringDistribution 和 PrintGCDetails 的对象空间占用不一致的问题​​​​​​​z

中的 Test08ParseFromDumpFile​​​​​​​ 来进行分析, 结果如下 

可以看到 old 里面确实是有 oop, 大致的占用也在 160kb 左右  

根据地址信息 调整一下 oop 的排列, oldGen 第三次 gc 之后正常 oop 排列如下 

0x7b9c00000 - java.lang.Class - 108 - class java.lang.ref.Finalizer (108 bytes)
0x7b9c00078 - java.lang.Class - 108 - class java.lang.ref.ReferenceQueue (108 bytes)
0x7b9c000f0 - java.lang.Class - 108 - class sun.misc.VM (108 bytes)
0x7b9c001a0 - java.lang.Class - 108 - class java.lang.ref.Reference (108 bytes)
0x7b9c00210 - [I - 81392 - null
0x7b9c14000 - java.lang.Object - 16 - null
0x7b9c14010 - java.lang.String - 28 - Negative timeout value (28 bytes)
0x7b9c14028 - [I - 81880 - null

第二次 minor gc  之后有 4 个 Class 对象 promote 到了 oldGen, 然后 gc 之后 retire plab, 填充了一个 int[81392] 

第三次 minor gc  之后有 1 个 Object 对象, 1 个 String 对象 promote 到了 oldGen, 然后 gc 之后 retire plab, 填充了一个 int[81880] 

但是 据此, 我们能够明确 oldGen 中是那些对象, 但是 不能明确具体的原因 

所以 还得基于 vm 来调试一下 

基于 VM 的调试

然后可以看到在 miinor gc 的时候, 确实是有 oop promote 到 oldGen 

然后 我们再来看一下 他的具体的原因 

调整一下 栈帧, 可以看到这里的 promotion_immediately, 然后 copy_to_survivor 的时候, 不会在 young 分配空间, 直接在 old 里面分配空间  

在往上看一看, 这里是在处理 codecache 里面关联的一部分 oop, 也就是说 codecache 里面会有一部分 oop 会直接 promote 到 oldGen 

 搜索一下 roots_to_old_closure 使用的地方, 只有这里; 搜索一下 PSPromoteRootsClosure 使用的地方, 也只有这里 

为什么差异是 80k

回到另外一个问题, "这里的差异是 80k, 上面的对话差异是 8k, 这里先剧透一下, 是和 OldPLABSize 的参数配置有关系" 

呵呵 这个就不用解释了吧 

如果您还没有懂, 请重新阅读一下本文, 以及参考文章 

完 

参考

UseConcMarkSweepGC 的情况下 PrintTenuringDistribution 和 PrintGCDetails 的对象空间占用不一致的问题