搞java開發，看懂JVM的GC日誌真的很重要

前言 今天整理的這篇文章，整理自之前記錄的平常筆記。

剛開始接觸JVM時，對待GC的日誌，是保持"逃避"態度的，線上部署的程序沒有達到指望的運行效率，或是預期目標時，每每會把問題的矛頭指向內存上。

是否是內存不夠？

GC日誌怎麼這麼多？佔用磁盤高達幾個G?

不想看到打印怎麼多，甚至暴力的將程序日誌屏蔽掉。

我也曾經這樣幹過，寫過的程序，一樣致使過內存溢出，甚至是主機宕機。

是的，java中的垃圾回收的確幫咱們省了不少事，咱們不像C/C++程序員同樣，

須要考慮分配（malloc）內存分配與（free）釋放內存，但我相信每一個java開發的小夥伴都

會遇到GC問題，不管是在程序的性能優化，仍是故障分析上。

咱們應該在一次又一次的失誤中得到經驗和教訓，而不是去逃避或是草草解決問題了事。 一樣的知識點，回顧兩次，就會產生 1 + 1 > 2 的效應 。

因此這篇文章咱們來談談耳熟能詳的JVM的 GC日誌。

GC 日誌是什麼 首先來講一說GC的概念， GC 就是垃圾回收 （Garbage Collection） 的縮寫。

何爲垃圾？

沒有任何引用指向的對象，被JVM視爲垃圾。

固然，對應的斷定算法有：引用計數算法、可達性分析算法。 對應的回收算法有：標記清除、複製、標記整理、分代收集算法。

那GC的日誌是什麼呢？

GC日誌是java虛擬機產生的一種描述性的文本日誌。就像咱們開發java程序須要輸出log日誌同樣。JAVA 虛擬機用GC日誌來描述，垃圾回收的狀況。

minor GC 和 Major GC Minor GC，表示新生代GC，指發生在新生代的垃圾收集動做，全部的Minor GC都會觸發全世界的暫停（stop-the-world），中止應用程序的線程，不過這個過程很是短。

Major GC：老年代GC，指發生在老年代的 GC，也稱之爲 Full GC。

GC 日誌有什麼用 經過GC日誌，咱們能直觀的看到內存清理的基本工做過程。

瞭解垃圾回收的一些行爲，什麼時候在Young（年輕代）什麼時候在回收Old（老年代），而且展現垃圾回收使用到多少資源。

儘管如今Java程序的可視化監控工具已經不少了【介紹？】，可是 GC 日誌對於開發人員來講，是咱們快速定位潛在的內存故障和性能瓶頸最直觀的信息之一。

經過GC 日誌咱們能獲取什麼信息 ES 的 GC分配失敗（GC Allocation Failure） 遇到線上GC問題時的日誌也是很寶貴的分析素材，這裏的GC Allocation Failure圖片引用自一位羣友的ES節點GC日誌。

file

GC Allocation Failure 是咱們常常遇到的一種GC日誌。

分配失敗表明着在JVM的Eden區中沒有更多的空間來分配對象了，這是minor GC的正常日誌。

那別光說不練，那咱們來看看GC Allocation Failure的日誌內容是什麼樣的。

file

是否是感受很亂？【摳腦殼圖 對話】

不要緊，咱們依次來分析分析。

咱們按時間分割，能夠知道，截圖中一共有兩行日誌，先來看日誌一：

2020-03-17T19:03:19.701+0800: 6664.686: Total time for which application threads were stopped: 0.0313360 seconds , Stopping threads took: 0.0000925 seconds 毋庸置疑，首先映入眼簾的是帶時區的日誌時間。

其次 Total time for which application threads were stopped 表示 全部應用線程暫停了 0.0313360 秒。

其中等待全部應用線程到達 【安全點】 用了0.0000925 秒。

暫停的這段時間，其實就是花在了GC上面。後續第二行的 real=0.03 secs 和這裏相對應。

剛纔提到了 安全點 ，那簡單提一提，咱們知道在 Java 的線程有幾個不一樣的狀態。也知道線程若是被 「打斷」 會出現什麼樣的問題。因此對於設計者來講，須要讓線程 「跑」 到安全點上，再停頓。當處於安全點時，線程的狀態是肯定的，這樣JVM就能夠安全的進行一些操做，好比執行垃圾回收。

安全點的位置包括：

file

若是有線程一直沒有進入到安全點，就會致使GC時JVM停頓時間延長。

再來看日誌二：

1） 2020-03-17T19:03:20.118+0800: 6665.102: 2）[GC (Allocation Failure) 2020-03-17T19:03:20.118+0800: 6665.102: 3）[ParNew Desired survivor size 8716288 bytes, new threshold 6 (max 6) 4）- age 1: 6826872 bytes, 6826872 total 5）- age 2: 1060216 bytes, 7887088 total 6）: 149828K->8895K(153344K), 0.0361997 secs] 7）6272826K->6139400K(8371584K),0.0363166 secs] 8） [Times: user=0.07 sys=0.00, real=0.03 secs] 第一行，爲日誌輸出的時間。

第二行，代表了進行了一次 GC 回收，注意，因爲這裏沒有 Full 關鍵字 ，代表是一次 Minor GC，並指明瞭 GC 的時間。 Allocation Failure則表示GC的緣由是在年輕代中沒有了足夠的空間來存儲數據了。

第三行，ParNew 一樣指明瞭本次 GC 是發生在年輕代，而且使用的是ParNew垃圾收集器。該收集器採用複製算法回收內存，期間會中止其餘工做線程，即Stop The World。

第3、4、五行，表示每次年輕代 GC 以後打印 survivor 區域內對象的年齡分佈， threshold則表示設置的晉升老年代的年齡閾值爲6。

第六行，分別表示GC前年輕代的使用容量，GC 後該區域使用容量，括號內是該區域的總容量。最後是該內存區域GC耗時，單位是秒。

file

第七行，分別表示堆內存在垃圾回收之間的大小、堆內存在垃圾回收以後的大小，堆區的總大小。

file

能夠看到在 GC 後，回收對象佔比不多。

第八行，顯示三個耗時，分別是用戶態耗時、內核態耗時、總耗時。

file

從以上信息咱們能夠分析得出如下結論：

本次 GC 新生代減小了： 149828 - 8895 = 140933K。

堆內存區域共減小了： 6272826 - 6139400 = 133426K。

file 圖來自網絡

再把兩個等號後的結果相減： 140933 - 133426 = 7507K

說明該次共有7507K（7.3M）內存從年輕代移到了老年代，能夠看出來數量並很少，說明都是生命週期短的對象，只是這種對象有不少。

咱們須要的是儘可能避免Full GC的發生，讓對象儘量的在年輕代就回收掉，因此這裏能夠稍微增長一點年輕代的大小，讓那 7.3M 的數據也保存在年輕代中。

ES 的 Old GC 上面介紹了 年輕代的GC日誌，下面咱們來講一說 老年代的 GC 日誌 ，其實和年輕代分析的方法同樣。

仍是先列出日誌：

[gc][238384] overhead, spent [2.2s] collecting in the last [2.3s]

[2020-03-18T01:01:29,020][INFO ][o.e.m.j.JvmGcMonitorService] [eS] [gc][old][238385][160772] duration [5s],

collections [1]/[5.1s], total [5s]/[4.4d], memory [945.4mb]->[958.5mb]/[1007.3mb],

all_pools {[young] [87.8mb]->[100.9mb]/[133.1mb]}{[survivor] [0b]->[0b]/[16.6mb]}{[old] [857.6mb]->[857.6mb]/[857.6mb]} 直接來解釋一下吧。 第一行指明瞭這是第 238384次 GC 在最近 2.3 s 內花了 2.2s 用來作垃圾收集。

相信解讀過年輕代的GC，理解第二行的含義並不複雜了。

[gc][本次是 old GC][這是第228385次 GC 檢查][從 JVM 啓動至今發生的第 160772次 GC] duration [本次檢查到的 GC 總耗時 5 秒，多是屢次的加和],

collections [從上次檢查至今總共發生1次 GC]/[從上次檢查至今已過去 5.1 秒],

total [本次檢查到的 GC 總耗時爲 5 秒]/[從 JVM 啓動至今發生的 GC 總耗時爲 4.4 天]，

memory [ GC 前 Heap memory 空間]->[GC 後 Heap memory 空間]/[Heap memory 總空間],

all_pools(分代部分的詳情)

{[young 區][GC 前 Memory ]->[GC後 Memory]/[young區 Memory 總大小] }

{[survivor 區][GC 前 Memory ]->[GC後 Memory]/[survivor區 Memory 總大小] }{[old 區][GC 前 Memory ]->[GC後 Memory]/[old區 Memory 總大小] }

ES 的 GC 配置 file

-XX:+PrintGCDetails 表示打印GC的詳細日誌

-XX:+PrintGCDateStamps 表示須要展現打印GC的日期時間

-XX:+PrintGCApplicationStoppedTime 打印垃圾回收期間程序暫停的時間

日誌滾動，輸出到指定的日誌文件中等等配置。

GC日誌圖示 若是前面的介紹尚未太明白，這裏附上兩張GC日誌的圖片，之後遇到須要閱讀GC日誌的時候，能夠用做工具查閱。

年輕代：

file

老年代：

file

總結（個人觀點） GC 涉及到的知識點不少，本文可能只是冰山一角，從GC 日誌出發分析，讓讀者瞭解，GC日誌中每一個數字的變化，意味着什麼。更多的，先前有介紹過線上 OOM 的一些排查思路和MAT 性能分析工具在實際案例中的使用，同時但願各位多多結合實際的案例來分析，作好知識儲備，便是線上出了 GC 的一些問題也能作到胸有成竹，調整出最優的JVM配置，提升線上程序的運行效率，儘可能避免性能上的一些故障。最後在內容上作個小結

本文介紹了整理這篇筆記的原因 介紹了GC日誌的基本概念 minor GC 和 Major GC的基本概念 說明了GC 日誌的做用 ES 的 GC分配失敗的日誌解讀 ES 的 Old GC的日誌解讀。 JAVA GC的圖示