天天看點

記一次有驚無險的 JVM 優化經曆

轉載:https://my.oschina.net/u/3627055/blog/2995973

背景

生産環境有二台阿裡雲伺服器,均為同一時期購買的,CPU、記憶體、硬碟等配置相同。具體配置如下:

       節點      CPU        記憶體        硬碟        其它
A 2CPU             4G 普通雲盤 Centos6.4 64位+JDK1.8.0_121
B

由于這二伺服器硬體和軟體配置相同,并且運作相同的程式,是以在Nginx輪詢政策均weight=1,即平台的某個流量由這二台機器平分。

有一次對系統進行例行檢查,使用PinPoint檢視下伺服器”Heap Usage”的使用情況時,發現在有一個系統Full GC非常頻繁,大約五分鐘一次Full GC,吓我一跳。

這麼頻繁的Full GC,導緻系統暫停處理業務,對系統的實時可用性大打折扣。

我檢查了一下Tomcat(Tomcat8.5.28)配置,發現在tomcat沒有作任何關于JVM記憶體的設定,全部使用預設模式。

GC資料

在業務峰期間,通過PinPoint觀察的A、B節點的”Heap Usage”使用情況,分别進行以下幾個時間段資料。

3小時圖:

上圖B系統在三個小時内,一共發生了22次Full GC,大約每8分鐘進行一次Full GC。

每次Full GC的時間大概有150ms左右,即B系統在三個小時内,大約有3300ms暫停系統運作。

從上圖來看,堆的空間最大值在890M左右,但在堆空間的大小大約200M就發生Full GC了,從系統資源的利用角度來考慮,這個使用率太低了。

記一次有驚無險的 JVM 優化經曆

上圖A系統在3個小時内,一共發生了0次Full GC,嗯,就是沒有任何停頓。 

在這3小時,系統一直在處理業務,沒有停頓。堆的總空間大約1536m,目前堆的空間大于500M。

6小時圖:

記一次有驚無險的 JVM 優化經曆

上圖B系統在6個小時的資料統計和3個小時很像,6個小時内一共發生了N次Full GC,均是堆的空間小于200M就發生Full GC了。

記一次有驚無險的 JVM 優化經曆

上圖A系統在6個小時内,一共發生了0次Full GC,表現優秀。

12小時

記一次有驚無險的 JVM 優化經曆

上圖B系統在12個小時内,一共發生了N次Full GC,左邊Full GC比較少,是因為我們的業務主要集中白天,雖然晚上屬于非業務高峰期間,還是有Full GC。

記一次有驚無險的 JVM 優化經曆

上圖A系統在12個小時内,一共發生了0次Full GC,表現優秀。

GC日志

看下gc.log檔案,因為我們兩台伺服器都輸出了gc的詳細日志,先看下B系統的Full GC日志。

記一次有驚無險的 JVM 優化經曆

上圖全部是” [Full GC (Ergonomics)”日志,是因為已經去掉” GC (Allocation Failure”日志,這樣更友善觀察和分析日志。

我們選取GC日志檔案最後一條Full GC日志。

2018-12-24T15:52:11.402+0800: 447817.937: [Full GC (Ergonomics) [PSYoungGen: 480K->0K(20992K)] [ParOldGen: 89513K->69918K(89600K)] 89993K->69918K(110592K), [Metaspace: 50147K->50147K(1095680K)], 0.1519366 secs] [Times: user=0.21 sys=0.00, real=0.15 secs]

可以計算得到以下資訊:

  • 堆的大小:110592K=108M
  • 老生代大小:89600K=87.5M
  • 新生代大小:20992K=20.5M

分析:這次Full GC是因為老年代對象占用的空間的大小已經超過老年代容量 引發的Full GC。

[ParOldGen: 89513K->69918K(89600K)]

究其原因,是因為配置設定給老年代的空間太小,遠遠不能滿足系統對業務的需要。

這導緻老年代的空間常常被占滿,老年代的空間滿了,導緻Full GC。而由于老年代的空間比較小,是以每次Full GC的時間也比較短。

A系統日志,隻有2次Full GC,這2次GC均發生在系統啟動時:

7.765: [Full GC (Metadata GC Threshold) [PSYoungGen: 18010K->0K(458752K)] [ParOldGen: 15142K->25311K(1048576K)] 33153K->25311K(1507328K), [Metaspace: 34084K->34084K(1081344K)], 0.0843090 secs] [Times: user=0.14 sys=0.00, real=0.08 secs]

可以得到以下資訊:

  • 堆的大小:1507328K=1472M
  • 老生代大小:89600K=1024M
  • 新生代大小:20992K=448M

分析:A系統隻有系統啟動才出現二次Full GC現象,而且是” Metadata GC Threshold”引起的,而不是堆空間引起的Full GC。

雖然經過一個星期的觀察,A系統沒有Full GC,但一旦發生Full GC時間則會比較長。

其它系統曾經發現過,1024M的老年代,Full GC持續的時間大約是90ms秒。

是以看得出來推也不是越大越好,或者說在UseParallelOldGC收集器中,堆的空間不是越大越好。

分析與優化

總體分析:

  • B系統的Full GC過于頻繁,是因為老生代隻有約108M空間,根本無法滿足系統在高峰時期的記憶體空間需求
  • 由于ParOldGen(老年代)常常被耗盡,是以就發生Full GC事件了
  • A系統的堆初始空間(Xms)和堆的最大值(Xmx)均為1536m,完全可以滿足業務高峰期的記憶體需求

優化政策:

  • B系統先增加堆空間大小,即通過設定Xms、 Xmx值增加堆空間。直接把Xms和Xmx均設定為1024M。
  • 堆的啟動空間(Xms)直接設定為堆的最大值的原因是:因為直接把Xms設定為最大值(Xmx)可以避免JVM運作時不停的進行申請記憶體,而是直接在系統啟動時就配置設定好了,進而提高系統的效率。
  • 把Xms(堆大小)設定為1024M,是因為采用JDK的建議,該建議通過指令得到:

    java -XX:+PrintCommandLineFlags -version

  • 綜合下來的B系統的JVM參數設定如下:

    export JAVA_OPTS="-server –Xms1024m -Xmx1024m -XX:+UseParallelOldGC  -verbose:gc -Xloggc:../logs/gc.log  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps"

  • A系統JVM參數設定保持不變,以便觀察系統運作情況,即:

    export JAVA_OPTS="-server -Xms1536m -Xmx1536m -XX:+UseParallelOldGC  -verbose:gc -Xloggc:../logs/gc.log  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

  • 将A、B節點系統的JVM參數采用2套參數,是為了驗證A或B的參數更适合實際情況。