淺析JVM中的GC日志

目錄

　　一、GC日志的格式分析

　　二、運行時開啟GC日志

 

一、GC日志的格式分析

在講述GC日志之前，我們先來運行下面這段代碼

package com.example;

public class TestMinorGC {
    private static final int _1MB = 1024*1024;

    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;

        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main() {
        testAllocation();
    }
}

 

配置如下的虛擬機參數運行上述程序：

vm option: -Xms20M -Xmx20M -Xmn10M -verbose:gc -XX:+PrintGCDetails -XX:SurvivorRatio=8

注： -XX:+PrintGCDetails參數用於告訴虛擬機在發生垃圾收集行為時打印內存回收日志，並且在進程退出的時候輸出當前內存的各區域分配情況。

 

最終，程序輸出：

[GC [PSYoungGen: 7307K->480K(9216K)] 7307K->6624K(19456K), 0.0072860 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
[Full GC [PSYoungGen: 480K->0K(9216K)] [ParOldGen: 6144K->6476K(10240K)] 6624K->6476K(19456K) [PSPermGen: 2920K->2919K(21504K)], 0.0178620 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
[Full GC [PSYoungGen: 4354K->1024K(9216K)] [ParOldGen: 6476K->9536K(10240K)] 10831K->10560K(19456K) [PSPermGen: 2921K->2921K(21504K)], 0.0139610 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
[Full GC [PSYoungGen: 7339K->0K(9216K)] [ParOldGen: 9536K->4419K(10240K)] 16876K->4419K(19456K) [PSPermGen: 3004K->3004K(21504K)], 0.0120490 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
Heap
 PSYoungGen      total 9216K, used 4190K [0x00000007ff600000, 0x0000000800000000, 0x0000000800000000)
  eden space 8192K, 51% used [0x00000007ff600000,0x00000007ffa17a18,0x00000007ffe00000)
  from space 1024K, 0% used [0x00000007ffe00000,0x00000007ffe00000,0x00000007fff00000)
  to   space 1024K, 0% used [0x00000007fff00000,0x00000007fff00000,0x0000000800000000)
 ParOldGen       total 10240K, used 4419K [0x00000007fec00000, 0x00000007ff600000, 0x00000007ff600000)
  object space 10240K, 43% used [0x00000007fec00000,0x00000007ff050eb0,0x00000007ff600000)
 PSPermGen       total 21504K, used 3010K [0x00000007f9a00000, 0x00000007faf00000, 0x00000007fec00000)
  object space 21504K, 14% used [0x00000007f9a00000,0x00000007f9cf0bf8,0x00000007faf00000)

程序輸出一大段看不懂的文字，這些就是本文要講述的GC日志，下面來介紹一下GC日志的格式：

（1）GC, Full GC說明了這次垃圾收集的停頓類型，而不是用來區分新生代GC還是老年代GC。如果有"Full"，則表示這次GC發生了"Stop-The-World"。

（2）PSYoungGen, ParOldGen，PSPermGen表示GC發生的區域，這里顯示的區域名稱與使用的GC收集器密切相關，不同收集器對於不同區域所顯示的名稱可能不同。

（3）接下來"7307K->480K(9216K)"的含義是：GC前該內存區域已使用容量 -> GC后該內存區域已使用容量(該內存區域的總容量)。

（4）"7307K->6624K(19456K)"的含義是：GC前Java堆已使用容量 -> GC后Java堆已使用容量（Java堆總容量） 。

（5）"0.0072860 secs" 表示該內存區域GC所占用的時間，單位是秒。

（6）[Times: user=0.01 sys=0.01, real=0.00 secs]：分別表示用戶態消耗CPU時間, 內核態消耗CPU時間，操作從開始到結束所經過的牆鍾時間。

　　PS，CPU時間與牆鍾時間的區別是：牆鍾時間包括各種非運算的等待耗時，例如等待磁盤I/O、等待線程阻塞等；而CPU時間不包括這些耗時。

　　當系統有多cpu或者多核的話，多線程操作會疊加這些CPU時間，所以有時看到user或sys時間超過real時間是完全正常的。

 

二、運行時開啟GC日志

我們經常會遇到JVM運行時出錯的情況。若能在啟動時加入一些啟動選項（startup option），便可以獲取與bug相關的重要線索，從而有希望根治它們。但在實際操作時，我們總是忘記添加-XX:+HeapDumpOnOutOfMemoryError 或 -XX:+PrintGCDetails這樣必要的flag。

每當面對如此窘境，我們只能關閉JVM，修改啟動參數（startup parameter），然后默默祈禱，希望問題場景（problematic situation）能在重啟之后得以重現。這種方法偶爾奏效，在場景重現后你或許還能收集到足夠的證據，以便動手根治潛在的問題。

不難看出，前文所述的方法問題顯著——你必須執行一次額外的重啟才能加入那煩人的debug選項，而不能借助中斷（outage）實現。事實上，JDK bundle提供了一種可行的變通方案，如果將之收入麾下，偶爾還能從中獲益。

 

jinfo

在JDK bundle中隱藏着一個精悍的小工具——jinfo。作為一個命令行工具，jinfo用於收集正在運行的Java進程的配置信息。jinfo吸引眼球的地方在於，它能通過-flag選項動態修改指定的Java進程中的某些JVM flag的值。雖然這樣的flag數量有限，但它們偶爾能夠幫助到你。通過以下的命令你便能看到JVM中哪些flag可以被jinfo動態修改：

my-precious me$ java -XX:+PrintFlagsFinal -version|grep manageable
     intx CMSAbortablePrecleanWaitMillis            = 100                                 {manageable}
     intx CMSWaitDuration                           = 2000                                {manageable}
     bool HeapDumpAfterFullGC                       = false                               {manageable}
     bool HeapDumpBeforeFullGC                      = false                               {manageable}
     bool HeapDumpOnOutOfMemoryError                = false                               {manageable}
     ... cut for brevity ...
     bool PrintGC                                   = false                               {manageable}
     bool PrintGCDateStamps                         = false                               {manageable}
     bool PrintGCDetails                            = false                               {manageable}
     bool PrintGCTimeStamps                         = false                               {manageable}

通過選項-XX:+PrintFlagsFinal可以列出所有的JVM flag，而其中的標注為manageable 的flag則是值得我們關注的部分。這些flag可通過JDK management interface（-XX:+PrintFlagsFinal）動態修改。雖然在JConsole中也能查到與其十分相似的MBean。但在我看來，以命令行的方式查看它們更加的便捷。

 

如何使用jinfo

讓我們通過實戰來學習如何使用jinfo。在下面的例子中，我們將在一個正在運行的JVM中動態開啟GC日志功能：

my-precious me$ jps
12278 HighAllocationRate
12279 Jps
12269 JConsole
my-precious me$ jinfo -flag +PrintGCDetails 12278
my-precious me$ jinfo -flag +PrintGC 12278
my-precious me$

在jinfo中需要打開-XX:+PrintGC和 -XX:+PrintGCDetails兩個選項才能開啟GC日志，這與用命令行參數的方式實現有着細微的差別——如果你通過啟動腳本（startup script）來設置參數，僅需-XX:+PrintGCDetails即可，因為-XX:+PrintGC會被自動打開。

不過，從standard output的結果來看，PID為12278的進程的GC日志的確能夠滾動地顯示出來：

...
[GC (Allocation Failure) [PSYoungGen: 876416K->102624K(909312K)] 1094420K->320820K(1161216K), 0.2173131 secs] [Times: user=0.74 sys=0.00, real=0.22 secs] 
...
[GC (Allocation Failure) [PSYoungGen: 890304K->102240K(917504K)] 1108924K->320956K(1169408K), 0.2446639 secs] [Times: user=0.82 sys=0.01, real=0.25 secs] 
...

同理，若想關閉GC日志功能，只需要執行jinfo -flag -PrintGCDetails 12278和 jinfo -flag -PrintGC 12278命令即可。