在JVM運行時如何開啟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命令即可。

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