JVM系列-讀懂 GC 日誌

時間  2020-07-26
標籤 jvm 系列 讀懂 日誌 欄目 Java 简体版
原文   原文鏈接

Java 生態發展到今天，JVM （Java Virtual Machine）的價值可能已經超過了 Java 語言自己。java

而 GC （垃圾回收）機制也是 JVM 的核心之一，在程序運行的過程當中，GC 的過程會以日誌的形式記錄下來，看懂 GC 日誌是研究 GC 機制的基礎，GC日誌也是判斷 Java 程序運行是否正常的重要依據。bash

這篇文章將會從多個方面來詳細說明 GC 日誌，本文基於 OpenJDK1.8 和 HotSpot 虛擬機。app

在開始說明 GC 機制以前，須要先了解一下相關的內容。工具

$ java -version
openjdk version "1.8.0_40"
OpenJDK Runtime Environment (build 1.8.0_40-b25)
OpenJDK 64-Bit Server VM (build 25.40-b25, mixed mode)
複製代碼

上面是使用 java -version 打印出來的信息，裏面信息量很大，好比上面代表這個 JDK 是 openjdk1.8，當前 JVM 是 Server VM，使用的是混合執行模式。ui

JVM 分爲 Client VM 和 Server VM，Client VM 適用內存小，適合一些交互性強的場景，好比桌面應用，Server 則適用於內存大的服務端環境。spa

可使用下面的命令進行 JVM 的切換。操作系統

$ java -client -version
$ java -server -version
複製代碼

可是須要注意，對於 64 位的 JDK，只有 Server VM， Java 已經放棄桌面應用，之後重點關注 Server VM 就能夠。3d

Java 是一門複雜的語言，既能解釋執行，也能編譯執行，也能夠兩種方式共存，默認就是兩種方式並存 (mixed mode)，由 JVM 來決定把哪些代碼編譯執行。日誌

這三種執行方式也能夠進行切換：code

$ java -Xint -version # 徹底解釋執行
$ java -Xcomp -version # 徹底編譯執行
$ java -Xmixed -version # 混合執行
複製代碼

Client VM 和 Server VM 的 GC 機制不同，這篇文章中，咱們只關注 Server VM 的 GC。

JVM 內存模型

下面這兩張圖很重要，只要提到 JVM，就會用到下面兩張圖（HotSpot 虛擬機）。

JVM 內存模型以下：


在 Java 8 之後，使用元空間來實現方法區，而且不佔用堆內的空間，而是使用本地內存來實現。

堆內部的各個區域分佈以下：


其中 Eden、from 和 to 區域稱爲新生代（Young）區域，這三個區域大小的比例默認爲 8:1:1，整個新生代區域和老年代區域的比例爲 1:2。

GC 基本分類

GC 整體上能夠分紅兩類，對部分區域的 GC 和整堆的 GC（Full GC），通常狀況下，只會發生部分區域的 GC，若是常常發生整堆的 GC，可能存在內存泄漏等狀況。

對部分區域的 GC 有可能發生在新生代（Minor GC），也有可能發生老年代（Major GC）。

也有一種特殊的狀況，若是使用的是 G1 收集器，那麼會同時對新生代和老年代進行 GC。


當咱們在說到 JVM 的 GC 時，通常都指對 JVM 堆的回收，大多數狀況下，只有堆內的內存纔會被回收。

GC 參數

默認狀況下，Java 程序在運行時並不會打印 GC 日誌，須要加上下面的 JVM 參數：

-verbose:gc # 控制檯打印 gc 日誌
-XX:+PrintGCDetails # 打印 gc 過程的細節
-XX:+PrintGCDateStamps # 打印 gc 的發生的時間戳
複製代碼

若是想保存爲文件，則須要加上下面的參數，須要注意的是，若是保存爲文件，則控制檯就再也不打印 gc 日誌：

-Xloggc:gc.log # 將 gc 日誌保存成文件，默認在項目的根目錄，能夠根據項目的狀況進行調整
複製代碼

還有一些其餘輔助性的參數:

-XX:+PrintGCApplicationStoppedTime # 打印 stop world 的時間
-XX:+PrintGCApplicationConcurrentTime # 打印程序未中斷運行的時間
-XX:+PrintHeapAtGC # 打印 GC 先後的堆棧信息
-XX:+PrintTenuringDistribution # 打印每次 minor GC 後新的存活週期的閾值
複製代碼

認識 GC 日誌

首先來了看一段基本的日誌，設置的參數爲：

-Xms8m
-Xmx8m
-verbose:gc
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
複製代碼

而後執行下面的代碼：

public class NoGC {
    public static void main(String[] args) {
        System.out.println("No gc");
    }
}
複製代碼

產生的日誌以下：

Heap
 PSYoungGen      total 2048K, used 1400K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 1536K, 91% used [0x00000000ffd80000,0x00000000ffede3d0,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 5632K, used 0K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
  object space 5632K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffd80000)
 Metaspace       used 3018K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 323K, capacity 388K, committed 512K, reserved 1048576K
複製代碼

運行上面的代碼以後，就會產生上面的日誌，上面的日誌顯示在運行這段代碼的時候尚未進行 GC，只是把堆的內存狀態打印出來了。

上面的 Heap 表示這是 JVM 的堆，主要分紅三個部分，PSYoungGen（新生代），ParOldGen（老年代） 和 Metaspace（元數據空間，也就是方法區）。

須要注意的是，元空間不從堆裏面分配內存，而是使用堆外內存，也就是直接從運行的機器上分配內存。但結構上與堆在一塊兒，元空間還有一個名稱是非堆。

PSYoungGen 表示的是新生代，而且使用 Parallel Scavenge 收集器來 GC，ParOldGen 表示老年代，而且使用 Parallel old 收集器來 GC，Server VM 使用的就是這對收集器的組合。

新生代分紅 eden、from 和 to 三個區域，from 和 to 區域也稱之爲 Survivor 區域，在上面的日誌中，咱們能夠看出每一個區域所佔的大小以及使用狀況。

老年代沒有再細分爲其餘的區域，那些在新生代沒有被淘汰的的對象會進入老年代。

發生部分 GC

執行下面這段代碼：

public class NormalGC {
    public static void main(String[] args) throws InterruptedException {

        Object o  = new Object();
        for (int i = 0; ;i++) {
            Thread.sleep(1000);
            byte[] b = new byte[1024 * 1024];
            b = null;
        }
    }
}
複製代碼

產生的 GC 日誌以下：

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 2048K, used 1536K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 1536K, 100% used [0x00000000ffd80000,0x00000000fff00000,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 5632K, used 0K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
  object space 5632K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffd80000)
 Metaspace       used 3136K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 333K, capacity 388K, committed 512K, reserved 1048576K
[GC (Allocation Failure) 
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 1536K->496K(2048K)] 1536K->560K(7680K), 0.0024873 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 2048K, used 496K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 1536K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x00000000fff00000)
  from space 512K, 96% used [0x00000000fff00000,0x00000000fff7c010,0x00000000fff80000)
  to   space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
 ParOldGen       total 5632K, used 64K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
  object space 5632K, 1% used [0x00000000ff800000,0x00000000ff810000,0x00000000ffd80000)
 Metaspace       used 3136K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 333K, capacity 388K, committed 512K, reserved 1048576K
}
Total time for which application threads were stopped: 0.0029243 seconds, Stopping threads took: 0.0000297 seconds
Application time: 1.0001808 seconds
複製代碼

先總體來看一下這個日誌的結構。

最前面一部分是進行 GC 以前堆內存的分配狀況，invocations 表示垃圾回收的次數，括號裏面是發生 Full GC 的次數。

而後就是 GC 回收的細節，下面詳細說，再而後是 GC 以後堆的內存分配狀況，與 GC 的以前堆的狀況能夠有個對比。

倒數第二行是 PrintGCApplicationStoppedTime 參數打印出來的信息，表示由於 GC 而產生的停頓時間。最後一行是 PrintGCApplicationConcurrentTime 參數所打印出來的信息，表示程序運行的時間。

下面來看 GC 的回收細節，經過上面的日誌能夠看到新生代的 eden 區已經滿了，而後就出現了下面這條日誌:

[GC (Allocation Failure) 
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 1536K->496K(2048K)] 1536K->560K(7680K), 0.0024873 secs] 
[Times: user=0.01 sys=0.00, real=0.01 secs] 
複製代碼

這條日誌就是在新生代進行了 minor GC。

第一行表示發起此次 GC 的緣由是分配新的內存失敗（Allocation Failure），第二行是由於咱們加上了 -XX:+PrintTenuringDistribution 這個參數，它會打印出新生代對象的年齡，以及對象進入老年代的年齡閾值，這裏默認是 7，最大是 15 ，能夠經過參數進行調整。

第三行就是具體的回收信息，PSYoungGen 表示這是發生在新生代的回收，分開來看各部分：

  • 1536K->496K(2048K) 表示：回收前該區域已使用的空間→回收後該區域使用的空間(該區域總空間)，這裏是指新生代區域
  • 1536K->560K(7680K) 表示：回收前堆中已使用的空間→回收後堆中已使用的空間(堆的總空間)
  • 0.0024873 secs：表示 GC 進行的時間，單位爲秒
  • Times: user=0.01 sys=0.00, real=0.01 secs： 這部分也是對 GC 時間進行統計，可是是從操做系統的角度來統計，分被表示用戶態時間，內核態時間和時鐘時間

發生 Full GC

執行下面的代碼就會發生 Full GC：

public class FullGC {
    public static void main(String[] args) {
        int size = 1024 * 1024;
        byte[] b = new byte[size];

        b = null;

        System.gc();
    }
}
複製代碼

Full GC 其餘的部分與上面部分 GC 基本一致，下面重點來看發生 Full GC 時，各個區域的回收狀況：

[Full GC (System.gc()) 
[PSYoungGen: 480K->0K(2048K)] 
[ParOldGen: 1104K->473K(5632K)] 
1584K->473K(7680K),
[Metaspace: 3107K->3107K(1056768K)], 
0.0055681 secs] 
[Times: user=0.02 sys=0.00, real=0.01 secs] 
複製代碼

第一行是表示此次發生的是 Full GC，發起的緣由是調用了 System.gc()。

第二行和第三行分別表示對新生代和老年代的回收，回收前後各個區域佔用的內存狀況都會打印出來。

第四行一樣表示整個堆內存的回收狀況。

第五行表示對元空間也進行了垃圾回收，雖然什麼也沒有回收成功。

若是內存泄露或溢出

OutOfMemoryError 是一種常見的錯誤，通常在拋出這個異常以前，都會出現一次 Full GC。

public class Leak2GC {
    public static void main(String[] args) {
         Vector strings = new Vector();

        for (int i = 0;  ;i++) {
            String str = new String("Hello gc" + i);
            strings.add(str);
            str = null;
        }
    }
}
複製代碼

執行上面的代碼以後，就會出現下來的日誌：

[Full GC (Allocation Failure) 
[PSYoungGen: 943K->943K(2048K)] 
[ParOldGen: 5556K->5539K(5632K)] 
6499K->6483K(7680K), 
[Metaspace: 3135K->3135K(1056768K)],
0.0260635 secs]
[Times: user=0.14 sys=0.00, real=0.03 secs] 
複製代碼

即便進行了 Full GC，也沒法對各個區域進行有效的回收，在沒法回收空間以後，就會報出下面的錯誤：

Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at java.util.Arrays.copyOf(Arrays.java:3210)
	at java.util.Arrays.copyOf(Arrays.java:3181)
	at java.util.Vector.grow(Vector.java:266)
	at java.util.Vector.ensureCapacityHelper(Vector.java:246)
	at java.util.Vector.add(Vector.java:782)
	at cn.rayjun.java.java8.gc.Leak2GC.main(Leak2GC.java:12)
複製代碼

GC 信息統計分析

經過上面的內容，應該就能夠看懂 GC 的日誌信息了，在不少狀況下，咱們經過部分的日誌沒法判斷問題。

因此就有必要對總體的 GC 狀況進行統計，通常會藉助其餘的統計工具來進行。

最直接的方式就是使用 JDK 的內置工具，jstat ，具體使用以下，參數爲 pid。

$ jstat -gc 24991
S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
512.0  512.0   0.0    0.0    1536.0   1024.0    5632.0     4755.0   4864.0 3477.4 512.0  378.3      54    0.082   1      0.018    0.099
複製代碼

各個數據項的含義以下：

  • S0C：from 區的大小
  • S1C：to 區的大小
  • S1U：from 區使用的大小
  • S1U：to 去使用的大小
  • EC：eden 區的大小
  • EU：eden 去使用的大小
  • OC：老年代的大小
  • OU：老年代使用的大小
  • MC：方法區的大小
  • MU：方法區使用的大小
  • CCSC：壓縮類空間大小
  • CCUS：壓縮類空間使用的大小
  • YGC：年輕代垃圾回收的次數
  • YGCT：年輕代垃圾回收消耗時間
  • FGC：老年代垃圾回收的次數
  • FGCT：老年代垃圾回收消耗時間
  • GCT：垃圾回收的總時間

也可使用可視化的分析工具來對 CG 日誌進行分析，好比 gceasy.io/。

若是使用其餘的收集器

在上面的日誌中，GC 使用的是默認收集器組合，咱們也可使用其餘的收集器來，好比使用 UseConcMarkSweepGC 參數來啓用 CMS收集器。

使用了這個收集器以後，日誌以下：

[GC (Allocation Failure) [ParNew: 1384K->256K(2432K), 0.0022504 secs] 1384K->491K(7936K), 0.0022693 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[Full GC (System.gc()) [CMS: 235K->472K(5504K), 0.0016647 secs] 1582K->472K(7936K), [Metaspace: 3009K->3009K(1056768K)], 0.0016851 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
複製代碼

稍微有了一點變化，新生代的收集器使用了 ParNew 收集器，老年代使用了 CMS收集器，日誌其餘部分的含義沒有變化。

也能夠根據本身的需求去使用其餘的收集器。

文 / Rayjun

                                                      
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程