Java垃圾回收日志解析

發(fā)表于 討論求助 2023-05-10 14:56:27

1.開啟垃圾回收日志

在運行一個java程序時可以在命令行中加入相應(yīng)的JVM垃圾回收參數(shù)，獲取程序運行時詳細的垃圾回收日志信息。以下是一些大概的參數(shù)：

  • -XX:+PrintGC與-verbose:gc 這兩個命令效果都是一樣，打印最基本的回收信息

  • -XX:+PrintGCDetails 可以打印詳細GC信息至控制臺

  • -XX:+PrintGCDateStamps 可以記錄GC發(fā)生的詳細時間

  • -Xloggc:{log.dir} 可以把GC輸出至文件，這對長時間服務(wù)器GC監(jiān)控

最常見的幾種垃圾回收參數(shù)莫過于以上幾種了，但是并不是全部，仍然有一些進階的垃圾回收參數(shù)，比如如下：

  • -XX:+PrintHeapAtGC 開關(guān)了解堆的更全面的信息

  • -XX:+PrintGCApplicationConcurrentTime 輸出應(yīng)用程序的執(zhí)行時間

  • -XX:+PrintGCApplicationStoppedTime 輸出GC造成應(yīng)用暫停的時間

  • -XX:+PrintReferenceGC 用來跟蹤系統(tǒng)內(nèi)的(softReference)軟引用，(weadReference)弱引用，(phantomReference)虛引用，顯示引用過程。弱引用，軟引用及虛引用對GC的影響

  • -verbose:class 跟蹤類的加載和卸載，亦可單獨配置-XX:+TraceClassLoading跟蹤類的加載或單獨配置-XX:+TraceClassUnloading

  • -XX:+PrintVMOptions 打印出JVM接受到的顯式（主動配置的）命令行參數(shù)

  • -XX:+PrintCommandLineFlags 打印出顯式（主動配置）和隱式（JVM自行設(shè)置）的一些參數(shù)，其中顯式即等同于-XX:+PrintVMOptions參數(shù)設(shè)置

  • -XX:+PrintClassHistogram 打印出Java各類實例的數(shù)量以及空間大小

以上均是一些JVM參數(shù)，大部分可以組合使用，至于其詳細的使用及詳細涵義，可自行搜索查閱。本文主要是分析GC的回收日志，故本文采取的是組合-XX:+PrintGCDetails -Xloggc:{log.file}這兩條命令，即下文中分析的日志是基于此命令組合產(chǎn)生的，存在于log.file文件中，此文中采取的應(yīng)用程序命令如下。

/usr/jdk64/jdk1.7.0_67/bin/java ?-XX:NewRatio=3 -XX:+UseConcMarkSweepGC -XX:-UseGCOverheadLimit -XX:CMSInitiatingOccupancyFraction=70 ? ?-XX:+PrintGCDetails -Xloggc:/var/lib/ambari-server/gc.log -Xms8048m -Xmx16384m Application

  • 1

以上命令采用的ConcMarkSweepGC垃圾回收器，指定此回收器，新生才使用ParNew回收器，老年代使用CMS。-XX:CMSInitiatingOccupancyFraction指定老年代空間使用率達到多少時，進行一次CMS垃圾回收。-XX:NewRatio提供年老代和年輕代的比例大小。默認值是2。詳細的垃圾回收器分類與指定，會在其下文中進行介紹，在此就不多作敘述。

2.垃圾回收日志分析

下圖是摘錄的GC日志示例圖。?

如上文看到的第一行，最前面是虛擬機啟動的時間，即運行了523.006秒時產(chǎn)生的垃圾回收。ParNew代表新生代容量為1854272K，括號中的數(shù)值。GC回收后占用從165011K降到133039k,耗時0.0305160秒。后面緊跟著的是整個堆內(nèi)存的回收情況，堆內(nèi)存從當(dāng)前4193343k降到4161371k的大小，同理后面括號中指定的是整個堆內(nèi)存的大小（8035712k），后面3個時間分別是三類回收時間，用戶，系統(tǒng)，以及實際時間，一般只需要看real的時間就夠了，這個只是新生代的回收，可以比對下，新生的回收的內(nèi)存是165011K-133039k=31972k，這個和實際的堆回收的內(nèi)存4193343k-4161371k=31972k是保持一致的。不過也有細心的讀者發(fā)現(xiàn)，整個堆內(nèi)存的大小是8035712k與命令行中指定的8048m的堆內(nèi)存大小不一致，這是什么原因呢？?
在這里猜測下，實際的堆內(nèi)存還包含持久代的，一般說堆的持久代就是說方法區(qū)，因為一旦JVM把方法區(qū)（類信息，常量池，靜態(tài)字段，方法）加載進內(nèi)存以后，這些內(nèi)存一般是不會被回收的了。持久代內(nèi)存指定通過-XX:PermSize–默認是物理內(nèi)存的1/64以及-XX:MaxPermSize指定–默認是物理內(nèi)存的1/4。關(guān)于，方法區(qū)是否屬于堆內(nèi)存的討論好像一直未停，很多人說持久代屬于非堆，也有人說方法區(qū)物理上存在于堆里，而且是在堆的持久代里面；但在邏輯上，方法區(qū)和堆是獨立的，在此姑且就認為日志中少掉的部分堆內(nèi)存是持久代占用了吧。?
再往下可以看到，在經(jīng)歷多次新生代內(nèi)存回收之后，有一部分關(guān)于CMS的內(nèi)存回收標(biāo)記。?
在虛擬機運行536.547秒時開始使用CMS回收器進行老年代回收。?
第一步是初始標(biāo)記(CMS-initial-mark)階段，這個階段標(biāo)記由根可以直接到達的對象，標(biāo)記期間整個應(yīng)用線程會暫停。此時老年代容量為6181440K，括號中的數(shù)值，CMS 回收器在空間占用達到 4403864k時被觸發(fā),這里可以計算下：4403864/6181440=71.24%，已經(jīng)超過上文配置的70%的回收閾值，故針對年老代進行垃圾回收。后面緊跟的當(dāng)前堆內(nèi)存的大小4611534k以及括號中是整個堆內(nèi)存的大小8035712k。?
第二步是 [CMS-concurrent-mark-start]開始并發(fā)標(biāo)記(concurrent-mark-start) 階段，在第一個階段被暫停的線程重新開始運行，由前階段標(biāo)記過的對象出發(fā)，所有可到達的對象都在本階段中標(biāo)記。 [CMS-concurrent-mark: 0.356/0.356 secs]?
代表并發(fā)標(biāo)記階段結(jié)束，占用 0.356秒CPU時間，0.356秒墻鐘時間(也包含線程讓出CPU給其他線程執(zhí)行的時間)?
第三步是[CMS-concurrent-preclean-start]開始預(yù)清理階段?
預(yù)清理也是一個并發(fā)執(zhí)行的階段。因為標(biāo)記和應(yīng)用線程是并發(fā)執(zhí)行的，因此會有些對象的狀態(tài)在標(biāo)記后會改變，此階段正是解決這個問題。因為之后的Rescan階段也會stop the world，為了使暫停的時間盡可能的小，也需要preclean階段先做一部分工作以節(jié)省時間。?
第四步是CMS-concurrent-abortable-preclean階段，加入此階段的目的是使cms gc更加可控一些，作用也是執(zhí)行一些預(yù)清理，以減少Rescan階段造成應(yīng)用暫停的時間。?
第五步則是Rescan階段，Stop-the-world 階段,從根及被其引用對象開始，重新掃描 CMS 堆中殘留的更新過的對象。這里重新掃描費時0.0351330秒，處理弱引用對象費時0.0008150秒。后面是重新remark的信息，具體參見第一步，本步驟費時0.037 秒，該階段總體耗時0.04秒。?
第六步是[CMS-concurrent-sweep-start]階段，開始并發(fā)清理階段，在清理階段，應(yīng)用線程還在運行。緊接著并發(fā)清理完成時間。?
最后一步則是[CMS-concurrent-reset-start]開始并發(fā)重置，該階段主要重新初始化CMS內(nèi)部數(shù)據(jù)結(jié)構(gòu)，以備下一輪 GC 使用，緊接著是該階段的完成時間。?
如上就是一個正常的CMS垃圾回收過程，其中可以看到，整個CMS期間還夾雜著2條新生代內(nèi)存的回收過程也屬于正常。同樣還有不正常的CMS垃圾回收日志，比如：

[GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] ?
(concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]

這段信息顯示ParNew 收集器被請求進行新生代的回收，但收集器并沒有嘗試回收，因為它預(yù)計在最糟糕的情況下，CMS老年代中沒有足夠的空間容納新生代的幸存對象。我們把這個失敗稱之為”完全晉升擔(dān)保失敗”。因為這樣，并發(fā)模式的CMS被中斷同并且在 197.981秒時，F(xiàn)ull GC被啟動。這次Full GC，采用標(biāo)記-清除-整理算法，會發(fā)生stop-the-world費時2.3733725秒。CMS 老年代占用從 402978K 降到248977K。為避免并發(fā)模式失敗, 通過增加老年代空間大小或者設(shè)置參數(shù) CMSInitiatingOccupancyFraction 同時設(shè)置UseCMSInitiatingOccupancyOnly為true。參數(shù) CMSInitiatingOccupancyFraction 的值必須謹慎選擇，設(shè)置過低會造成頻繁發(fā)生 CMS 回收。?
有時我們發(fā)現(xiàn)，當(dāng)日志中出現(xiàn)晉升失敗時，老年代還有足夠的空間。這是因為”碎片”，老年代中的可用空間并不連續(xù)，而從新生代晉升上來的對象，需要一塊連續(xù)的可用空間。CMS 收集器是一種非壓縮收集器，在某種類型的應(yīng)用中會發(fā)生碎片。


發(fā)表
26906人 簽到看排名