Java GC日誌檢視,GC日誌時間分析
Java中的GC有哪幾種類型?
引數 |
描述 |
UseSerialGC |
虛擬機器執行在Client模式的預設值,開啟此開關引數後, 使用Serial+Serial Old收集器組合進行垃圾收集。 |
UseParNewGC |
開啟此開關引數後,使用ParNew+Serial Old收集器組合進行垃圾收集。 |
UseConcMarkSweepGC |
開啟此開關引數後,使用ParNew+CMS+Serial Old收集器組合進行垃圾收集。Serial Old作為CMS收集器出現Concurrent Mode Failure的備用垃圾收集器。 |
UseParallelGC |
虛擬機器執行在Server模式的預設值,開啟此開關引數後,使用Parallel Scavenge+Serial Old收集器組合進行垃圾收集。 |
UseParallelOldGC |
開啟此開關引數後,使用Parallel Scavenge+Parallel Old收集器組合進行垃圾收集。 |
在Java程式啟動完成後,通過jps觀察程序來查詢到當前執行的java程序,使用
jinfo –flag UseSerialGC 程序
的方式可以定位其使用的gc策略,因為這些引數都是boolean型的常量,如果使用該種gc策略會出現+號,否則-號。
使用-XX:+上述GC策略可以開啟對應的GC策略。
GC日誌檢視
可以通過在java命令種加入引數來指定對應的gc型別,列印gc日誌資訊並輸出至檔案等策略。
GC的日誌是以替換的方式(>)寫入的,而不是追加(>>),如果下次寫入到同一個檔案中的話,以前的GC內容會被清空。
對應的引數列表
-XX:+PrintGC 輸出GC日誌 -XX:+PrintGCDetails 輸出GC的詳細日誌 -XX:+PrintGCTimeStamps 輸出GC的時間戳(以基準時間的形式) -XX:+PrintGCDateStamps 輸出GC的時間戳(以日期的形式,如 2013-05-04T21:53:59.234+0800) -XX:+PrintHeapAtGC 在進行GC的前後打印出堆的資訊 -Xloggc:../logs/gc.log 日誌檔案的輸出路徑
例如:eclipse.ini中配置下面程式碼啟動後會在同一目錄下生成gc.log
1 2 3 |
|
這裡使用如下的引數來進行日誌的列印:
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs
對於新生代回收的一行日誌,其基本內容如下:
2014-07-18T16:02:17.606+0800: 611.633: [GC 611.633: [DefNew: 843458K->2K(948864K), 0.0059180 secs] 2186589K->1343132K(3057292K), 0.0059490 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
其含義大概如下:
2014-07-18T16:02:17.606+0800(當前時間戳): 611.633(時間戳): [GC(表示Young GC) 611.633: [DefNew(單執行緒Serial年輕代GC): 843458K(年輕代垃圾回收前的大小)->2K(年輕代回收後的大小)(948864K(年輕代總大小)), 0.0059180 secs(本次回收的時間)] 2186589K(整個堆回收前的大小)->1343132K(整個堆回收後的大小)(3057292K(堆總大小)), 0.0059490 secs(回收時間)] [Times: user=0.00(使用者耗時) sys=0.00(系統耗時), real=0.00 secs(實際耗時)]
老年代回收的日誌如下:
2014-07-18T16:19:16.794+0800: 1630.821: [GC 1630.821: [DefNew: 1005567K->111679K(1005568K), 0.9152360 secs]1631.736: [Tenured: 2573912K->1340650K(2574068K), 1.8511050 secs] 3122548K->1340650K(3579636K), [Perm : 17882K->17882K(21248K)], 2.7854350 secs] [Times: user=2.57 sys=0.22, real=2.79 secs]
gc日誌中的最後貌似是系統執行完成前的快照:
Heap def new generation total 1005568K, used 111158K [0x00000006fae00000, 0x000000073f110000, 0x0000000750350000) eden space 893888K, 12% used [0x00000006fae00000, 0x0000000701710e90, 0x00000007316f0000) from space 111680K, 3% used [0x0000000738400000, 0x000000073877c9b0, 0x000000073f110000) to space 111680K, 0% used [0x00000007316f0000, 0x00000007316f0000, 0x0000000738400000) tenured generation total 2234420K, used 1347671K [0x0000000750350000, 0x00000007d895d000, 0x00000007fae00000) the space 2234420K, 60% used [0x0000000750350000, 0x00000007a2765cb8, 0x00000007a2765e00, 0x00000007d895d000) compacting perm gen total 21248K, used 17994K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000) the space 21248K, 84% used [0x00000007fae00000, 0x00000007fbf92a50, 0x00000007fbf92c00, 0x00000007fc2c0000) No shared spaces configured.
GC日誌的離線分析
可以使用一些離線的工具來對GC日誌進行分析,比如sun的gchisto(https://java.net/projects/gchisto),gcviewer(https://github.com/chewiebug/GCViewer),這些都是開源的工具,使用者可以直接通過版本控制工具下載其原始碼,進行離線分析。
下面就已gcviewer為例,簡要分析一下gc日誌的離線分析,gcviewer原始碼工程是maven結構的,可以直接用maven進行package,這裡編譯的是1.34版本,本版本的快照已經上傳至附件中。
需要說明的是,gcviewer支援多種引數生成的gc日誌,直接通過java –jar的方式執行,載入生成的gc日誌即可:
------------------------第二種理解-----------------------
首先,給出一個日誌輸出的例子:
引數設定為:
-XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy -XX:SurvivorRatio=8 -XX:NewSize=10M -XX:MaxNewSize=10M
引數解釋:
-XX:+PrintGCDetails 啟用日誌
-XX:-UseAdaptiveSizePolicy 禁用動態調整,使SurvivorRatio可以起作用
-XX:SurvivorRatio=8 設定Eden:Survivior=8
-XX:NewSize=10M -XX:MaxNewSize=10M 設定整個新生代的大小為10M
預設垃圾收集器為:Parallel Scavenge
輸出結果為:
[GC [PSYoungGen: 4423K->320K(9216K)] 4423K->320K(58880K), 0.0011900 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[Full GC (System) [PSYoungGen: 320K->0K(9216K)] [ParOldGen: 0K->222K(49664K)] 320K->222K(58880K) [PSPermGen: 2458K->2456K(21248K)], 0.0073610 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Heap
PSYoungGen total 9216K, used 491K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
eden space 8192K, 6% used [0x00000000ff600000,0x00000000ff67af50,0x00000000ffe00000)
from space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
to space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
ParOldGen total 49664K, used 222K [0x00000000c5800000, 0x00000000c8880000, 0x00000000ff600000)
object space 49664K, 0% used [0x00000000c5800000,0x00000000c58378a0,0x00000000c8880000)
PSPermGen total 21248K, used 2466K [0x00000000c0600000, 0x00000000c1ac0000, 0x00000000c5800000)
object space 21248K, 11% used [0x00000000c0600000,0x00000000c0868b48,0x00000000c1ac0000)
前半段分析:
GC (minor )日誌
Full GC 日誌
後半段分析:
對照上面的圖,GC日誌中的PSYoungGen(PS是指Parallel Scavenge)為Eden+FromSpace,而整個YoungGeneration為Eden+FromSpace+ToSpace。
我們設定的新生代大小為10240K,這包括9216K大小的PSYoungGen和1024K大小的ToSpace。其中,PSYoungGen中的Eden:FromSpace為8:1,
這包括8192K的Eden和1024K的FromSpace。
關於老年代和永久代的輸出比較簡單,不再詳述。
更詳細描述參見官方文件:http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html
最後注意,如果新生代的空間不能剛好按比例劃分,則可能有一定的誤差。比如,將上述的引數中SurvivorRatio改為10,則輸出如下:
[GC [PSYoungGen: 4439K->320K(9408K)] 4439K->320K(59072K), 0.0010120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System) [PSYoungGen: 320K->0K(9408K)] [ParOldGen: 0K->222K(49664K)] 320K->222K(59072K) [PSPermGen: 2458K->2456K(21248K)], 0.0095710 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
Heap
PSYoungGen total 9408K, used 514K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
eden space 8576K, 6% used [0x00000000ff600000,0x00000000ff680b78,0x00000000ffe60000)
from space 832K, 0% used [0x00000000ffe60000,0x00000000ffe60000,0x00000000fff30000)
to space 832K, 0% used [0x00000000fff30000,0x00000000fff30000,0x0000000100000000)
ParOldGen total 49664K, used 222K [0x00000000c5800000, 0x00000000c8880000, 0x00000000ff600000)
object space 49664K, 0% used [0x00000000c5800000,0x00000000c58378a0,0x00000000c8880000)
PSPermGen total 21248K, used 2466K [0x00000000c0600000, 0x00000000c1ac0000, 0x00000000c5800000)
object space 21248K, 11% used [0x00000000c0600000,0x00000000c0868b48,0x00000000c1ac0000)
可以看到新生代的相關數值是有一定誤差的
GC日誌分析
在GC日誌裡,一條完整的GC日誌記錄最後,會帶有本次GC所花費的時間,如下面這一條新生代GC:
[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), .0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
注意到日誌中時間分為了三塊:user
,sys
,和real
,三者的區別和含義如下:
-
real
:指的是在此次GC事件中所花費的總時間; -
user
:指的是CPU工作在使用者態所花費的時間; -
sys
:指的是CPU工作在核心態所花費的時間。
user
+sys
就是CPU花費的實際時間,注意這個值統計了所有CPU上的時間,如果程序工作在多執行緒的環境下,這個值是會超出 real 所記錄的值的,即user
+sys
>=real
對於GC事件來說,無論是 Minor GC 還是 Full GC 的過程,都存在併發的GC演算法,如新生代的ParNew,老年代的ParallelOld,GC過程中工作負載是由多個執行緒共同完成的,這也就意味著使用這些GC演算法時,GC日誌中我們應該觀察到:user
+sys
>real
。譬如說:配置了ParNew
且併發數為5的GC活動(-XX:+UseParNewGC -XX:ParallelGCThreads=5
)中,如果user
+sys
的值為2 seconds,那麼real
的時間 就近似為400ms(2 seconds / 5)
。
場景1:
[Times: user=11.53 sys=1.38, real=1.03 secs]
垃圾回收過程是通過併發執行,因此user
+sys
遠大於real
。
場景2:
[Times: user=0.09 sys=0.00, real=0.09 secs]
因為使用了序列的垃圾回收期,所以時間應該是user
和real
相等。
場景3:
[Times: user=0.20 sys=0.01, real=18.45 secs]
這是一個異常的示例,可以看到real
所顯示的時間 遠 大於user
+sys
。一般來說,如果觀察到GC日誌裡多次出現了場景3所示的日誌,這表明JVM的GC 過程存在某些問題(等待計算資源),原因可能是下面這兩種:
- 頻繁的IO操作
- 缺乏CPU資源
繁忙的I/O操作
當程式存在繁忙的I/O操作(網路IO或磁碟IO)時,會讓real
時間大幅上升。因為在記錄GC日誌的時候,你的程式進行了磁碟讀寫,如果同一時間其他IO操作較重,則此時GC事件會延遲,進而影響了最終的real
的值。注意,如果程式本身不存在的頻繁的IO操作,同一機器上其他程序的頻繁IO也會影響real
的最終結果。Linux環境下可以使用sar
監視機器上的I/O,eg.sar -d -p 1
,如果頻繁的IO操作的確存在,可以通過下面兩種方式改進:
- 優化程式本身的IO操作邏輯;
- 消除其他程序帶來的IO影響。
缺乏CPU資源
當程式本身是CPU密集型應用,或機器上其他程序佔用了大量的CPU計算資源,則有可能會出現分配不到 CPU cycles的情況,這會讓程式掛起,GC所花費的實際時間也將遠大於user
+sys
的值。
可以使用top
命令觀察一下 程序的CPU利用率,同時輔以Profiler工具統計一段時間內程序的狀態分佈。如果的確是CPU資源不足,解決方法無法下面幾種:
- 優化程式內部的執行緒使用,確保無冗餘的執行緒配置;
- 增加虛擬機器或容器的CPU配置,提升機器總的計算能力。
轉載於:https://blog.csdn.net/xiaocai9999/article/details/88368395