JVM系列之:GC調優基礎以及初識jstat命令

語言: CN / TW / HK

theme: cyanosis

本文為《深入學習 JVM 系列》第二十二篇文章

影響垃圾收集效能有三個主要的屬性,垃圾收集調優又有三個基本原則,以及垃圾收集調優時需要採集的資訊。如果想要對垃圾收集進行調優,則需要根據實際場景對不同屬性做出取捨,理解調優的原則以及收集什麼資訊。

效能屬性

吞吐量

吞吐量是評價垃圾收集器能力的重要指標之一,指不考慮垃圾收集引起的停頓時間或記憶體消耗,每單位時間可以執行的工作量的指標。通常,吞吐量的增加是以延遲增加和/或記憶體佔用增加為代價的。

一般吞吐量需求(Generic requirements for throughput) 類似這樣:

  • 每天必須處理 100萬個訂單;
  • 每秒應執行 2500 個事務

可以看出,吞吐量需求不是針對單個操作的,,而是在給定的時間內,系統必須完成多少個操作。

延遲

延遲是衡量應用程式接收到執行某些工作的激勵與該工作完成之間經過的時間。延遲要求忽略吞吐量。通常,提高響應能力或降低延遲是以降低吞吐量和/或增加記憶體佔用為代價的。

延遲指標通常如下所述:

  • 應用程式應在 60 毫秒內執行交易請求以完成
  • 90%的訂單付款操作必須在3秒以內處理完成

這類效能指標要確保程式在工作過程中,GC 暫停不能暫用太長時間,否則就滿足不了指標。

記憶體佔用

記憶體佔用量是在某種吞吐量、某種延遲和/或某種可用性和可管理性水平上執行應用程式所需的記憶體量的度量。記憶體佔用通常表示為執行應用程式所需的 Java 堆數量和/或執行應用程式所需的記憶體總量。通常,通過增加 Java 堆大小來增加記憶體佔用可以提高吞吐量或減少延遲,或兩者兼而有之。隨著應用程式可用記憶體的減少,通常會犧牲吞吐量或延遲。

例如系統部署到小於1G 記憶體的伺服器上,因為計算資源不可隨意揮霍,所以在滿足延遲和吞吐量需求的基礎上必須要滿足記憶體佔用。

原則

  • Minor GC 回收原則。每次 Minor GC 都儘可能多地收集垃圾物件,減少 Full GC 的頻率。Full GC 持續時間總是最長的,會影響吞吐量和延遲的效能。
  • GC 記憶體最大化原則。在預算以內,堆記憶體越大越好,吞吐量和延遲效能都會越好。這也意味著新生代可以適當調整大小,以更好應對短壽命物件的建立率,減少提升到老年代的分配數量。
  • 三選二原則。在上述三個效能屬性(吞吐量、延遲、記憶體佔用)中任意選擇兩個進行 JVM 垃圾收集調優。

關於 GC 調優需要收集什麼資訊,以及怎麼檢視,我們將先通過命令列檢視 GC 日誌,後續通過視覺化工具來獲取關鍵資訊。

GC日誌分析

我們需要通過 JVM 引數(預設為 JDK8)預先設定 GC 日誌,通常有以下幾種 JVM 引數設定:

java -XX:+PrintGC 輸出GC日誌 -XX:+PrintGCDetails 輸出GC的詳細日誌 -XX:+PrintGCTimeStamps 輸出GC的時間戳(以基準時間的形式) -XX:+PrintGCDateStamps 輸出GC的時間戳(以日期的形式,如 2013-05-04T21:53:59.234+0800) -XX:+PrintHeapAtGC 在進行GC的前後打印出堆的資訊 -XX:+PrintReferenceGC 輸出的內容包含系統的軟引用、弱引用、虛引用和Finallize佇列 -Xloggc:../logs/gc.log 日誌檔案的輸出路徑

這裡使用如下引數來列印日誌,基於 JDK8,預設使用 Parallel Scavenge 收集器和 Parallel Old 收集器。

```java @Data @AllArgsConstructor @NoArgsConstructor public class Goods {

private String name; private Double price; private String[] types; }

//-Xms60M -Xmx60M -XX:+PrintGCDetails -XX:+PrintGCTimeStamps public class OutOfMemoryTest {

public static void main(String[] args) throws InterruptedException { Map map = new HashMap<>(); int counter = 1; while (true) { Thread.sleep(10); Goods goods = new Goods(); String[] types = new String[counter]; for (int i = 0; i < types.length; i++) { types[i] = "type" + i; } goods.setName("hresh" + counter); goods.setPrice(Double.valueOf(counter)); goods.setTypes(types); map.put(goods.getName(), goods); // if (counter % 100 == 0) { // System.out.println("put" + counter); // } counter++; }

} } ```

擷取 Full GC 的部分日誌內容如下:

16.619: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40924K->40924K(40960K)] 56284K->56284K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0320617 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 16.651: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40926K->40926K(40960K)] 56286K->56286K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0337364 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 16.685: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40927K->40927K(40960K)] 56287K->56287K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0322237 secs] [Times: user=0.30 sys=0.00, real=0.03 secs] 16.717: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40929K->40929K(40960K)] 56289K->56289K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0314023 secs] [Times: user=0.30 sys=0.01, real=0.04 secs] 16.749: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40931K->40931K(40960K)] 56291K->56291K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0327116 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]

關於 GC 日誌,Minor GC 和 Full GC 的含義可以參考本文

分析上述輸出結果,可以得知:

  • 從 16.619 到 16.749 發生了 4次 Full GC,大概耗費了 130 ms,有4次 GC 暫停;
  • 比如說 16.749 這一刻的 GC,花費總時長為 310 ms,暫停時間為 0.0327116 s,不過因為是多核 CPU 機器,而且使用的是並行 GC,所以暫停時間大約為 30ms;
  • 這四次 GC 暫停總時長大約為 130ms,這裡存在疑惑,按理說暫停時長應該小於執行時長,個人猜測可能是 real 的值不夠那麼精確;
  • 在 GC 完成後,幾乎所有的老年代空間(40960K)依然被佔用(40931K)。

通過上述日誌可以發現老年代空間幾乎被佔滿了,而且 GC 之後也沒有釋放,那麼過不了多久,就會丟擲 OOM 異常。

老年代記憶體佔用經過 GC 後沒有改善,仍然接近全滿,那麼會造成效能瓶頸,可能是記憶體太小,又或者存在記憶體洩漏。除了可以通過觀察老年代的記憶體使用情況,還可以觀察每次 GC 的暫停時間(即我們之前學習的 STW,在日誌中可以參考 real所表示的時間),如果暫停總時長佔比特別高,那麼會損壞系統的吞吐量。如果個別 GC 暫停時間過長,則會影響系統的延遲指標。

除了在程式啟動時配置相關引數,還可以在程式執行時使用 JDK 自帶的命令來檢視 GC 資訊。

jstat命令

jstat 命令(幫助文件)可用來列印目標 Java 程序的效能資料。它包括多條子命令,如下所示:

shell % jstat -options -class //列印類載入相關的資料 -compiler //列印即時編譯相關的資料 // 以gc開頭的子命令,列印垃圾回收相關的資料 -gc //顯示和gc相關的堆資訊 -gccapacity //顯示各個代的容量以及使用情況 -gccause //顯示垃圾回收的相關資訊(通-gcutil),同時顯示最後一次或當前正在發生的垃圾回收的誘因 -gcmetacapacity //顯示metaspace的大小 -gcnew // 顯示新生代資訊 -gcnewcapacity //顯示新生代大小和使用情況 -gcold //顯示老年代和永久代的資訊 -gcoldcapacity //顯示老年代的大小 -gcutil //顯示垃圾收集資訊 -printcompilation //列印即時編譯相關的資料

預設情況下,jstat 只會列印一次效能資料。

shell // JDK8 % jstat -gc 67537 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 2560.0 2560.0 0.0 1223.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.001 0 0.000 0.001

實際應用中,我們肯定是想觀察某個程序一段時間內效能資料,這時可以這樣做:將它配置為每隔一段時間列印一次,直至目標 Java 程序終止,或者達到我們所配置的最大列印次數。具體示例如下所示:

sh //JDK8 % jstat -gc 67558 1s 4 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004

上述命令格式如下:

sh jstat -outputOptions [-t] [-hlines] VMID [interval [count]]

  • outputOptions:指的是上文提到的子命令,一個或多個輸出選項;

  • t:將時間戳列顯示為輸出的第一列。時間戳是自目標 JVM 啟動時間以來的時間。

  • lines:每個樣本(輸出行)顯示一個列標題,其中n是一個正整數。預設值為0,即顯示第一行資料的列標題。

  • VMID:虛擬機器識別符號,它是指示目標 JVM 的字串。請參閱虛擬機器識別符號。當監控本地環境的 Java 程序時,VMID 可以簡單理解為 PID。

  • interval:以指定單位、秒 (s) 或毫秒 (ms) 為單位的取樣間隔。預設單位是毫秒。這必須是一個正整數。

  • count:用於指定輸出多少次記錄,預設則會一直列印

在-gc子命令的輸出中,前四列分別為兩個 Survivor 區的容量(Capacity)和已使用量(Utility)。我們可以看到,這兩個 Survivor 區的容量相等,而且始終有一個 Survivor 區的記憶體使用量為 0,關於這點在講解 JVM 垃圾回收時有說過原因。

關於 jstat 命令的輸出結果,想要知道每列代表什麼含義,以及怎麼計算的,其實在 JDK lib 包下的 tools.jar 裡存在一個檔案叫做 jstat_options,這個檔案裡定義了上面的每種型別的輸出結果。比如說 gc。

如上圖所示,我們可以在 IDEA 中開啟該檔案。這裡只擷取部分內容:

如果垃圾收集器使用的是 G1 收集器,輸出結果則變為:

sh //JDK9 % jstat -gc 31678 1s 4 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004

可以看出,S0C 和 S0U 始終為 0,即其中一個 Survivor 容量和使用量始終為 0 。

這是因為,當使用 G1 GC 時,Java 虛擬機器不再設定 Eden 區、Survivor 區,老年代區的記憶體邊界,而是將堆劃分為若干個等長記憶體區域(Region)。

每一個 Region 都可以根據需要,扮演新生代的 Eden 空間,Survivor 空間,或者老年代空間,並且可以在不同區域型別之間來回切換。

換句話說,邏輯上我們只有一個 Survivor 區。當需要遷移 Survivor 區中的資料時(即 Copying GC),我們只需另外申請一個或多個記憶體區域,作為新的 Survivor 區。

因此,Java 虛擬機器決定在使用 G1 GC 時,將所有 Survivor 記憶體區域的總容量以及已使用量存放至 S1C 和 S1U 中,而 S0C 和 S0U 則被設定為 0。

那麼實際應用中,我們使用 jstat 命令如何來分析 Java 程序的效能呢?

我們來下面這樣一段效能輸出結果:

java % jstat -gc 33678 1s 9 Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 200.0 8448.0 8448.0 8448.0 0.0 67712.0 67712.0 169344.0 169344.0 21248.0 20534.3 3072.0 2807.7 34 0.720 658 133.684 134.404 201.0 8448.0 8448.0 8448.0 0.0 67712.0 67712.0 169344.0 169343.2 21248.0 20534.3 3072.0 2807.7 34 0.720 662 134.712 135.432 202.0 8448.0 8448.0 8102.5 0.0 67712.0 67598.5 169344.0 169343.6 21248.0 20534.3 3072.0 2807.7 34 0.720 667 135.840 136.559 203.0 8448.0 8448.0 8126.3 0.0 67712.0 67702.2 169344.0 169343.6 21248.0 20547.2 3072.0 2807.7 34 0.720 669 136.178 136.898 204.0 8448.0 8448.0 8126.3 0.0 67712.0 67702.2 169344.0 169343.6 21248.0 20547.2 3072.0 2807.7 34 0.720 669 136.178 136.898 205.0 8448.0 8448.0 8134.6 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 671 136.234 136.954 206.0 8448.0 8448.0 8134.6 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 671 136.234 136.954 207.0 8448.0 8448.0 8154.8 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 673 136.289 137.009 208.0 8448.0 8448.0 8154.8 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 673 136.289 137.009

我們先檢視第一行的資料:

  • jstat 連線到 JVM 的時間, 是JVM啟動後的 200秒。此資訊從第一行的 “Timestamp” 列得知。
  • 從第一行的 “YGC” 列得知年輕代共執行了34次GC, 由 “FGC” 列得知整個堆記憶體已經執行了 658次 full GC。
  • 年輕代的GC耗時總共為 0.720 秒, 顯示在“YGCT” 這一列。
  • Full GC 的總計耗時為 133.684 秒, 由“FGCT”列得知。 這立馬就吸引了我們的目光, 總的 JVM 執行時間只有 200 秒, 但其中有 66% 的部分被 Full GC 消耗了

再看第二行的資料:

  • 在接下來的一秒內共執行了 4 次 Full GC。參見 “FGC“ 列。
  • 這4次 Full GC 暫停佔用了差不多 1秒的時間(根據 FGCT列的差得知)。與第一行相比,Full GC 耗費了928 毫秒,總時長為 1s, 那麼 Full GC 則佔用了 92.8% 的時間。
  • 根據 “OC 和 “OU” 列得知, 整個老年代的空間169,344.0 KB (“OC“), 在 4 次 Full GC 後依然佔用了 169,344.2 KB (“OU“)。用了 928ms 的時間卻只釋放了 800 位元組的記憶體, 怎麼看都覺得很不正常。

通過前兩行資料可以發現程式存在嚴重的問題,後續的資料可以確定該問題依然存在。

通過 jstat 的輸出能夠快速發現以下問題:

  • 可以比較 Java 程序的啟動時間以及總 GC 時間(GCT 列),或者兩次測量的間隔時間以及總 GC 時間的增量,來得出 GC 時間佔執行時間的比例。就暴露出 GC 開銷過大的問題. 不同系統對 GC 開銷有不同的容忍度, 由效能需求決定, 一般來講, 超過 10% 的 GC 開銷都是有問題的。
  • YGC” 和 “FGC” 列的快速變化往往也是有問題的徵兆。頻繁的 GC 暫停會累積,並導致更多的執行緒停頓(stop-the-world pauses),進而影響吞吐量。
  • 如果看到 “OU” 列中,老年代的使用量約等於老年代的最大容量(OC), 並且不降低的話, 就表示雖然執行了老年代 GC, 但基本上屬於無效GC。

後續我們會繼續學習日誌分析工具,可以更直觀的觀測 GC 狀態,下篇文章我們不見不散。