阅读GC日志

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

package com.tech.gc.gc;


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;


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 FilesJavajdk1.8.0_251binjava.exe" -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc "-javaagent:D:TechresourceIntelliJ IDEA 2018.3.1libidea_rt.jar=55146:D:TechresourceIntelliJ IDEA 2018.3.1bin" -Dfile.encoding=UTF-8 -classpath "C:Program FilesJavajdk1.8.0_251jrelibcharsets.jar;C:Program FilesJavajdk1.8.0_251jrelibdeploy.jar;C:Program FilesJavajdk1.8.0_251jrelibextaccess-bridge-64.jar;C:Program FilesJavajdk1.8.0_251jrelibextcldrdata.jar;C:Program FilesJavajdk1.8.0_251jrelibextdnsns.jar;C:Program FilesJavajdk1.8.0_251jrelibextjaccess.jar;C:Program FilesJavajdk1.8.0_251jrelibextjfxrt.jar;C:Program FilesJavajdk1.8.0_251jrelibextlocaledata.jar;C:Program FilesJavajdk1.8.0_251jrelibextnashorn.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunec.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunjce_provider.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunmscapi.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunpkcs11.jar;C:Program FilesJavajdk1.8.0_251jrelibextzipfs.jar;C:Program FilesJavajdk1.8.0_251jrelibjavaws.jar;C:Program FilesJavajdk1.8.0_251jrelibjce.jar;C:Program FilesJavajdk1.8.0_251jrelibjfr.jar;C:Program FilesJavajdk1.8.0_251jrelibjfxswt.jar;C:Program FilesJavajdk1.8.0_251jrelibjsse.jar;C:Program FilesJavajdk1.8.0_251jrelibmanagement-agent.jar;C:Program FilesJavajdk1.8.0_251jrelibplugin.jar;C:Program FilesJavajdk1.8.0_251jrelibresources.jar;C:Program FilesJavajdk1.8.0_251jrelibrt.jar;D:Techcodetech-jvmtargetclasses;C:Userslw.m2repositoryorgprojectlomboklombok1.18.22lombok-1.18.22.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-annotations2.12.4jackson-annotations-2.12.4.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-core2.12.4jackson-core-2.12.4.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-databind2.12.4jackson-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, 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)
 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;


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 FilesJavajdk1.8.0_251binjava.exe" -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc "-javaagent:D:TechresourceIntelliJ IDEA 2018.3.1libidea_rt.jar=63578:D:TechresourceIntelliJ IDEA 2018.3.1bin" -Dfile.encoding=UTF-8 -classpath "C:Program FilesJavajdk1.8.0_251jrelibcharsets.jar;C:Program FilesJavajdk1.8.0_251jrelibdeploy.jar;C:Program FilesJavajdk1.8.0_251jrelibextaccess-bridge-64.jar;C:Program FilesJavajdk1.8.0_251jrelibextcldrdata.jar;C:Program FilesJavajdk1.8.0_251jrelibextdnsns.jar;C:Program FilesJavajdk1.8.0_251jrelibextjaccess.jar;C:Program FilesJavajdk1.8.0_251jrelibextjfxrt.jar;C:Program FilesJavajdk1.8.0_251jrelibextlocaledata.jar;C:Program FilesJavajdk1.8.0_251jrelibextnashorn.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunec.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunjce_provider.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunmscapi.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunpkcs11.jar;C:Program FilesJavajdk1.8.0_251jrelibextzipfs.jar;C:Program FilesJavajdk1.8.0_251jrelibjavaws.jar;C:Program FilesJavajdk1.8.0_251jrelibjce.jar;C:Program FilesJavajdk1.8.0_251jrelibjfr.jar;C:Program FilesJavajdk1.8.0_251jrelibjfxswt.jar;C:Program FilesJavajdk1.8.0_251jrelibjsse.jar;C:Program FilesJavajdk1.8.0_251jrelibmanagement-agent.jar;C:Program FilesJavajdk1.8.0_251jrelibplugin.jar;C:Program FilesJavajdk1.8.0_251jrelibresources.jar;C:Program FilesJavajdk1.8.0_251jrelibrt.jar;D:Techcodetech-jvmtargetclasses;C:Userslw.m2repositoryorgprojectlomboklombok1.18.22lombok-1.18.22.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-annotations2.12.4jackson-annotations-2.12.4.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-core2.12.4jackson-core-2.12.4.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-databind2.12.4jackson-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;


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 FilesJavajdk1.8.0_251binjava.exe" -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -verbose:gc "-javaagent:D:TechresourceIntelliJ IDEA 2018.3.1libidea_rt.jar=60226:D:TechresourceIntelliJ IDEA 2018.3.1bin" -Dfile.encoding=UTF-8 -classpath "C:Program FilesJavajdk1.8.0_251jrelibcharsets.jar;C:Program FilesJavajdk1.8.0_251jrelibdeploy.jar;C:Program FilesJavajdk1.8.0_251jrelibextaccess-bridge-64.jar;C:Program FilesJavajdk1.8.0_251jrelibextcldrdata.jar;C:Program FilesJavajdk1.8.0_251jrelibextdnsns.jar;C:Program FilesJavajdk1.8.0_251jrelibextjaccess.jar;C:Program FilesJavajdk1.8.0_251jrelibextjfxrt.jar;C:Program FilesJavajdk1.8.0_251jrelibextlocaledata.jar;C:Program FilesJavajdk1.8.0_251jrelibextnashorn.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunec.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunjce_provider.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunmscapi.jar;C:Program FilesJavajdk1.8.0_251jrelibextsunpkcs11.jar;C:Program FilesJavajdk1.8.0_251jrelibextzipfs.jar;C:Program FilesJavajdk1.8.0_251jrelibjavaws.jar;C:Program FilesJavajdk1.8.0_251jrelibjce.jar;C:Program FilesJavajdk1.8.0_251jrelibjfr.jar;C:Program FilesJavajdk1.8.0_251jrelibjfxswt.jar;C:Program FilesJavajdk1.8.0_251jrelibjsse.jar;C:Program FilesJavajdk1.8.0_251jrelibmanagement-agent.jar;C:Program FilesJavajdk1.8.0_251jrelibplugin.jar;C:Program FilesJavajdk1.8.0_251jrelibresources.jar;C:Program FilesJavajdk1.8.0_251jrelibrt.jar;D:Techcodetech-jvmtargetclasses;C:Userslw.m2repositoryorgprojectlomboklombok1.18.22lombok-1.18.22.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-annotations2.12.4jackson-annotations-2.12.4.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-core2.12.4jackson-core-2.12.4.jar;C:Userslw.m2repositorycomfasterxmljacksoncorejackson-databind2.12.4jackson-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的数组进入了老年代。