垃圾回收全集之九：GC 演算法調優的工具篇

稍微解釋一下上面的內容。參考 jstat manpage , 我們可以知道:

• jstat 連線到 JVM 的時間, 是JVM啟動後的 200秒。此資訊從第一行的 “ Timestamp ” 列得知。繼續看下一行, jstat 每秒鐘從JVM 接收一次資訊, 也就是命令列引數中 “ 1s “ 的含義。
• 從第一行的 “ YGC ” 列得知年輕代共執行了34次GC, 由 “ FGC ” 列得知整個堆記憶體已經執行了 658次 full GC。
• 年輕代的GC耗時總共為  0.720 秒 , 顯示在“ YGCT ” 這一列。
• Full GC 的總計耗時為  133.684 秒 , 由“ FGCT ”列得知。 這立馬就吸引了我們的目光, 總的JVM 執行時間只有 200 秒,  但其中有 66% 的部分被 Full GC 消耗了 。

再看下一行, 問題就更明顯了。

• 在接下來的一秒內共執行了 4 次 Full GC。參見 “ FGC “ 列.
• 這4次 Full GC 暫停佔用了差不多 1秒的時間(根據  FGCT 列的差得知)。與第一行相比, Full GC 耗費了 928 毫秒 , 即  92.8%  的時間。
• 根據 “ OC  和 “ OU ” 列得知,  整個老年代的空間 為  169,344.0 KB  (“OC“), 在 4 次 Full GC 後依然佔用了  169,344.2 KB  (“OU“)。用了  928ms  的時間卻只釋放了 800 位元組的記憶體, 怎麼看都覺得很不正常。

只看這兩行的內容, 就知道程式出了很嚴重的問題。繼續分析下一行, 可以確定問題依然存在,而且變得更糟。

JVM幾乎完全卡住了(stalled), 因為GC佔用了90%以上的計算資源。GC之後, 所有的老代空間仍然還在佔用。事實上, 程式在一分鐘以後就掛了, 丟擲了 “ java.lang.OutOfMemoryError: GC overhead limit exceeded ” 錯誤。

可以看到, 通過 jstat 能很快發現對JVM健康極為不利的GC行為。一般來說, 只看 jstat 的輸出就能快速發現以下問題:

• 最後一列 “ GCT ”, 與JVM的總執行時間 “ Timestamp ” 的比值, 就是GC 的開銷。如果每一秒內, “ GCT “ 的值都會明顯增大, 與總執行時間相比, 就暴露出GC開銷過大的問題. 不同系統對GC開銷有不同的容忍度, 由效能需求決定, 一般來講, 超過  10%  的GC開銷都是有問題的。
• “ YGC ” 和 “ FGC ” 列的快速變化往往也是有問題的徵兆。頻繁的GC暫停會累積,並導致更多的執行緒停頓(stop-the-world pauses), 進而影響吞吐量。
• 如果看到 “ OU ” 列中,老年代的使用量約等於老年代的最大容量( OC ), 並且不降低的話, 就表示雖然執行了老年代GC, 但基本上屬於無效GC。