java VisualVM辅助分析GC日志

还是上一篇的代码。这次试用java visualVM和Visual GC，来分析每一次GC对于堆的影响。后面总结了一些有趣的结论。

package com.company;

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

public class Main {

    public static void main(String[] args) {
        Scanner scanner = new Scanner(System.in);
        String in = scanner.nextLine();

        List<Integer> lInt=new ArrayList<>();
        int num=10000000;
        int max2=num+num;
        int max3=max2+num;
        long time0=System.currentTimeMillis();
        for(int i=0;i<num;i++){
            lInt.add(i);
        }
        System.out.println("first : "+(System.currentTimeMillis()-time0));

        //lInt.clear();
        long time1=System.currentTimeMillis();
        for(int i=num;i<max2;i++){
            lInt.add(i);
        }
        System.out.println("first : "+(System.currentTimeMillis()-time1));


        //lInt.clear();
        long time2=System.currentTimeMillis();

        for(int i=max2;i<max3;i++){
            lInt.add(i);
        }
        System.out.println("first : "+(System.currentTimeMillis()-time2));

    }
}

没有任何VM内存的参数设定，只是输出GC情况：

"C:\Program Files\Java\jdk1.8.0_221\bin\java.exe" -XX:+PrintGCDetails -XX:+PrintGCTimeStamps "-javaagent:D:\javaDev\JetBrains\IntelliJ IDEA 2019.2.1\lib\idea_rt.jar=56763:D:\javaDev\JetBrains\IntelliJ IDEA 2019.2.1\bin" -Dfile.encoding=UTF-8 -classpath "C:\Program Files\Java\jdk1.8.0_221\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\cldrdata.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\jaccess.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\sunec.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\sunmscapi.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\ext\zipfs.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\jce.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\jfxswt.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\resources.jar;C:\Program Files\Java\jdk1.8.0_221\jre\lib\rt.jar;C:\Users\che101ast\IdeaProjects\TestOSR\out\production\TestOSR" com.company.Main
171.372: [GC (Allocation Failure) [PSYoungGen: 33280K->2360K(38400K)] 33280K->2376K(125952K), 0.0073926 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

309.028: [GC (Allocation Failure) [PSYoungGen: 33433K->5110K(38400K)] 33449K->12894K(125952K), 0.0227113 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
309.066: [GC (Allocation Failure) [PSYoungGen: 38390K->5096K(38400K)] 46174K->36178K(125952K), 0.0532345 secs] [Times: user=0.19 sys=0.00, real=0.05 secs] 
309.135: [GC (Allocation Failure) [PSYoungGen: 33197K->5096K(71680K)] 64279K->62957K(159232K), 0.0576907 secs] [Times: user=0.20 sys=0.03, real=0.06 secs] 
309.193: [Full GC (Ergonomics) [PSYoungGen: 5096K->0K(71680K)] [ParOldGen: 57861K->55705K(125952K)] 62957K->55705K(197632K), [Metaspace: 9662K->9662K(1058816K)], 0.9557118 secs] [Times: user=2.02 sys=0.01, real=0.96 secs] 
310.185: [GC (Allocation Failure) [PSYoungGen: 66560K->5120K(71680K)] 122265K->105334K(197632K), 0.0947620 secs] [Times: user=0.38 sys=0.00, real=0.09 secs] 
310.279: [Full GC (Ergonomics) [PSYoungGen: 5120K->0K(71680K)] [ParOldGen: 100214K->94591K(201728K)] 105334K->94591K(273408K), [Metaspace: 9662K->9662K(1058816K)], 1.1738484 secs] [Times: user=2.56 sys=0.01, real=1.17 secs] 
311.488: [GC (Allocation Failure) [PSYoungGen: 66560K->59383K(150528K)] 161151K->160406K(352256K), 0.1491100 secs] [Times: user=0.42 sys=0.02, real=0.15 secs] 
first : 2708
311.745: [Full GC (Ergonomics) [PSYoungGen: 150519K->43796K(150528K)] [ParOldGen: 155106K->201676K(329728K)] 305625K->245473K(480256K), [Metaspace: 9662K->9662K(1058816K)], 2.7758059 secs] [Times: user=7.09 sys=0.02, real=2.78 secs] 
314.604: [Full GC (Ergonomics) [PSYoungGen: 91136K->0K(150528K)] [ParOldGen: 282800K->319292K(481792K)] 373936K->319292K(632320K), [Metaspace: 9662K->9662K(1058816K)], 2.3526426 secs] [Times: user=7.75 sys=0.00, real=2.35 secs] 
first : 5288
317.096: [Full GC (Ergonomics) [PSYoungGen: 91136K->0K(150528K)] [ParOldGen: 440978K->450532K(647168K)] 532114K->450532K(797696K), [Metaspace: 9662K->9662K(1058816K)], 3.2777666 secs] [Times: user=10.81 sys=0.00, real=3.28 secs] 
320.421: [GC (Allocation Failure) [PSYoungGen: 91136K->76800K(174592K)] 541668K->541452K(821760K), 0.5873119 secs] [Times: user=2.17 sys=0.08, real=0.59 secs] 
first : 4035
Heap
 PSYoungGen      total 174592K, used 129687K [0x00000000d5d80000, 0x00000000e8e00000, 0x0000000100000000)
  eden space 97792K, 54% used [0x00000000d5d80000,0x00000000d9125ea8,0x00000000dbd00000)
  from space 76800K, 100% used [0x00000000dbd00000,0x00000000e0800000,0x00000000e0800000)
  to   space 100352K, 0% used [0x00000000e2c00000,0x00000000e2c00000,0x00000000e8e00000)
 ParOldGen       total 647168K, used 464652K [0x0000000081800000, 0x00000000a9000000, 0x00000000d5d80000)
  object space 647168K, 71% used [0x0000000081800000,0x000000009ddc33d8,0x00000000a9000000)
 Metaspace       used 9670K, capacity 10028K, committed 10240K, reserved 1058816K
  class space    used 1114K, capacity 1196K, committed 1280K, reserved 1048576K

Process finished with exit code 0

运行的同时，用java visualVM进行内存的监测，用到了Visual GC。Visual GC的采样间隔是100ms截图如下

用GC的log和visual GC进行对比非常不直观，就专门做了一个excel辅助对比。

其中old(in log)这列的数值是根据gc log中数值录入的old数值（full GC的log包含了old的变化数值）。

old列是heap 减去 young，计算出来的，同时也能够跟old(in log)互相印证。

interval是本次GC花的时间。

excel中一共列出了10次GC，而log中是12次GC，头两次GC的分析价值不大，就没有列到excel中。

每次GC有两行，第一行是GC开始时候的状态，第二行是结束时候的状态。

截图如下：

从上面的图就能非常直观的看到每一次GC和对应的堆内存变化。

有几个有趣的点：

1 第8次GC是full GC，持续了2.35秒，但是从内存的图来看，2.35秒中的绝大部分时间中，eden，servivor和old都没有变化，等到快结束了的时候young变为0，old从282800 ->319292。是不是，2.35秒的大部分时间都是用来标记哪些对象要挪到old，标记完成后，再一次性挪过去？

2 第8次GC开始时候old的容量是282800，第7次结束时old的容量是201677，在连续两次full GC之间old的容量是增长的。是否说明，jvm也会直接把object创建到old上？

   6 -> 7, 7 -> 8, 8 -> 9都会出现两次GC之间old容量增长。有点儿搞不懂，什么情况下会直接使用Old部分。

3 第一次GC不是full GC，但是依然会增长old，所以也不能说minor GC就只是young generation的事情。

   似乎只能断定，不是full GC，就肯定不会清理old，但是在清理young的时候，依然有可能往old中copy

4 第9次GC，young变成的0，释放了91M的容量，但是old并没有相应增加91M，释放的都是那些对象？

5 还是第8次GC，eden变为0，但是survivor没有增加，而是old有增加，所以，应该是把一部分eden上的对象直接挪到了old中，而不是先放到survivor中，等对象存活几次后再挪到old中。

6 jdk是1.8，young gen的GC算法是parallel scavenge，所以PSYoungGen

  old gen的GC算法是parallel old gen，所以ParOldGen

7 还是第8次GC，young gen变为0之后，非常快，也就0.1秒左右，eden又满了，不得不进行第9次GC。从这个现象可以看出，似乎申请内存并创建对象，比GC要快的多。

full GC需要对所有对象进行扫描，判断该对象是否还被引用，所以随着对象数量的增长，这个扫描花费的时间也是线性增长的。从第一次full gc的0.95秒都最后一次的3.28秒。

第8次GC和第9次GC之间新创建的对象肯定小于2千万个，应该在1千万以内，大概花了0.1秒，但是full gc扫描2千多万个对象花了差不多3秒，结合上一篇博文，没有GC的情况下，创建1千万个对象差不多0.3秒。因此，可以得出结论是，full gc扫描对象相比创建对象更耗时。可能是因为要分析对象之间的引用关系（可达性分析）