java VisualVM辅助分析GC日志 II

上一篇提出了几个问题，经过进一步的学习，在这里做些解答：

1 问题4，young中减少的容量没有全部加到old中，中间少的部分是什么？

--参考：https://blog.csdn.net/u010267179/article/details/21785887

ArrayList实际就是一个数组，容量不够就增加当前容量的0.5倍+1，所以每次也是从heap上申请一大块内容（就有可能直接放到old中了），同时要把原来的数组释放掉，释放的就应该是问题中提到的：少的部分

2 问题2，什么情况会直接在old中创建对象？很多文章提到了，大对象有可能会直接创建到old中。

  在使用ArrayList的时候，增加数组容量的过程就是先创建大数组，然后再释放原来的数组。

为了验证这连个结论，把程序稍微改了一下，用LinkedList替换了ArrayList

package com.company;

import java.util.ArrayList;
import java.util.LinkedList;
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 LinkedList<>();
        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));

    }
}

以下是Log

"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=62739: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

24.487: [GC (Allocation Failure) [PSYoungGen: 33280K->5096K(38400K)] 33280K->18776K(125952K), 0.0771462 secs] [Times: user=0.28 sys=0.03, real=0.08 secs] 
24.579: [GC (Allocation Failure) [PSYoungGen: 38376K->5112K(38400K)] 52056K->52168K(125952K), 0.1502185 secs] [Times: user=0.45 sys=0.02, real=0.15 secs] 
24.743: [GC (Allocation Failure) [PSYoungGen: 38392K->5112K(38400K)] 85448K->85576K(125952K), 0.1501893 secs] [Times: user=0.50 sys=0.06, real=0.15 secs] 
24.894: [Full GC (Ergonomics) [PSYoungGen: 5112K->0K(38400K)] [ParOldGen: 80464K->85238K(166912K)] 85576K->85238K(205312K), [Metaspace: 9349K->9349K(1058816K)], 2.8088633 secs] [Times: user=8.67 sys=0.11, real=2.81 secs] 
27.719: [GC (Allocation Failure) [PSYoungGen: 33280K->5120K(66048K)] 118518K->117614K(232960K), 0.1362002 secs] [Times: user=0.49 sys=0.02, real=0.14 secs] 
27.885: [GC (Allocation Failure) [PSYoungGen: 66048K->5120K(71680K)] 178542K->177942K(244736K), 0.2765756 secs] [Times: user=0.94 sys=0.05, real=0.28 secs] 
28.161: [Full GC (Ergonomics) [PSYoungGen: 5120K->4604K(71680K)] [ParOldGen: 172822K->173000K(290816K)] 177942K->177604K(362496K), [Metaspace: 9356K->9356K(1058816K)], 3.8051435 secs] [Times: user=12.08 sys=0.03, real=3.81 secs] 
32.002: [GC (Allocation Failure) [PSYoungGen: 71164K->65024K(163328K)] 244164K->242552K(454144K), 0.3269996 secs] [Times: user=1.14 sys=0.03, real=0.33 secs] 
32.387: [GC (Allocation Failure) [PSYoungGen: 163328K->78336K(176640K)] 340856K->339832K(467456K), 0.5377874 secs] [Times: user=1.78 sys=0.05, real=0.54 secs] 
32.925: [Full GC (Ergonomics) [PSYoungGen: 78336K->49110K(176640K)] [ParOldGen: 261496K->290308K(455168K)] 339832K->339419K(631808K), [Metaspace: 9384K->9384K(1058816K)], 4.6383954 secs] [Times: user=15.42 sys=0.06, real=4.64 secs] 
first : 13130
37.616: [GC (Allocation Failure) [PSYoungGen: 147414K->133120K(258048K)] 437723K->437148K(713216K), 0.6256326 secs] [Times: user=1.97 sys=0.05, real=0.63 secs] 
38.295: [GC (Allocation Failure) [PSYoungGen: 258048K->162304K(287232K)] 562076K->562092K(742400K), 0.7854310 secs] [Times: user=2.70 sys=0.11, real=0.79 secs] 
39.081: [Full GC (Ergonomics) [PSYoungGen: 162304K->106412K(287232K)] [ParOldGen: 399788K->455109K(669696K)] 562092K->561521K(956928K), [Metaspace: 9387K->9387K(1058816K)], 5.9091004 secs] [Times: user=21.09 sys=0.05, real=5.91 secs] 
45.051: [GC (Allocation Failure) [PSYoungGen: 231340K->174496K(382976K)] 686449K->686429K(1052672K), 0.7080703 secs] [Times: user=2.33 sys=0.17, real=0.71 secs] 
first : 8200
45.820: [GC (Allocation Failure) [PSYoungGen: 334240K->159712K(389632K)] 846173K->846565K(1076736K), 1.1706075 secs] [Times: user=4.23 sys=0.09, real=1.17 secs] 
46.991: [Full GC (Ergonomics) [PSYoungGen: 159712K->158512K(389632K)] [ParOldGen: 686853K->686990K(975872K)] 846565K->845502K(1365504K), [Metaspace: 9389K->9389K(1058816K)], 12.1453146 secs] [Times: user=41.41 sys=0.20, real=12.14 secs] 
59.193: [GC (Allocation Failure) [PSYoungGen: 318256K->159424K(421888K)] 1005246K->1005566K(1397760K), 0.9241405 secs] [Times: user=2.95 sys=0.11, real=0.92 secs] 
60.117: [Full GC (Ergonomics) [PSYoungGen: 159424K->29326K(421888K)] [ParOldGen: 846142K->975421K(1336832K)] 1005566K->1004747K(1758720K), [Metaspace: 9395K->9395K(1058816K)], 10.4582921 secs] [Times: user=28.84 sys=0.25, real=10.46 secs] 
first : 24873
Heap
 PSYoungGen      total 421888K, used 204675K [0x00000000d5d80000, 0x00000000fe580000, 0x0000000100000000)
  eden space 203776K, 86% used [0x00000000d5d80000,0x00000000e08bd348,0x00000000e2480000)
  from space 218112K, 13% used [0x00000000f1080000,0x00000000f2d23b30,0x00000000fe580000)
  to   space 229888K, 0% used [0x00000000e2480000,0x00000000e2480000,0x00000000f0500000)
 ParOldGen       total 1336832K, used 975421K [0x0000000081800000, 0x00000000d3180000, 0x00000000d5d80000)
  object space 1336832K, 72% used [0x0000000081800000,0x00000000bd08f420,0x00000000d3180000)
 Metaspace       used 9424K, capacity 9822K, committed 9984K, reserved 1058816K
  class space    used 1114K, capacity 1195K, committed 1280K, reserved 1048576K

Process finished with exit code 0

可以看出，除了第一次GC以外，整个heap的容量是稳步增长的，有些GC后整个heap的容量也就减少几百k，不是像上一个版本会减少几十兆。这也就说明了LinkedList是不会像ArrayList销毁大数组，是逐步增加节点的。减少的几百K，应该是整形i装箱过程中产生的临时变量。

但是，从运算时间来看，相比ArrayList版本就要慢很多了。有几个因素：

1 full gc多了一次

2 full gc的时间明显更长，最长一次12秒，ArrayList版最长3.2秒。 估计是因为ArrayList是直接一个数组进行收集，而LinkedList应该是很多零散的对象，对象越多需要进行可达性检查的对象就越多，就要花更多的时间。