美文网首页
读懂jvm日志

读懂jvm日志

作者: 我要进大厂 | 来源:发表于2020-07-14 10:05 被阅读0次

    测试代码

    package mm02;
import java.util.ArrayList;
import java.util.List;
public class HelloWorld{
    public static void main(String[] args) {
        System.out.println("Hello World");
        List<String> str = new ArrayList<String>();
        int i=0;
        while (true){
            str.add(String.valueOf(i).intern());
        }
    }
}

    vm参数

    -XX:+PrintGCDetails(打印GC详细信息) 和-verbose:gc 这两个没有什么区别，一般采用前者。

    -XX:+PrintGCDetails -Xms20M -Xmx20m -XX:+PrintCommandLineFlags -XX:+UseConcMarkSweepGC

    -XX:+UseConcMarkSweepGC 这个参数是切换垃圾回收器，下面测试垃圾回收器时，该参数会随测试的回收器不同而改变。

    img

    默认垃圾回收器

    • jdk1.7 默认垃圾收集器Parallel Scavenge（新生代）+ Parallel Old（老年代），即-XX:+UseParallelGC
    • jdk1.8 默认垃圾收集器Parallel Scavenge（新生代）+ Parallel Old（老年代），即-XX:+UseParallelGC
    • jdk1.9 默认垃圾收集器G1，即-XX:+UseG1GC

    可通过java -XX:+PrintCommandLineFlags -version查看正在使用的垃圾回收器。

    回收器分类

    • 串行回收期（单线程）：Serial/Serial Old
    • 并行回收器（多线程）：ParNew 和 Parallel Scavenge（新生代的并行回收器）/ Parallel Old（老年代的并行回收器）
    • 并发回收器：CMS回收器

    直通BAT必考题系列：7种JVM垃圾收集器特点，优劣势、及使用场景

    Parallel Scavenge(并行拾荒)会stw吗？

    会的。无论哪种垃圾回收器发生，minor gc还是full gc都会发生STW 。只是G1 的 Stop The World 更可控，G1 在停顿上添加了预测机制，用户可以指定期望的停顿时间。所以无论是并行回收器CMS或者是并发回收期ParNew 和 Parallel Scavenge/ Parallel Old都是存在STW(STOP THE WORLD)的。但jvm gc日志，并不是每行日志都发生了STW，cms垃圾回收器的并发标记和并发清除这两个阶段都是同用户线程并发进行的，不会STW，但cms回收过程，包含了，初始标记和重新标记发送了STW，所以从整体来看，cms垃圾回收器也是会STW的。

    我们先全局看下各个回收器打印的gc日志，后续我们再分析日志。

    串行回收器：-XX:+UseSerialGC

    jvm日志包含：[GC[DefNew: ，tenured generation:。表示年轻代使用Serial 串行回收器 + 老年代的用 Serial Old。

    -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDetails -XX:-UseLargePagesIndividualAllocation 
Hello World
[GC[DefNew: 5504K->640K(6144K), 0.0113903 secs] 5504K->870K(19840K), 0.0395112 secs] [Times: user=0.00 sys=0.00, real=0.04 secs] 
[GC[DefNew: 6144K->0K(6144K), 0.0028659 secs] 6374K->1391K(19840K), 0.0029022 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0027365 secs] 6895K->2798K(19840K), 0.0027913 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0014930 secs] 8302K->4908K(19840K), 0.0015198 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0002404 secs] 10412K->4908K(19840K), 0.0002665 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0022991 secs] 10412K->8074K(19840K), 0.0023358 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0002842 secs] 13578K->8074K(19840K), 0.0003087 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 3572K->0K(6144K), 0.0003111 secs] 11646K->8074K(19840K), 0.0003415 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0035441 secs] 13578K->12822K(19840K), 0.0035808 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->5504K(6144K), 0.0000126 secs][Tenured: 12821K->5200K(13696K), 0.0089890 secs] 18326K->5200K(19840K), [Perm : 1681K->1681K(12288K)], 0.0090498 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0002988 secs] 10704K->5200K(19840K), 0.0003304 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->5504K(6144K), 0.0000197 secs][Tenured: 12322K->7574K(13696K), 0.0093068 secs] 17826K->7574K(19840K), [Perm : 1681K->1681K(12288K)], 0.0094145 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0003478 secs] 13078K->7575K(19840K), 0.0003853 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0002507 secs] 13079K->7574K(19840K), 0.0002795 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0002408 secs] 13078K->7574K(19840K), 0.0002684 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 5504K->0K(6144K), 0.0002444 secs] 13078K->7575K(19840K), 0.0002716 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[DefNew: 340K->0K(6144K), 0.0001011 secs][Tenured: 7574K->7574K(13696K), 0.0096573 secs] 7915K->7574K(19840K), [Perm : 1681K->1681K(12288K)], 0.0098006 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC[Tenured: 7574K->7563K(13696K), 0.0123152 secs] 7574K->7563K(19840K), [Perm : 1681K->1680K(12288K)], 0.0123480 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:2245)
    at java.util.Arrays.copyOf(Arrays.java:2219)
    at java.util.ArrayList.grow(ArrayList.java:242)
    at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:216)
    at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:208)
    at java.util.ArrayList.add(ArrayList.java:440)
    at mm02.HelloWorld.main(HelloWorld.java:16)
Heap
 def new generation   total 6144K, used 223K [0x04800000, 0x04ea0000, 0x04ea0000)
  eden space 5504K,   4% used [0x04800000, 0x04837e90, 0x04d60000)
  from space 640K,   0% used [0x04e00000, 0x04e00000, 0x04ea0000)
  to   space 640K,   0% used [0x04d60000, 0x04d60000, 0x04e00000)
 tenured generation   total 13696K, used 7563K [0x04ea0000, 0x05c00000, 0x05c00000)
   the space 13696K,  55% used [0x04ea0000, 0x05602eb8, 0x05603000, 0x05c00000)
 compacting perm gen  total 12288K, used 1701K [0x05c00000, 0x06800000, 0x09c00000)
   the space 12288K,  13% used [0x05c00000, 0x05da9428, 0x05da9600, 0x06800000)
No shared spaces configured.

    理解GC日志

    [GC[DefNew: 340K->0K(6144K), 0.0001011 secs][Tenured: 7574K->7574K(13696K), 0.0096573 secs] 7915K->7574K(19840K), [Perm : 1681K->1681K(12288K)], 0.0098006 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

[Full GC[Tenured: 7574K->7563K(13696K), 0.0123152 secs] 7574K->7563K(19840K), [Perm : 1681K->1680K(12288K)], 0.0123480 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

    其实从这里看，[GC 和 [Full GC都有点违背我们之前说的，GC是年轻代的垃圾回收（上面日志GC包含老年代的垃圾回收），Full GC是整个垃圾回收（没有年轻代的垃圾回收）。有可能是包含年轻代的垃圾回收，DefNew定义为GC,有老年代、永久代的垃圾回收，定义为full gc。但不管怎样，我觉得不必纠结[gc和[full gc的区别，只需要看实际代表回收哪个区域来判断哪个区域频繁垃圾回收。千万记住，《深入理解jvm》里面89页说的，GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC的。如果有“full”，说明这次GC是发生了Stop The World的，这句话是错的。无论gc还是full gc都会发生STW.

    接下来“[DefNew”、“[Tenured”、“[Perm”、“[PSYoungGen”表示GC发生的区域，这里显示的区域名称与使用的GC收集器是密切相关的，例如Serial收集器为“[DefNew”，ParNew收集器为“[ParNew”，如果是Parallel Scavenge收集器，那它配套的新生代为“PSYoungGen”，老年代和永久代同理，名称也是由收集器决定的。

    后面方括号内部的“340K->0K(6144K)” 含义是“GC前该内存区域已使用容量->GC后该内存区域已使用容量（该内存区域总容量）”。

    而在方括号之外的“7915K->7574K(19840K)”表示“GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）”

    再往后，“0.0001011 secs”表示该内存区域GC所占用的时间，单位是秒。“[Times: user=0.00 sys=0.00, real=0.01 secs] ”，这里面的user、sys、和real与linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU时间和操作从开始到结束所经历过的墙钟时间。CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘IO，等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以user或者sys时间超过real时间是完全正常的。

    并发回收器：-XX:+UseParNewGC

    jvm日志包含：[GC[ParNew: ，tenured generation:。表示年轻代使用ParNew + 老年代的用 Serial Old。

    -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintCommandLineFlags -XX:+PrintGCDetails -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
Hello World
[GC[ParNew: 5504K->463K(6144K), 0.0016169 secs] 5504K->880K(19840K), 0.0016738 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5967K->167K(6144K), 0.0025683 secs] 6384K->1989K(19840K), 0.0026153 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5671K->41K(6144K), 0.0025462 secs] 7493K->3271K(19840K), 0.0025813 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5545K->15K(6144K), 0.0033621 secs] 8775K->5355K(19840K), 0.0034016 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5519K->4K(6144K), 0.0002870 secs] 10859K->5343K(19840K), 0.0003115 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5508K->2K(6144K), 0.0050205 secs] 10847K->8507K(19840K), 0.0050612 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC[ParNew: 5506K->6K(6144K), 0.0001804 secs] 14011K->8511K(19840K), 0.0002049 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 3578K->4K(6144K), 0.0002183 secs] 12084K->8509K(19840K), 0.0002534 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5508K->6K(6144K), 0.0075233 secs] 14013K->13259K(19840K), 0.0075568 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC[ParNew: 5510K->5510K(6144K), 0.0000166 secs][Tenured: 13253K->5631K(13696K), 0.0070969 secs] 18763K->5631K(19840K), [Perm : 1681K->1681K(12288K)], 0.0071577 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC[ParNew: 5504K->0K(6144K), 0.0001919 secs] 11135K->5631K(19840K), 0.0002301 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->5504K(6144K), 0.0000114 secs][Tenured: 12753K->8005K(13696K), 0.0083688 secs] 18257K->8005K(19840K), [Perm : 1681K->1681K(12288K)], 0.0084300 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC[ParNew: 5504K->2K(6144K), 0.0001966 secs] 13509K->8007K(19840K), 0.0002349 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5506K->0K(6144K), 0.0002546 secs] 13511K->8005K(19840K), 0.0002898 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->0K(6144K), 0.0002001 secs] 13509K->8005K(19840K), 0.0002420 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->2K(6144K), 0.0003000 secs] 13509K->8007K(19840K), 0.0003257 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 342K->0K(6144K), 0.0001922 secs][Tenured: 8005K->8005K(13696K), 0.0059900 secs] 8348K->8005K(19840K), [Perm : 1681K->1681K(12288K)], 0.0062143 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC[Tenured: 8005K->7563K(13696K), 0.0069094 secs] 8005K->7563K(19840K), [Perm : 1681K->1680K(12288K)], 0.0069323 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:2245)
    at java.util.Arrays.copyOf(Arrays.java:2219)
    at java.util.ArrayList.grow(ArrayList.java:242)
    at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:216)
    at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:208)
    at java.util.ArrayList.add(ArrayList.java:440)
    at mm02.HelloWorld.main(HelloWorld.java:15)
Heap
 par new generation   total 6144K, used 223K [0x04c00000, 0x052a0000, 0x052a0000)
  eden space 5504K,   4% used [0x04c00000, 0x04c37e90, 0x05160000)
  from space 640K,   0% used [0x05200000, 0x05200000, 0x052a0000)
  to   space 640K,   0% used [0x05160000, 0x05160000, 0x05200000)
 tenured generation   total 13696K, used 7563K [0x052a0000, 0x06000000, 0x06000000)
   the space 13696K,  55% used [0x052a0000, 0x05a02ec0, 0x05a03000, 0x06000000)
 compacting perm gen  total 12288K, used 1701K [0x06000000, 0x06c00000, 0x0a000000)
   the space 12288K,  13% used [0x06000000, 0x061a9428, 0x061a9600, 0x06c00000)
No shared spaces configured.

    摘自上面的日志，可以看出，[GC 也并不是单纯的年轻代垃圾回收。[Full GC也不一定是年轻代 + 老年代 + 永久代（如果存在永久代的话）的垃圾回收。

    [GC[ParNew: 342K->0K(6144K), 0.0001922 secs][Tenured: 8005K->8005K(13696K), 0.0059900 secs] 8348K->8005K(19840K), [Perm : 1681K->1681K(12288K)], 0.0062143 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC[Tenured: 8005K->7563K(13696K), 0.0069094 secs] 8005K->7563K(19840K), [Perm : 1681K->1680K(12288K)], 0.0069323 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

    并行回收器：-XX:+UseParallelGC

    jvm1.7+ 日志包含：[GC [PSYoungGen: ，[ParOldGen:。表示年轻代使用 Parallel Scavenge(并行拷贝式收集器) +老年代的用 Parallel Old。

    而jvm 1.6 的日志包含的是：[PSYoungGen，[PSOldGen。即 -XX:+UseParallelGC是Parallel Scavenge + Serial Old。PSOldGen看起来像并行，但其实跟Serial Old共用一个collector，所以还是串行回收器。如果老年代时Serial Old 想切换到Parallel Scavenge + Serial Old ，可使用-XX:+UseParallelOldGC使得老年代切换成Parallel Old回收器。

    -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintCommandLineFlags -XX:+PrintGCDetails -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
Hello World
[GC [PSYoungGen: 5376K->752K(6144K)] 5376K->880K(19968K), 0.0058373 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 6128K->368K(6144K)] 6256K->1433K(19968K), 0.0045338 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 5744K->352K(6144K)] 6809K->2824K(19968K), 0.0076662 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 5728K->368K(6144K)] 8200K->4951K(19968K), 0.0132086 secs] [Times: user=0.03 sys=0.02, real=0.01 secs] 
[GC [PSYoungGen: 5744K->352K(5888K)] 10327K->4935K(19712K), 0.0137833 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 5728K->368K(5888K)] 10311K->8116K(19712K), 0.0164258 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
[GC [PSYoungGen: 5232K->16K(5888K)] 12980K->8108K(19712K), 0.0094607 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 4880K->16K(5888K)] 12972K->8108K(19712K), 0.0017586 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 4880K->16K(5888K)] 12972K->12856K(19712K), 0.0092527 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
[Full GC [PSYoungGen: 16K->0K(5888K)] [ParOldGen: 12840K->5200K(13824K)] 12856K->5200K(19712K) [PSPermGen: 1681K->1680K(12288K)], 0.0207512 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
[GC [PSYoungGen: 4864K->16K(5888K)] 10064K->5216K(19712K), 0.0014452 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 4880K->16K(5888K)] 10080K->5216K(19712K), 0.0014815 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 4880K->16K(5888K)] 10080K->5216K(19712K), 0.0014428 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 4880K->0K(5888K)] [ParOldGen: 12322K->7574K(13824K)] 17202K->7574K(19712K) [PSPermGen: 1680K->1680K(12288K)], 0.1516035 secs] [Times: user=0.14 sys=0.00, real=0.15 secs] 
[GC [PSYoungGen: 4864K->16K(5888K)] 12438K->7590K(19712K), 0.0021787 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 4880K->16K(5888K)] 12454K->7590K(19712K), 0.0025533 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 4880K->0K(5888K)] 12454K->7574K(19712K), 0.0020875 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 4864K->16K(6144K)] 12438K->7590K(19968K), 0.0021554 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 682K->0K(6144K)] 8256K->7574K(19968K), 0.0020602 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 0K->0K(6144K)] 7574K->7574K(19968K), 0.0023508 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 0K->0K(6144K)] [ParOldGen: 7574K->7574K(13824K)] 7574K->7574K(19968K) [PSPermGen: 1680K->1680K(12288K)], 0.0220456 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
[GC [PSYoungGen: 0K->0K(6144K)] 7574K->7574K(19968K), 0.0003829 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 0K->0K(6144K)] [ParOldGen: 7574K->7563K(13824K)] 7574K->7563K(19968K) [PSPermGen: 1680K->1680K(12288K)], 0.0621828 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:2245)
    at java.util.Arrays.copyOf(Arrays.java:2219)
    at java.util.ArrayList.grow(ArrayList.java:242)
    at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:216)
    at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:208)
    at java.util.ArrayList.add(ArrayList.java:440)
    at mm02.HelloWorld.main(HelloWorld.java:16)
Heap
 PSYoungGen      total 6144K, used 218K [0x094c0000, 0x09b80000, 0x09b80000)
  eden space 5376K, 4% used [0x094c0000,0x094f6b28,0x09a00000)
  from space 768K, 0% used [0x09a00000,0x09a00000,0x09ac0000)
  to   space 768K, 0% used [0x09ac0000,0x09ac0000,0x09b80000)
 ParOldGen       total 13824K, used 7563K [0x08740000, 0x094c0000, 0x094c0000)
  object space 13824K, 54% used [0x08740000,0x08ea2ec8,0x094c0000)
 PSPermGen       total 12288K, used 1701K [0x04740000, 0x05340000, 0x08740000)
  object space 12288K, 13% used [0x04740000,0x048e9428,0x05340000)

    轻松永远记住经典jvm参数

    ​ 下图摘自《轻松永远记住经典jvm参数》。我们可以看出默认参数是-XX:+UseParallelGC。

    image-20200710151902944

    ​ 从这篇文章，我们也可以看出，该作者的垃圾回收器是Parallel Scavenge（新生代）+ Parallel Old（老年代）而非 Parallel Scavenge（新生代）+ Serial Old（老年代）。

    image-20200710151654874

    CMS回收器：-XX:+UseConcMarkSweepGC

    jvm日志包含：[GC[ParNew: ，[CMS-concurrent。表示年轻代使用 ParNew + 老年代的用 CMS

    image-20200710150052125 
    -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=6991872 -XX:MaxTenuringThreshold=6 -XX:NewSize=6991872 -XX:OldPLABSize=16 -XX:OldSize=13979648 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
Hello World
[GC[ParNew: 5504K->470K(6144K), 0.0017389 secs] 5504K->887K(19840K), 0.0018076 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5974K->82K(6144K), 0.0036989 secs] 6391K->1895K(19840K), 0.0037324 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5586K->20K(6144K), 0.0026903 secs] 7399K->3240K(19840K), 0.0027416 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5524K->10K(6144K), 0.0035875 secs] 8744K->5340K(19840K), 0.0036329 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5514K->4K(6144K), 0.0002254 secs] 10844K->5333K(19840K), 0.0002645 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5508K->4K(6144K), 0.0052376 secs] 10837K->8499K(19840K), 0.0052747 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [1 CMS-initial-mark: 8495K(13696K)] 8579K(19840K), 0.0001074 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-mark: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5508K->4K(6144K), 0.0003383 secs] 14003K->8499K(19840K), 0.0003727 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 3576K->0K(6144K), 0.0003466 secs] 12072K->8495K(19840K), 0.0003983 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-abortable-preclean: 0.002/0.025 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
[GC[YG occupancy: 4748 K (6144 K)][Rescan (parallel) , 0.0105716 secs][weak refs processing, 0.0000454 secs][scrub string table, 0.0000371 secs] [1 CMS-remark: 8495K(13696K)] 13243K(19840K), 0.0107263 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->2K(6144K), 0.0081166 secs] 9126K->8372K(19840K), 0.0081521 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [1 CMS-initial-mark: 8370K(13696K)] 8442K(19840K), 0.0000754 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-mark: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5506K->5506K(6144K), 0.0000241 secs][CMS[CMS-concurrent-abortable-preclean: 0.000/0.008 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 8370K->5200K(13696K), 0.0084794 secs] 13876K->5200K(19840K), [CMS Perm : 1681K->1680K(12288K)], 0.0085571 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC[ParNew: 5504K->0K(6144K), 0.0002266 secs] 10704K->5200K(19840K), 0.0002625 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->5504K(6144K), 0.0000158 secs][CMS: 12322K->7574K(13696K), 0.0088737 secs] 17826K->7574K(19840K), [CMS Perm : 1680K->1680K(12288K)], 0.0089483 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [1 CMS-initial-mark: 7574K(13696K)] 7677K(19840K), 0.0000699 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-mark: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[YG occupancy: 1841 K (6144 K)][Rescan (parallel) , 0.0016402 secs][weak refs processing, 0.0000253 secs][scrub string table, 0.0000233 secs] [1 CMS-remark: 7574K(13696K)] 9416K(19840K), 0.0017385 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->2K(6144K), 0.0002534 secs] 13078K->7576K(19840K), 0.0002925 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [1 CMS-initial-mark: 7574K(13696K)] 7683K(19840K), 0.0000596 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-mark: 0.014/0.014 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5506K->0K(6144K), 0.0002155 secs] 13080K->7574K(19840K), 0.0002519 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->0K(6144K), 0.0002767 secs] 13078K->7574K(19840K), 0.0003111 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 5504K->2K(6144K), 0.0003513 secs] 13078K->7576K(19840K), 0.0003817 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC[ParNew: 342K->0K(6144K), 0.0002748 secs][CMS[CMS-concurrent-abortable-preclean: 0.003/0.040 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
 (concurrent mode failure): 7574K->7574K(13696K), 0.0070515 secs] 7917K->7574K(19840K), [CMS Perm : 1680K->1680K(12288K)], 0.0073812 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[Full GC[CMS: 7574K->7564K(13696K), 0.0077889 secs] 7574K->7564K(19840K), [CMS Perm : 1680K->1680K(12288K)], 0.0078189 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:2245)
    at java.util.Arrays.copyOf(Arrays.java:2219)
    at java.util.ArrayList.grow(ArrayList.java:242)
    at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:216)
    at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:208)
    at java.util.ArrayList.add(ArrayList.java:440)
    at mm02.HelloWorld.main(HelloWorld.java:16)
Heap
 par new generation   total 6144K, used 223K [0x04800000, 0x04ea0000, 0x04ea0000)
  eden space 5504K,   4% used [0x04800000, 0x04837e90, 0x04d60000)
  from space 640K,   0% used [0x04e00000, 0x04e00000, 0x04ea0000)
  to   space 640K,   0% used [0x04d60000, 0x04d60000, 0x04e00000)
 concurrent mark-sweep generation total 13696K, used 7564K [0x04ea0000, 0x05c00000, 0x05c00000)
 concurrent-mark-sweep perm gen total 12288K, used 1701K [0x05c00000, 0x06800000, 0x09c00000)

    JVM之G1垃圾收集器

    G1回收器：-XX:+UseG1GC

    G1垃圾回收器不区分新生代、老年代回收器了。它是对整个堆的回收器都是使用G1回收器。

    [hadoop@node03 install]$ /kkb/install/jdk1.8.0_141/bin/java -XX:+PrintGCDetails -Xms20M -Xmx20m -XX:+PrintCommandLineFlags -XX:+UseG1GC HelloWorld
-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintCommandLineFlags -XX:+PrintGCDetails -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 
Hello World
[GC pause (G1 Evacuation Pause) (young), 0.0749018 secs]
   [Parallel Time: 70.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 176.2, Avg: 176.4, Max: 176.7, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.3, Avg: 2.1, Max: 6.5, Diff: 6.2, Sum: 8.3]
      [Update RS (ms): Min: 0.0, Avg: 4.2, Max: 5.8, Diff: 5.8, Sum: 17.0]
         [Processed Buffers: Min: 0, Avg: 3.0, Max: 4, Diff: 4, Sum: 12]
      [Scan RS (ms): Min: 10.9, Avg: 11.0, Max: 11.2, Diff: 0.3, Sum: 44.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 52.5, Avg: 52.6, Max: 52.6, Diff: 0.2, Sum: 210.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 69.6, Avg: 69.9, Max: 70.1, Diff: 0.5, Sum: 279.7]
      [GC Worker End (ms): Min: 246.3, Avg: 246.3, Max: 246.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 1.3 ms]
   [Other: 3.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 1.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12.0M(12.0M)->0.0B(11.0M) Survivors: 0.0B->1024.0K Heap: 13.5M(20.0M)->1947.2K(20.0M)]
 [Times: user=0.23 sys=0.05, real=0.07 secs] 
[GC pause (G1 Evacuation Pause) (young), 0.1704006 secs]
   [Parallel Time: 168.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 403.5, Avg: 406.1, Max: 413.4, Diff: 9.9]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 1.1]
      [Update RS (ms): Min: 0.0, Avg: 4.6, Max: 6.3, Diff: 6.3, Sum: 18.5]

    总结

    现在CMS和G1、ZGC还没完全掌握，需要对浮动垃圾等进行了解。

    相关文章

      网友评论

          本文标题：读懂jvm日志

          本文链接：https://www.haomeiwen.com/subject/vmepcktx.html

          延伸阅读

          深度阅读

          • 您也可以注册成为美文阅读网的作者，发表您的原创作品、分享您的心情！

          栏目导航

          热点阅读

          关于我们|服务条款|联系我们|读懂jvm日志|投稿指南|网站地图|RSS订阅|排版工具|手机版

          提供经典美文摘抄,优美散文欣赏,现代诗歌精选,短篇小说,心情随笔,表白情书范文,故事会在线阅读欣赏

          Copyright © 2014-2023 Haomeiwen.com All Rights Reserved. 好美文阅读网 版权所有

          备案信息：桂公网安备 45052102000051号 · 桂ICP备13007215号-3

          本站所收录作品、热点评论等信息部分来源互联网，目的只是为了系统归纳学习和传递资讯

          所有作品版权归原创作者所有，与本站立场无关，如不慎侵犯了你的权益，请联系我们告知，我们将做删除处理！