阅读GC日志

编写代码并添加JVM参数，观测GC日志信息

package com.tech.gc.gc;  /**  * 阅读GC日志  * -Xms20M -Xmx20M -Xmn10M -XX: UseSerialGC -XX: PrintGCDetails -verbose:gc  * 堆的初始和最大内存是20M,新生代分配10M老年代剩余10M,使用SerialGC垃圾回收器，打印GC日志  * @author lw  * @since 2021/11/7  */ public class Demo_1 {     private static final int _512KB=512*1024;     private static final int _1MB=1024*1024;     private static final int _6MB=6*1024*1024;     private static final int _7MB=7*1024*1024;     private static final int _8MB=8*1024*1024;     public static void main(String[] args) {      } } 

这里使用了SerialGC不是垃圾回收器JDK该回收器幸存区的比例不会动态调整。

设置好JVM运行结果如下：

Heap  def new generation   total 9216K, used 2203K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)   eden space 8192K,  26% used [0x00000000fec00000, 0x00000000fee26ec0, 0x00000000ff400000)   from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)   to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)  tenured generation   total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)    the space 10240K,   0% used [0x00000000ff600000, 0x00000000ff600000, 0x00000000ff600200, 0x0000000100000000)  Metaspace       used 3243K, capacity 4496K, committed 4864K, reserved 1056768K   class space    used 352K, capacity 388K, committed 512K, reserved 1048576K  Process finished with exit code 0 

def new generation：新一代，总内存为9M（实际上是10M，这里的total幸存区没有计算TO占用的1M内存，因为幸存区TO内存应该是空的，以便复制生存对象，因此不包括在对象可以直接使用的范围内一代，默认情况下，每个区域占用内存eden:from:to=8M:1M:1M，也就是8:1:1，eden由于一些系统对象占用内存，该区域被使用了25%，from to该区域尚未使用。

tenured generation：老年人的总内存是10M，未使用。

Metaspace：元空间，使用的直接内存，不是堆内存。

修改堆程序，在栈帧中创建本地变量，分配7M内存

package com.tech.gc.gc;  import java.util.ArrayList; import java.util.List;  /**  * 阅读GC日志  * -Xms20M -Xmx20M -Xmn10M -XX: UseSerialGC -XX: PrintGCDetails -verbose:gc  * 堆的初始和最大内存是20M,新生代分配10M老年代剩余10M,使用SerialGC垃圾回收器，打印GC日志  *  * @author lw  * @since 2021/11/7  */ public class Demo_1 {     private static final int _512KB = 512 * 1024;     private static final int _1MB = 1024 * 1024;     private static final int _6MB = 6 * 1024 * 1024;     private static final int _7MB = 7 * 1024 * 1024;     private static final int _8MB = 8 * 1024 * 1024;      public static void main(String[] args) {         List list=new ArrayList();         list.add(new byte[_7MB]);     } } 

运行日志：

"C:\Program Files\Java\jdk1.8.0_251\bin\java.exe" -Xms20M -Xmx20M -Xmn10M -XX: UseSerialGC -XX: PrintGCDetails -verbose:gc "-javaagent:D:\Tech\resource\IntelliJ IDEA 2018.3.1\lib\idea_rt.jar=55146:D:\Tech\resource\IntelliJ IDEA 2018.3.1\bin" -Dfile.encoding=UTF-8 -classpath "C:\Program Files\Java\jdk1.8.0_251\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\cldrdata.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\jaccess.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunec.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunmscapi.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\zipfs.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jce.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jfxswt.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\resources.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\rt.jar;D:\Tech\code\tech-jvm\target\classes;C:\Users\lw\.m2\repository\org\projectlombok\lombok\1.18.22\lombok-1.18.22.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-annotations\2.12.4\jackson-annotations-2.12.4.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-core\2.12.4\jackson-core-2.12.4.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-databind\2.12.4\jackson-databind-2.12.4.jar" com.tech.gc.gc.Demo_1 [GC (Allocation Failure) [DefNew: 2039K->651K(9216K), 0.0021124 secs] 2039K->651K(19456K), 0.0021555 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  Heap  def new generation   total 9216K, used 8229K [0x00000000fec00000, 0x00000000f600000, 0x00000000ff600000)
  eden space 8192K,  92% used [0x00000000fec00000, 0x00000000ff366830, 0x00000000ff400000)
  from space 1024K,  63% used [0x00000000ff500000, 0x00000000ff5a2eb8, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000, 0x00000000ff600000, 0x00000000ff600200, 0x0000000100000000)
 Metaspace       used 3261K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 355K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 0

分析：

由于eden分配内存为8M,系统对象占用了2M左右，在放入一个7M的数组，内存分配失败，会触发GC。

GC (Allocation Failure) ：表示内存分配失败触发了GC，这里的GC表示的是Minor GC，如果是Full GC，日志应该为Full GC (Allocation Failure)；

[DefNew: 2039K->651K(9216K), 0.0021124 secs]：表示新生代，已占用的内存为2039K，回收后已占用内存为651K，新生代的总内存为9216K(不包含幸存区TO)，进行GC花费的实际为0.002秒。

2039K->651K(19456K), 0.0021555 secs：表示整个堆的内存，已占用2039K，回收后占用651K，花费的时间为0.002s。

def new generation   total 9216K, used 8229K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  92% used [0x00000000fec00000, 0x00000000ff366830, 0x00000000ff400000)
  from space 1024K,  63% used [0x00000000ff500000, 0x00000000ff5a2eb8, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)

eden区内存为8M,使用了92%内存,from区内存为1M，使用了63%内存，TO是空的（在GC时是之前的from,from被清空，to from进行了内存互换）

由于eden区被占用了92%，此时还有空间在放一个512K的数组，修改代码如下:

package com.tech.gc.gc;

import java.util.ArrayList;
import java.util.List;

/**
 * 阅读GC日志
 * -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc
 * 堆的初始和最大内存为20M,新生代分配10M老年代剩余10M,使用SerialGC垃圾回收器，打印GC日志
 *
 * @author lw
 * @since 2021/11/7
 */
public class Demo_1 {
    private static final int _512KB = 512 * 1024;
    private static final int _1MB = 1024 * 1024;
    private static final int _6MB = 6 * 1024 * 1024;
    private static final int _7MB = 7 * 1024 * 1024;
    private static final int _8MB = 8 * 1024 * 1024;

    public static void main(String[] args) {
        List list=new ArrayList();
        list.add(new byte[_7MB]);
        list.add(new byte[_512KB]);
    }
}

运行日志：

"C:\Program Files\Java\jdk1.8.0_251\bin\java.exe" -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc "-javaagent:D:\Tech\resource\IntelliJ IDEA 2018.3.1\lib\idea_rt.jar=63578:D:\Tech\resource\IntelliJ IDEA 2018.3.1\bin" -Dfile.encoding=UTF-8 -classpath "C:\Program Files\Java\jdk1.8.0_251\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\cldrdata.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\jaccess.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunec.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunmscapi.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\zipfs.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jce.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jfxswt.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\resources.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\rt.jar;D:\Tech\code\tech-jvm\target\classes;C:\Users\lw\.m2\repository\org\projectlombok\lombok\1.18.22\lombok-1.18.22.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-annotations\2.12.4\jackson-annotations-2.12.4.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-core\2.12.4\jackson-core-2.12.4.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-databind\2.12.4\jackson-databind-2.12.4.jar" com.tech.gc.gc.Demo_1
[GC (Allocation Failure) [DefNew: 2039K->635K(9216K), 0.0012386 secs] 2039K->635K(19456K), 0.0012686 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 8725K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  98% used [0x00000000fec00000, 0x00000000ff3e6840, 0x00000000ff400000)
  from space 1024K,  62% used [0x00000000ff500000, 0x00000000ff59ecb0, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000, 0x00000000ff600000, 0x00000000ff600200, 0x0000000100000000)
 Metaspace       used 3275K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 357K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 0

发现还是只有1次GC,eden区占用内存达到了98%,其他区域内存不变。

修改程序如下：

package com.tech.gc.gc;

import java.util.ArrayList;
import java.util.List;

/**
 * 阅读GC日志
 * -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc
 * 堆的初始和最大内存为20M,新生代分配10M老年代剩余10M,使用SerialGC垃圾回收器，打印GC日志
 *
 * @author lw
 * @since 2021/11/7
 */
public class Demo_1 {
    private static final int _512KB = 512 * 1024;
    private static final int _1MB = 1024 * 1024;
    private static final int _6MB = 6 * 1024 * 1024;
    private static final int _7MB = 7 * 1024 * 1024;
    private static final int _8MB = 8 * 1024 * 1024;

    public static void main(String[] args) {
        List list=new ArrayList();
        list.add(new byte[_7MB]);
        list.add(new byte[_512KB]);
        list.add(new byte[_512KB]);
    }
}

再添加一个512K的对象，此时eden区剩余2%的内存不够，还会触发一次GC

"C:\Program Files\Java\jdk1.8.0_251\bin\java.exe" -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc "-javaagent:D:\Tech\resource\IntelliJ IDEA 2018.3.1\lib\idea_rt.jar=60226:D:\Tech\resource\IntelliJ IDEA 2018.3.1\bin" -Dfile.encoding=UTF-8 -classpath "C:\Program Files\Java\jdk1.8.0_251\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\cldrdata.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\jaccess.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunec.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunmscapi.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\ext\zipfs.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jce.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jfxswt.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\resources.jar;C:\Program Files\Java\jdk1.8.0_251\jre\lib\rt.jar;D:\Tech\code\tech-jvm\target\classes;C:\Users\lw\.m2\repository\org\projectlombok\lombok\1.18.22\lombok-1.18.22.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-annotations\2.12.4\jackson-annotations-2.12.4.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-core\2.12.4\jackson-core-2.12.4.jar;C:\Users\lw\.m2\repository\com\fasterxml\jackson\core\jackson-databind\2.12.4\jackson-databind-2.12.4.jar" com.tech.gc.gc.Demo_1
[GC (Allocation Failure) [DefNew: 2039K->631K(9216K), 0.0017836 secs] 2039K->631K(19456K), 0.0018267 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [DefNew: 8638K->515K(9216K), 0.0035060 secs] 8638K->8291K(19456K), 0.0035271 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 1191K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,   8% used [0x00000000fec00000, 0x00000000feca9190, 0x00000000ff400000)
  from space 1024K,  50% used [0x00000000ff400000, 0x00000000ff480dc8, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 7776K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  75% used [0x00000000ff600000, 0x00000000ffd98038, 0x00000000ffd98200, 0x0000000100000000)
 Metaspace       used 3253K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 353K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 0

可以发现触发了两次GC,第2次GC时，新生代占用内存8638K到占用内存515K,整个堆的内存占用从8638K到占用8291K,并没有释放多少内存，而是新生代GC后内存不足，新生代的一些对象进入了老年代，老年代占用了75%内存，应该是7M的数组进入了老年代。