jvm 日誌輸出說明

轉帖地址：http://www.iteye.com/topic/603347

在大型的java運用中，要進行程式調優，指定一個合適的記憶體回收機制是必不可少的，那如何可確定某gc是否使得程式最佳化呢？我們可以查看jvm列印出的gc日誌來分析，並做出進一步最佳化，而目前並沒有一篇文章明確的指明java中各種gc演算法列印出日誌的格式，以及如何閱讀。所以接下來本文將試著邊介紹各種記憶體回收機制邊解釋該回收機制下log的格式。

1，垃圾收集演算法
 1.1 引用計數法（Reference Counting Collector）
    系統記錄對象被應用的次數，當應用次數為0時，就可以將該對象所佔記憶體回收。該演算法可以不用暫停運用，但缺點是無法解決重複運用的問題。所以java並沒有提供此類記憶體回收行程。
  1.2  tracing演算法(Tracing Collector)
       tracing演算法的垃圾收集器從根集開始掃描，識別出哪些對象可達，哪 些對象不可達，並用某種方式標記可達對象。
  1.2.1 複製（ Copying ）演算法
     複製演算法將堆等分成2個地區，一個地區含有現在的資料對象(ToSpace)，而另一個地區包含廢棄的資料(FromSpace)。複製演算法將存活的對象從FromSpace複製到ToSpace，然後切換Fromspace和ToSpace的指標，以前的FromSpace變為現在的ToSpace地區。
  1.2.2 標記－整理（ Mark-Compact ）演算法
       
  1.2.3 標記-清除（Mark-Sweep）
Using the -XX flags for our collectors for jdk6,

• UseSerialGC is "Serial" + "Serial Old"
• UseParNewGC is "ParNew" + "Serial Old"
  
• UseConcMarkSweepGC is "ParNew" + "CMS" + "Serial Old". "CMS" is used most of the time to collect the tenured generation. "Serial Old" is used when a concurrent mode failure occurs.
  
• UseParallelGC is "Parallel Scavenge" + "Serial Old"
  
• UseParallelOldGC is "Parallel Scavenge" + "Parallel Old" 

 

SerailGC

1，Serial Young GC 
0.246: [GC 0.246: [DefNew: 1403K->105K(1984K), 0.0109275 secs] 1403K->1277K(6080K), 0.0110143 secs] 
2, Serial Olg Gc

1.133: [GC 1.133: [DefNew: 960K->64K(960K), 0.0012208 secs]1.135: [Tenured: 7334K->7142K(7424K), 0.0213756 secs] 7884K->7142K(8384K), [Perm : 364K->364K(12288K)], 0.0226997 secs] [Times:
user=0.01 sys=0.00, real=0.02 secs]

 

Parrallel GC serailGC的適應muti Core的加強版，就是在minorGC時候採用並行的進行收集，而fullGC並沒有改變

Parralllel Compacting GC
在parrallelGC的基礎上將fullgc也變為並發的了With the parallel compacting collector, the old and permanent generations are collected in a stop-theworld,mostly parallel fashion with sliding compaction. The collector utilizes three phases. First,
each generation is logically divided into fixed-sized regions. In the marking phase, the initial set of live objects directly reachable from the application code is divided among garbage collection threads, and then all live objects are marked in parallel.
As an object is identified as live, the data for the region it is in is updated with information about the size and location of the object.備忘 待翻譯

 

Concurrent Mark-Sweep (CMS) Collector  有一種需求是應用的相應時間比應用的吞吐重要，為了滿足這種需求，jvm提供了該情境下的垃圾收集器CMS，使用該垃圾收集器的時候minorGC和ParralelGC當中採用的一樣，只是在老生代更換了不同的演算法。

CMS將老生代的回收分為4個階段 其中只有2個階段是要stop-the-world的,而其餘階段是不需要的，因此降低了系統暫停時間，缺點是在其餘的2個階段會更應用搶jvm資源。

 

  

從可以看出，CMS的運行過程。

A collection cycle for the CMS collector starts with a short pause, called the initial mark, thatidentifies the initial set of live objects directly reachable from the application code. Then,during the concurrent marking phase, the collector marks all live objects that are transitivelyreachable from this set. Because the application is running and updating reference fields while the marking phase is taking place, not all live objects are guaranteed to be marked at the end of the
concurrent marking phase. To handle this, the application stops again for a second pause, called remark, which finalizes marking by revisiting any objects that were modified during the concurrent marking phase. Because the remark pause is more substantial
than the initial mark, multiple threads are run in parallel to increase its efficiency.備忘 待翻譯

Concurrent Mark-Sweep GC log format：

Full GC 被調用的出現情況 

promotion failed(
mark-sweep-compact stop-the-world )ParNew (promotion failed):  當老生代空閑空間存在片段，導致沒有足夠大的連續空間開存放新生代對象的升級時，機會觸發promotion
failed。此時調用一個Mark-Compact 垃圾收集器是很有必要的。（預設採用 Serial Old GC）

106.641: [GC 106.641: [ParNew (promotion failed): 14784K->14784K(14784K), 0.0370328 secs]106.678:
[CMS106.715: [CMS-concurrent-mark: 0.065/0.103 secs] [Times: user=0.17 sys=0.00, real=0.11 secs]

 (concurrent mode failure): 41568K->27787K(49152K), 0.2128504 secs] 52402K->27787K(63936K), [CMS Perm : 2086K->2086K(12288K)], 0.2499776 secs] [Times: user=0.28
sys=0.00, real=0.25 secs]

full promotion guarantee failure(concurrent mode failure):
當記憶體回收演算法預測在下一次Conc-Mark-Sweep演算法調用之前，老生代的空餘空間將會被系統佔用光。為瞭解決這一問題，記憶體回收演算法進入conccurent mode failure狀態，調用一個 stop-the-world（serail Old GC）來清理系統Heap。

eg:為了觸發這種情況 我們先分配64m記憶體給jvm，然後新生代和老年代的佔用比例為7，即老年代用了7*8=58 觸發concurrent mode failure的情況:

 

 

public class FullPromotionGuaranteeFailure
{
    public static void main(String[] args)
    {
    List<byte[]> bytesList = new ArrayList<byte[]>();
    for (int i = 0; i < 7 * 8 * 1024; i++)
    {
        bytesList.add(new byte[1024]);
    }
    
    //bytesList = null; 沒有必要的 gc會知道函數裡面變數是否還會被引用
    byte[] bytes = new byte[16 * 1024 * 1024];
    String.valueOf(bytes[0]);
    }
}

運行時JVM參數：
-Xmx64m -Xms64m -XX:NewRatio=7 -XX:MaxTenuringThreshold=0 -verbose:gc  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+UseConcMarkSweepGC
-Xloggc:full-promotion-guarantee-failure.log
full-promotion-guarantee-failure.log 內容

0.195: [GC 0.195: [ParNew: 2986K->2986K(8128K), 0.0000083 secs]0.195: [CMS0.212: [CMS-concurrent-preclean: 0.011/0.031 secs] [Times: user=0.03 sys=0.02, real=0.03 secs]

 (concurrent mode failure): 56046K->138K(57344K), 0.0271519 secs] 59032K->138K(65472K), [CMS Perm : 2079K->2078K(12288K)], 0.0273119 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 

 

 

調用Serial Old GC 是費時並且暫停了整個應用，這顯然不是我們想看到的。為了 避免辦法出現（concurrent mode failure）這種情況,可以參考bluedavy的該篇blogGC
策略的調優

Stop-the-world GC happens when a JNI critical section is released. Here again the young generation collection failed due to "full promotion guarantee failure" and then the Full GC was invoked.

283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000615 secs]

826554K->826554K(1048384K), 0.0003259 secs]
GC locker: Trying a full collection because scavenge failed

參考連結：

1. Java SE 6 HotSpot[tm] Virtual Machine Garbage Collection Tuning
2. Turbo-charging Java HotSpot
   Virtual Machine, v1.4.x to Improve the Performance and Scalability of Application Servers
3. Understanding Concurrent Mark Sweep Garbage Collector Logs
4. What the Heck's a Concurrent Mode?
5. https://java.sun.com/j2se/reference/...whitepaper.pdf 
6. http://blogs.sun.com/jonthecollector...the_sum_of_the 
7. http://blogs.sun.com/jonthecollector...t_the_heck_s_a