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

-Xloggc:gc.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

 

 

這里使用如下的參數來進行日志的打印：

-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