在JVM執行時開啟GC日誌

ImportNew發表於2015-04-27

我們經常會遇到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 12278jinfo -flag -PrintGC 12278命令即可。

在我看來,學會使用jinfo,只能讓你在故障排除的工作中少花一到兩天的時間。若打一開始就使用Plumbr這類效能監控工具,你可能從未有過這樣的煩惱。

相關文章