1. 程式人生 > >《JVM故障診斷指南》之6 —— JVM verbose GC 輸出日誌指南

《JVM故障診斷指南》之6 —— JVM verbose GC 輸出日誌指南

JVM verbose GC 輸出日誌指南

這個部分我們會為你提供詳細的指導文件,是關於如何啟用和閱讀Java 7 HotSpot 虛擬機器verbose gc輸出日誌資料。

我建議你也去編譯和執行後面的例子程式。

我們最近也做了一個Java verbose GC 指導視訊 ,它詳細解釋了整個分析過程

引數和工具
• OS: Windows 7 - 64-bit
• Java VM: Sun Java 7 HotSpot (build 21.0-b17)
• IDE: Eclipse Java EE IDE for Web Developer v4.1

Step #1 – 編譯我們的樣例Java程式

我們建立一個Java樣例程式,讓它載入Java堆並觸發顯式的GC,以便它能產生一些我們感興趣的verbose gc輸出日誌。這個程式輕鬆的在一個靜態的Map資料結構中載入了大約300萬個String例項,並觸發了一個顯式的GC(通過System.gc())。隨後移除了200萬個例項,並在退出前產生了第二個顯式GC。

package org.ph.javaee.tools.jdk7;
import java.util.Map; import java.util.HashMap;
/**
*   JavaHeapVerboseGCTest
*   @author Pierre-Hugues Charbonneau
*
*/
public class JavaHeapVerboseGCTest { private static Map<String, String> mapContainer = new HashMap<String, String>(); /** * @param args */ public static void main(String[] args) { System.out.println("Java 7 HotSpot Verbose GC Test Program v1.0"); System.out.println("Author: Pierre-Hugues Charbonneau"
); System.out.println("http://javaeesupportpatterns.blogspot.com/"); String stringDataPrefix = "stringDataPrefix"; // Load Java Heap with 3 M java.lang.String instances for (int i=0; i<3000000; i++) { String newStringData = stringDataPrefix + i; mapContainer.put(newStringData, newStringData); } System.out.println("MAP size: "+mapContainer.size()); System.gc(); // Explicit GC! // Remove 2 M out of 3 M for (int i=0; i<2000000; i++) { String newStringData = stringDataPrefix + i; mapContainer.remove(newStringData); } System.out.println("MAP size: "+mapContainer.size()); System.gc(); System.out.println("End of program!"); } }

Step #2 – 通過JVM啟動引數啟用 verbose GC

接下來是通過JVM啟動引數設定來啟用verbose gc,並指定了名字和gc日誌檔案儲存路徑。
這裡寫圖片描述

Step #3 – 執行我們的樣例Java程式

此刻正是執行我們的樣例程式併產生JVM verbose GC輸出的時候了。
這裡寫圖片描述

  • Verbose GC 輸出概括分析

現在來回顧生成的GC輸出日誌。

首先,讓我們先看原始資料。從下面可以看到,GC輸出分成了3個主要部分:
• 5個Minor 收集 (年輕代收集)被標記為PSYoungGen
• 2 個Major收集(由System.gc()觸發)被標記為Full GC (系統)
• 每個記憶體區域的Java堆分解分析。 

0.437: [GC [PSYoungGen: 262208K->43632K(305856K)] 
 262208K->137900K(1004928K), 0.1396040 secs] 
 [Times: user=0.45 sys=0.01, real=0.14 secs]

0.785: [GC [PSYoungGen: 305840K->43640K(305856K)] 
 400108K->291080K(1004928K), 0.2197630 secs] 
 [Times: user=0.56 sys=0.03, real=0.22 secs]
1.100: [GC [PSYoungGen: 164752K->43632K(305856K)] 
 412192K->340488K(1004928K), 0.0878209 secs] 
 [Times: user=0.37 sys=0.00, real=0.09 secs] 
1.188: [Full GC (System) [PSYoungGen: 43632K->0K(305856K)] 
 [PSOldGen: 296856K->340433K(699072K)] 
 340488K->340433K(1004928K) 
 [PSPermGen: 1554K->1554K(16384K)], 0.4053311 secs]  [Times: user=0.41 sys=0.00, real=0.40 secs] 

1.883: [GC [PSYoungGen: 262208K->16K(305856K)] 
 602641K->340449K(1004928K), 0.0326756 secs] 
 [Times: user=0.09 sys=0.00, real=0.03 secs]
2.004: [GC [PSYoungGen: 92122K->0K(305856K)] 
 432556K->340433K(1004928K), 0.0161477 secs] 
 [Times: user=0.06 sys=0.00, real=0.02 secs] 
2.020: [Full GC (System) [PSYoungGen: 0K->0K(305856K)] 
 [PSOldGen: 340433K->125968K(699072K)] 
 340433K->125968K(1004928K) 
 [PSPermGen: 1555K->1555K(16384K)], 0.2302415 secs]  [Times: user=0.23 sys=0.00, real=0.23 secs] 

Heap
PSYoungGen total 305856K, used 5244K [0x3dac0000, 0x53010000, 0x53010000)  eden space 262208K, 2% used [0x3dac0000,0x3dfdf168,0x4dad0000)  from space 43648K, 0% used [0x4dad0000,0x4dad0000,0x50570000)  to space 43648K, 0% used [0x50570000,0x50570000,0x53010000)
PSOldGen total 699072K, used 125968K [0x13010000, 0x3dac0000, 0x3dac0000)  object space 699072K, 18% used [0x13010000,0x1ab140a8,0x3dac0000) PSPermGen total 16384K, used 1560K [0x0f010000, 0x10010000, 0x13010000)  object space 16384K, 9% used [0x0f010000,0x0f1960b0,0x10010000)
  • Verbose GC 資料的解釋以及次序

從verbose GC的輸出你可以看到,老年代空間在初始載入了300萬字符串例項到HashMap後達到了340M。在移除了200萬字符串例項後下降到了126M。

現在看下面的說明和圖片快照,它是關於如何詳細的閱讀每個Java堆空間GC輸出資料。

年輕代空間分析

這裡寫圖片描述

年老代空間分析

這裡寫圖片描述

持久代空間分析

這裡寫圖片描述

Java 堆分解分析

這裡寫圖片描述
希望這個樣例Java程式和verbose GC輸出分析能幫助你瞭解如何閱讀和解釋這些關鍵資料。