JVM第七周 GC日志学习

coder后花园
529 阅读19分钟

GC日志

动手模拟出频繁Young GC的场景

JVM参数配置如下：

-XX:NewSize=5242880 -XX:MaxNewSize=5242880 -XX:InitialHeapSize=10485760
-XX:MaxHeapSize=10485760 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC 
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

参数详细说明：

  • -XX:NewSize=5242880 初始新生代大小 5MB
  • -XX:MaxNewSize=5242880 新生代最大大小 5MB
  • -XX:InitialHeapSize=10485760 初始堆大小 10MB
  • -XX:MaxHeapSize=10485760 堆的最大大小 10MB
  • -XX:PretenureSizeThreshold=10485760 大对象阈值 10MB

-XX:+UseParNewGC -XX:+UseConcMarkSweepGC

新生代采用ParNew垃圾回收器，老年代采用CMS垃圾回收器

  • -XX:+PrintGCDetails： 打印详细的GC日志
  • -XX:+PrintGCTimeStamps 打印每次GC的时间
  • -Xloggc:gc.log 将GC日志写入磁盘文件

堆内存：

  • 新生代 5MB
    • Eden 4MB
    • Survivor1 0.5MB
    • Survivor2 0.5MB
  • 老年代 5MB

示例程序：

    public static void main(String[] args) {
        // 连续创建3个数组，每个数组的大小 为 1MB
        byte[] array1 = new byte[1024 * 1024];
        array1 = new byte[1024 * 1024];
        array1 = new byte[1024 * 1024];
        // 三个数组变为垃圾对象
        array1 = null;

        // 创建一个数组，大小为 2MB
        byte[] array2=new byte[2*1024*1024];

    }

执行main方法后，得到的gc日志内容为：

OpenJDK 64-Bit Server VM (25.252-b09) for windows-amd64 JRE (1.8.0_252-b09), built on Apr 22 2020 09:32:45 by "jenkins" with MS VC++ 12.0 (VS2013)
Memory: 4k page, physical 8045256k(1927624k free), swap 17724284k(4980548k free)
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.216: [GC (Allocation Failure) 0.218: [ParNew: 3489K->512K(4608K), 0.0030149 secs] 3489K->1851K(9728K), 0.0053277 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.222: [GC (Allocation Failure) 0.222: [ParNew: 2639K->0K(4608K), 0.0019249 secs] 3979K->1848K(9728K), 0.0020139 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 4608K, used 2192K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1848K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3165K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 328K, capacity 388K, committed 512K, reserved 1048576K

Young GC日志分析

CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC

程序员设置的以及默认的JVM参数

0.216: [GC (Allocation Failure) 0.218: [ParNew: 3489K->512K(4608K), 0.0030149 secs] 3489K->1851K(9728K), 0.0053277 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

GC (Allocation Failure) : 给对象分配内存失败

0.216： 系统运行了216ms后发生了垃圾回收

ParNew: 3489K->512K(4608K), 0.0030149 secs

  • ParNew: 新生代GC采用的垃圾回收器

  • 3489K->512K(4608K)

    • 4608K : 新生代可用内存(4.5MB=1024*4.5)，Eden 4MB+ Survivor(空闲) 0.5MB =4.5MB

    • 3489K->512K

      对年轻代进行了一次GC，GC前使用了 3489KB，GC之后只有 512KB 的对象存活了下来

  • 0.0030149 secs

    本次GC大约耗费3ms，仅仅回收3MB左右的对象

3489K->1851K(9728K), 0.0053277 secs

指的是整个Java堆的情况

Java堆的总可用空间 为 9728K（新生代 4.5MB + 老年代 5MB），

发生GC前堆内存使用了3489K，GC之后Java堆使用了574KB

[Times: user=0.00 sys=0.00, real=0.00 secs]

本地GC消耗时间

这里最小单位是小数点之后两位，但是这里全部是0.00 secs，也就是说本次gc就耗费了几毫秒，所以从秒为单位来看，几乎是0。

GC之后堆内存的使用情况

Heap
 par new generation   total 4608K, used 2192K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1848K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3165K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 328K, capacity 388K, committed 512K, reserved 1048576K

这段日志是在JVM退出时打印出来的堆内存使用情况。

Heap
 par new generation   total 4608K, used 2192K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)

Heap par new generation total 4608K, used 2192K

“ParNew”垃圾回收器负责的年轻代一共4608K（4.5MB）的可用内存，目前使用了2192KB

后面创建了一个2MB的数组

 eden space 4096K,  53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)

Eden区域 4MB内存，53%被使用

from Survivor区 512KB，100%？不对啊

 concurrent mark-sweep generation total 5120K, used 1848K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3165K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 328K, capacity 388K, committed 512K, reserved 1048576K

说Concurrent Mark-Sweep垃圾回收器，也就是CMS垃圾回收器，管理的老年代内存空间一共是5MB，此时使用了1848KB的空间。暂时先不用知道这1848KB内存是啥

Metaspace元数据空间和Class空间，存放了一些类信息和一些常量池之类的东西。

Java8 取消了PermGen。取而代之的是MetaSpace，方法区在java8以后移至MetaSpace。 Jdk8开始把类的元数据放到本地内存（native heap），称之为MetaSpace



理论上本地内存剩余多少，MetaSpace就有多大，当然我们也不可能无限制的增大MetaSpace，需要用-XX:MaxMetaSpaceSize来指定MetaSpace区域大小。 



关于used capacity commited 和reserved，在stackoverflow找到个比较靠谱的答案，我尝试翻译一下： MetaSpace由一个或多个Virtual Space（虚拟空间）组成。虚拟空间是操作系统的连续存储空间，虚拟空间是按需分配的。当被分配时，虚拟空间会向操作系统预留（reserve）空间，但还没有被提交（committed）。



MetaSpace的预留空间（reserved）是全部虚拟空间的大小。 虚拟空间的最小分配单元是MetaChunk（也可以说是Chunk）。



当新的Chunk被分配至虚拟空间时，与Chunk相关的内存空间被提交了（committed）。MetaSpace的committed指的是所有Chunk占有的空间。 



每个Chunk占据空间不同，当一个类加载器（Class Loader）被gc时，所有与之关联的Chunk被释放（freed）。这些被释放的Chunk被维护在一个全局的释放数组里。



MetaSpace的capacity指的是所有未被释放的Chunk占据的空间。 这么看gc日志发现自己committed是4864K，capacity4486K。有一部分的Chunk已经被释放了，代表有类加载器被回收了

动手模拟出对象进入老年代的场景

对象进入老年代的时机

  1. 躲过15次GC，达到15岁年龄后进入老年代
  2. 动态年龄判定规则，如果Survivor区域，年龄1+年龄2+。。。+年龄n的对象大小 超过了 Suvivor空间的50%，则年龄为n以上的对象全部进入老年代（不一定达到15岁）
  3. 如果GC后，存活对象太多，Survivor区域放不下，则对象进入老年代
  4. 大对象直接进入老年代（G1中，是放入大对象专门的Region中）

模拟动态年龄判定规则（对象进入老年代）

JVM参数

-XX:NewSize=10485760  -XX:MaxNewSize=10485760  
-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520
-XX:SurvivorRatio=8  -XX:MaxTenuringThreshold=15  -XX:PretenureSizeThreshold=10485760
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC 
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

新生代 10MB，Eden区 8MB，每个Survivor区分别为1MB。

Java堆总大小为20MB，老年代为10MB

大对象必须超过10MB才会直接进入老年代

对象15岁直接进入老年代

测试代码

    public static void main(String[] args) {
        
        byte[] array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB

        array1 = null;

        byte[] array2 = new byte[128 * 1024];// 128KB

        byte[] array3 = new byte[2*1024 * 1024]; // 2MB
    }

GC日志

OpenJDK 64-Bit Server VM (25.252-b09) for windows-amd64 JRE (1.8.0_252-b09), built on Apr 22 2020 09:32:45 by "jenkins" with MS VC++ 12.0 (VS2013)
Memory: 4k page, physical 8045256k(870552k free), swap 18055740k(2357196k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.153: [GC (Allocation Failure) 0.184: [ParNew: 7984K->825K(9216K), 0.0031582 secs] 7984K->825K(19456K), 0.0333578 secs] [Times: user=0.00 sys=0.00, real=0.03 secs] 
Heap
 par new generation   total 9216K, used 3039K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee29808, 0x00000000ff400000)
  from space 1024K,  80% used [0x00000000ff500000, 0x00000000ff5ce600, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3238K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 338K, capacity 388K, committed 512K, reserved 1048576K

0.291: [GC (Allocation Failure) 0.292: [ParNew: 6763K->854K(9216K), 0.0034261 secs] 6763K->2904K(19456K), 0.0043645 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

byte[] array3 = new byte[2*1024 * 1024]; // 2MB代码尝试去分配2MB内存时，发现Eden区内存不够了，就触发YoungGC，标记存活对象，并将存活对象复制到From Survivor区。

9216K 是新生代可用内存=Eden 8MB+空闲的Survivor区（From Survivor区）1MB=9MB

6763K=6MB byte数组对象+128KB数组对象+其他对象 491 KB。

6MB byte数组对象+128KB数组对象=6272 KB

491 KB + 128KB=619KB对象，虽然比 854KB对象要小一些，但也差不多了。

Heap par new generation total 9216K, used 5402K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000) eden space 8192K, 55% used [0x00000000fec00000, 0x00000000ff071048, 0x00000000ff400000) from space 1024K, 83% used [0x00000000ff500000, 0x00000000ff5d5838, 0x00000000ff600000) to space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)

eden space 8192K, 55% = 4.4MB

from space 1024K, 83% 约等于 854KB。

示例代码完善

 public static void main(String[] args) {
        byte[] array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB

        array1 = null;

        byte[] array2 = new byte[128 * 1024];// 128KB

        byte[] array3 = new byte[2 * 1024 * 1024]; // 2MB

        array3 = new byte[2 * 1024 * 1024]; // 2MB
        array3 = new byte[2 * 1024 * 1024]; // 2MB
        array3 = new byte[128 * 1024];// 128KB
        array3 = null;

        byte[] array4 = new byte[2 * 1024 * 1024];//2MB
    }

代码完善以后，我们可以触发第二次Young GC

        array3 = new byte[2 * 1024 * 1024]; // 2MB
        array3 = new byte[2 * 1024 * 1024]; // 2MB
 		array3 = new byte[128 * 1024];// 128KB
        array3 = null;

Java HotSpot(TM) 64-Bit Server VM (25.151-b12) for windows-amd64 JRE (1.8.0_151-b12), built on Sep  5 2017 19:33:46 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8045256k(2183480k free), swap 18224968k(2626948k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.111: [GC (Allocation Failure) 0.111: [ParNew: 7255K->700K(9216K), 0.0008549 secs] 7255K->700K(19456K), 0.0010023 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.112: [GC (Allocation Failure) 0.112: [ParNew: 7004K->0K(9216K), 0.0025875 secs] 7004K->680K(19456K), 0.0026298 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 2212K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee290e0, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 concurrent mark-sweep generation total 10240K, used 680K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2603K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

这时候触发了动态年龄判定规则，From Survivor区中的存活对象直接进入老年代了

动手模拟 对象年龄为15时直接进入老年代

 for (int i = 0; i < 15; i++) {
            byte[] temp = new byte[7 * 1024 * 1024];
            temp = null;
            if (i == 0) {
                byte[] array1 = new byte[800 * 1024];
            }
 }

OpenJDK 64-Bit Server VM (25.252-b09) for windows-amd64 JRE (1.8.0_252-b09), built on Apr 22 2020 09:32:45 by "jenkins" with MS VC++ 12.0 (VS2013)
Memory: 4k page, physical 8045256k(1311456k free), swap 19123728k(2824324k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.135: [GC (Allocation Failure) 0.135: [ParNew: 1672K->661K(9216K), 0.0008223 secs] 1672K->661K(19456K), 0.0010460 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.141: [GC (Allocation Failure) 0.141: [ParNew: 8853K->445K(9216K), 0.0028831 secs] 8853K->1034K(19456K), 0.0029499 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.144: [GC (Allocation Failure) 0.144: [ParNew: 7695K->98K(9216K), 0.0004226 secs] 8284K->687K(19456K), 0.0004748 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.145: [GC (Allocation Failure) 0.145: [ParNew: 7321K->30K(9216K), 0.0003140 secs] 7909K->618K(19456K), 0.0003887 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.147: [GC (Allocation Failure) 0.147: [ParNew: 7233K->18K(9216K), 0.0004608 secs] 7822K->607K(19456K), 0.0005303 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
0.148: [GC (Allocation Failure) 0.148: [ParNew: 7209K->18K(9216K), 0.0004721 secs] 7798K->607K(19456K), 0.0005568 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.149: [GC (Allocation Failure) 0.149: [ParNew: 7201K->18K(9216K), 0.0006734 secs] 7790K->606K(19456K), 0.0007440 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.151: [GC (Allocation Failure) 0.151: [ParNew: 7196K->24K(9216K), 0.0006611 secs] 7784K->612K(19456K), 0.0007174 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.152: [GC (Allocation Failure) 0.152: [ParNew: 7198K->22K(9216K), 0.0004382 secs] 7787K->610K(19456K), 0.0004980 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.153: [GC (Allocation Failure) 0.153: [ParNew: 7214K->42K(9216K), 0.0004039 secs] 7803K->631K(19456K), 0.0004536 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.154: [GC (Allocation Failure) 0.154: [ParNew: 7213K->42K(9216K), 0.0004537 secs] 7802K->631K(19456K), 0.0005069 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.155: [GC (Allocation Failure) 0.155: [ParNew: 7212K->25K(9216K), 0.0006380 secs] 7801K->613K(19456K), 0.0006959 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.157: [GC (Allocation Failure) 0.157: [ParNew: 7200K->25K(9216K), 0.0005777 secs] 7789K->614K(19456K), 0.0006299 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.158: [GC (Allocation Failure) 0.158: [ParNew: 7199K->27K(9216K), 0.0005130 secs] 7788K->616K(19456K), 0.0005629 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.159: [GC (Allocation Failure) 0.159: [ParNew: 7197K->28K(9216K), 0.0005821 secs] 7786K->617K(19456K), 0.0006502 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 7394K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  89% used [0x00000000fec00000, 0x00000000ff331a38, 0x00000000ff400000)
  from space 1024K,   2% used [0x00000000ff500000, 0x00000000ff5070e0, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 588K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3270K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 343K, capacity 388K, committed 512K, reserved 1048576K

动手模拟 Young GC后对象放不进Survivor直接进入老年代

avatar
文章
阅读
粉丝
相关推荐
JVM基本概念、命令、参数、GC日志总结
526阅读
 · 
8点赞
GCeasy: 让天下没有难懂的GC日志
1.3k阅读
 · 
9点赞
请大家一定不要像我们公司这样打印log日志
47k阅读
 · 
457点赞
JVM: GC过程总结(minor GC 和 Full GC)
2.5k阅读
 · 
1点赞
JVM频繁GC内存溢出排查
2.0k阅读
 · 
27点赞