Java垃圾回收日志解析
1.開啟垃圾回收日志
在運行一個java程序時可以在命令行中加入相應的JVM垃圾回收參數，獲取程序運行時詳細的垃圾回收日志信息。以下是一些大概的參數：
-
-XX:+PrintGC與-verbose:gc 這兩個命令效果都是一樣，打印最基本的回收信息
-
-XX:+PrintGCDetails 可以打印詳細GC信息至控制臺
-
-XX:+PrintGCDateStamps 可以記錄GC發生的詳細時間
-
-Xloggc:{log.dir} 可以把GC輸出至文件，這對長時間服務器GC監控
最常見的幾種垃圾回收參數莫過于以上幾種了，但是并不是全部，仍然有一些進階的垃圾回收參數，比如如下： -
-XX:+PrintHeapAtGC 開關了解堆的更全面的信息
-
-XX:+PrintGCApplicationConcurrentTime 輸出應用程序的執行時間
-
-XX:+PrintGCApplicationStoppedTime 輸出GC造成應用暫停的時間
-
-XX:+PrintReferenceGC 用來跟蹤系統內的(softReference)軟引用，(weadReference)弱引用，(phantomReference)虛引用，顯示引用過程。弱引用，軟引用及虛引用對GC的影響
-
-verbose:class 跟蹤類的加載和卸載，亦可單獨配置-XX:+TraceClassLoading跟蹤類的加載或單獨配置-XX:+TraceClassUnloading
-
-XX:+PrintVMOptions 打印出JVM接受到的顯式（主動配置的）命令行參數
-
-XX:+PrintCommandLineFlags 打印出顯式（主動配置）和隱式（JVM自行設置）的一些參數，其中顯式即等同于-XX:+PrintVMOptions參數設置
-
-XX:+PrintClassHistogram 打印出Java各類實例的數量以及空間大小
以上均是一些JVM參數，大部分可以組合使用，至于其詳細的使用及詳細涵義，可自行搜索查閱。本文主要是分析GC的回收日志，故本文采取的是組合-XX:+PrintGCDetails -Xloggc:{log.file}這兩條命令，即下文中分析的日志是基于此命令組合產生的，存在于log.file文件中，此文中采取的應用程序命令如下。
以上命令采用的ConcMarkSweepGC垃圾回收器，指定此回收器，新生才使用ParNew回收器，老年代使用CMS。-XX:CMSInitiatingOccupancyFraction指定老年代空間使用率達到多少時，進行一次CMS垃圾回收。-XX:NewRatio提供年老代和年輕代的比例大小。默認值是2。詳細的垃圾回收器分類與指定，會在其下文中進行介紹，在此就不多作敘述。
2.垃圾回收日志分析
下圖是摘錄的GC日志示例圖。
如上文看到的第一行，最前面是虛擬機啟動的時間，即運行了523.006秒時產生的垃圾回收。ParNew代表新生代容量為1854272K，括號中的數值。GC回收后占用從165011K降到133039k,耗時0.0305160秒。后面緊跟著的是整個堆內存的回收情況，堆內存從當前4193343k降到4161371k的大小，同理后面括號中指定的是整個堆內存的大小（8035712k），后面3個時間分別是三類回收時間，用戶，系統，以及實際時間，一般只需要看real的時間就夠了，這個只是新生代的回收，可以比對下，新生的回收的內存是165011K-133039k=31972k，這個和實際的堆回收的內存4193343k-4161371k=31972k是保持一致的。不過也有細心的讀者發現，整個堆內存的大小是8035712k與命令行中指定的8048m的堆內存大小不一致，這是什么原因呢？
在這里猜測下，實際的堆內存還包含持久代的，一般說堆的持久代就是說方法區，因為一旦JVM把方法區（類信息，常量池，靜態字段，方法）加載進內存以后，這些內存一般是不會被回收的了。持久代內存指定通過-XX:PermSize–默認是物理內存的1/64以及-XX:MaxPermSize指定–默認是物理內存的1/4。關于，方法區是否屬于堆內存的討論好像一直未停，很多人說持久代屬于非堆，也有人說方法區物理上存在于堆里，而且是在堆的持久代里面；但在邏輯上，方法區和堆是獨立的，在此姑且就認為日志中少掉的部分堆內存是持久代占用了吧。
再往下可以看到，在經歷多次新生代內存回收之后，有一部分關于CMS的內存回收標記。
在虛擬機運行536.547秒時開始使用CMS回收器進行老年代回收。
第一步是初始標記(CMS-initial-mark)階段，這個階段標記由根可以直接到達的對象，標記期間整個應用線程會暫停。此時老年代容量為6181440K，括號中的數值，CMS 回收器在空間占用達到 4403864k時被觸發,這里可以計算下：4403864/6181440=71.24%，已經超過上文配置的70%的回收閾值，故針對年老代進行垃圾回收。后面緊跟的當前堆內存的大小4611534k以及括號中是整個堆內存的大小8035712k。
第二步是 [CMS-concurrent-mark-start]開始并發標記(concurrent-mark-start) 階段，在第一個階段被暫停的線程重新開始運行，由前階段標記過的對象出發，所有可到達的對象都在本階段中標記。 [CMS-concurrent-mark: 0.356/0.356 secs]
代表并發標記階段結束，占用 0.356秒CPU時間，0.356秒墻鐘時間(也包含線程讓出CPU給其他線程執行的時間)
第三步是[CMS-concurrent-preclean-start]開始預清理階段
預清理也是一個并發執行的階段。因為標記和應用線程是并發執行的，因此會有些對象的狀態在標記后會改變，此階段正是解決這個問題。因為之后的Rescan階段也會stop the world，為了使暫停的時間盡可能的小，也需要preclean階段先做一部分工作以節省時間。
第四步是CMS-concurrent-abortable-preclean階段，加入此階段的目的是使cms gc更加可控一些，作用也是執行一些預清理，以減少Rescan階段造成應用暫停的時間。
第五步則是Rescan階段，Stop-the-world 階段,從根及被其引用對象開始，重新掃描 CMS 堆中殘留的更新過的對象。這里重新掃描費時0.0351330秒，處理弱引用對象費時0.0008150秒。后面是重新remark的信息，具體參見第一步，本步驟費時0.037 秒，該階段總體耗時0.04秒。
第六步是[CMS-concurrent-sweep-start]階段，開始并發清理階段，在清理階段，應用線程還在運行。緊接著并發清理完成時間。
最后一步則是[CMS-concurrent-reset-start]開始并發重置，該階段主要重新初始化CMS內部數據結構，以備下一輪 GC 使用，緊接著是該階段的完成時間。
如上就是一個正常的CMS垃圾回收過程，其中可以看到，整個CMS期間還夾雜著2條新生代內存的回收過程也屬于正常。同樣還有不正常的CMS垃圾回收日志，比如：
這段信息顯示ParNew 收集器被請求進行新生代的回收，但收集器并沒有嘗試回收，因為它預計在最糟糕的情況下，CMS老年代中沒有足夠的空間容納新生代的幸存對象。我們把這個失敗稱之為”完全晉升擔保失敗”。因為這樣，并發模式的CMS被中斷同并且在 197.981秒時，Full GC被啟動。這次Full GC，采用標記-清除-整理算法，會發生stop-the-world費時2.3733725秒。CMS 老年代占用從 402978K 降到248977K。為避免并發模式失敗, 通過增加老年代空間大小或者設置參數 CMSInitiatingOccupancyFraction 同時設置UseCMSInitiatingOccupancyOnly為true。參數 CMSInitiatingOccupancyFraction 的值必須謹慎選擇，設置過低會造成頻繁發生 CMS 回收。
有時我們發現，當日志中出現晉升失敗時，老年代還有足夠的空間。這是因為”碎片”，老年代中的可用空間并不連續，而從新生代晉升上來的對象，需要一塊連續的可用空間。CMS 收集器是一種非壓縮收集器，在某種類型的應用中會發生碎片。
總結
以上是生活随笔為你收集整理的Java垃圾回收日志解析的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： dump分析死锁
- 下一篇： 简单排序算法（Java实现）