頻繁GC (Allocation Failure)及young gc時間過長分析

go4it發表於2019-03-04

本文主要分析一個頻繁GC (Allocation Failure)及young gc時間過長的case。

症狀

  • gc throughput percent逐步下降,從一般的99.96%逐步下降,跌破99%,進入98%,最低點能到94%
  • young gc time逐步增加,從一般的十幾毫秒逐步上升,突破50,再突破100,150,200,250
  • 在8.5天的時間內,發生了9000多次gc,其中full gc為4次,平均將近8秒,大部分是young gc(allocation failure為主),平均270多毫秒,最大值將近7秒
  • 平均物件建立速率為10.63 mb/sec,平均的晉升速率為2 kb/sec,cpu使用率正常,沒有明顯的飆升

jvm引數

-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=4 -XX:+UseAdaptiveSizePolicy -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=1073741824 -XX:NewSize=1073741824 -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps
複製程式碼

jdk版本

java -version
java version "1.8.0_66"
Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode)
複製程式碼

full gc

27.066: [Full GC (Metadata GC Threshold) [PSYoungGen: 19211K->0K(917504K)] [ParOldGen: 80K->18440K(1048576K)] 19291K->18440K(1966080K), [Metaspace: 20943K->20943K(1069056K)], 0.5005658 secs] [Times: user=0.24 sys=0.01, real=0.50 secs] 
100.675: [Full GC (Metadata GC Threshold) [PSYoungGen: 14699K->0K(917504K)] [ParOldGen: 18464K->23826K(1048576K)] 33164K->23826K(1966080K), [Metaspace: 34777K->34777K(1081344K)], 0.7937738 secs] [Times: user=0.37 sys=0.01, real=0.79 secs]
195.073: [Full GC (Metadata GC Threshold) [PSYoungGen: 24843K->0K(1022464K)] [ParOldGen: 30048K->44782K(1048576K)] 54892K->44782K(2071040K), [Metaspace: 58220K->58220K(1101824K)], 3.7936515 secs] [Times: user=1.86 sys=0.02, real=3.79 secs] 
242605.669: [Full GC (Ergonomics) [PSYoungGen: 67276K->0K(882688K)] [ParOldGen: 1042358K->117634K(1048576K)] 1109635K->117634K(1931264K), [Metaspace: 91365K->90958K(1132544K)], 22.1573804 secs] [Times: user=2.50 sys=3.51, real=22.16 secs]
複製程式碼

可以發現發生的4次full gc,前三次都是由於Metadata GC Threshold造成的,只有最後一次是由於Ergonomics引發的。

Full GC (Metadata GC Threshold)

這裡使用的是java8,引數沒有明確指定metaspace的大小和上限,檢視一下

jstat -gcmetacapacity 7
   MCMN       MCMX        MC       CCSMN      CCSMX       CCSC     YGC   FGC    FGCT     GCT
       0.0  1136640.0    99456.0        0.0  1048576.0    12160.0 38009    16  275.801 14361.992
複製程式碼
  • 忽略後面的FGC,因為分析的日誌只是其中四分之一
  • 這裡可以看到MCMX(Maximum metaspace capacity (kB))有一個多G,而MC(Metaspace capacity (kB))才97M左右,為啥會引起Full GC (Metadata GC Threshold)

相關引數

  • -XX:MetaspaceSize,初始空間大小(也是初始的閾值,即初始的high-water-mark),達到該值就會觸發垃圾收集進行型別解除安裝,同時GC會對該值進行調整:如果釋放了大量的空間,就適當降低該值;如果釋放了很少的空間,那麼在不超過MaxMetaspaceSize時,適當提高該值。
  • -XX:MaxMetaspaceSize,最大空間,預設是沒有限制的,取決於本地系統空間容量。
  • -XX:MinMetaspaceFreeRatio,在GC之後,最小的Metaspace剩餘空間容量的百分比(即後設資料在當前分配大小的最大佔用大小),如果空閒比小於這個引數(即超過了最大佔用大小),那麼將對meta space進行擴容。
  • -XX:MaxMetaspaceFreeRatio,在GC之後,最大的Metaspace剩餘空間容量的百分比(即後設資料在當前分配大小的最小佔用大小),如果空閒比大於這個引數(即小於最小佔用大小),那麼將對meta space進行縮容.

由於沒有設定,在機器上的預設值為:

java -XX:+PrintFlagsFinal | grep Meta
    uintx InitialBootClassLoaderMetaspaceSize       = 4194304                             {product}
    uintx MaxMetaspaceExpansion                     = 5451776                             {product}
    uintx MaxMetaspaceFreeRatio                     = 70                                  {product}
    uintx MaxMetaspaceSize                          = 18446744073709547520                    {product}
    uintx MetaspaceSize                             = 21807104                            {pd product}
    uintx MinMetaspaceExpansion                     = 339968                              {product}
    uintx MinMetaspaceFreeRatio                     = 40                                  {product}
     bool TraceMetadataHumongousAllocation          = false                               {product}
     bool UseLargePagesInMetaspace                  = false                               {product}
複製程式碼

可以看到MinMetaspaceFreeRatio為40,MaxMetaspaceFreeRatio為70,MetaspaceSize為20M,Full GC (Metadata GC Threshold)主要分為了三次

  • 第一次,[Metaspace: 20943K->20943K(1069056K)]
  • 第二次,[Metaspace: 34777K->34777K(1081344K)]
  • 第三次,[Metaspace: 58220K->58220K(1101824K)]

可以看到metaspace的閾值不斷動態調整,至於具體調整的邏輯,官方文件貌似沒講,這裡暫時不深究。只要沒有超過Max值就沒有致命影響,但是對於低延時的應用來講,是要儘量避免動態調整引起的gc耗時,可以根據調優計算並設定初始閾值來解決。

Full GC (Ergonomics)

這裡可以到full gc的reason是Ergonomics,是因為開啟了UseAdaptiveSizePolicy,jvm自己進行自適應調整引發的full gc

GC (Allocation Failure)

分析完full gc之後我們看下young gc,看log裡頭99%都是GC (Allocation Failure)造成的young gc。Allocation Failure表示向young generation(eden)給新物件申請空間,但是young generation(eden)剩餘的合適空間不夠所需的大小導致的minor gc。

-XX:+PrintTenuringDistribution

Desired survivor size 75497472 bytes, new threshold 2 (max 15)
- age   1:   68407384 bytes,   68407384 total
- age   2:   12494576 bytes,   80901960 total
- age   3:      79376 bytes,   80981336 total
- age   4:    2904256 bytes,   83885592 total
複製程式碼
  • 這個Desired survivor size表示survivor區域允許容納的最大空間大小為75497472 bytes
  • 下面的物件列表為此次gc之後,survivor當前存活物件的年齡大小分佈,total大小為83885592 > 75497472,而age1大小為68407384 < 75497472,因此new threshold變為2(作用於下次gc)。下次gc如果物件沒釋放的話,超過閾值的物件將晉升到old generation。

age list為空

59.463: [GC (Allocation Failure) 
Desired survivor size 134217728 bytes, new threshold 7 (max 15)
[PSYoungGen: 786432K->14020K(917504K)] 804872K->32469K(1966080K), 0.1116049 secs] [Times: user=0.10 sys=0.01, real=0.20 secs] 
複製程式碼

這裡Desired survivor size這行下面並沒有各個age物件的分佈,那就表示此次gc之後,當前survivor區域並沒有age小於max threshold的存活物件。而這裡一個都沒有輸出,表示此次gc回收物件之後,沒有存活的物件可以拷貝到新的survivor區。

gc之後survivor有物件的例子

jstat -gcutil -h10 7 10000 10000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  99.99  90.38  29.82  97.84  96.99    413  158.501     4   14.597  173.098
 11.60   0.00  76.00  29.83  97.84  96.99    414  158.511     4   14.597  173.109
 11.60   0.00  77.16  29.83  97.84  96.99    414  158.511     4   14.597  173.109
  0.00  13.67  60.04  29.83  97.84  96.99    415  158.578     4   14.597  173.176
  0.00  13.67  61.05  29.83  97.84  96.99    415  158.578     4   14.597  173.176
複製程式碼
  • 在ygc之前young generation = eden + S1;ygc之後,young generation = eden + S0
  • 觀察可以看到ygc之後old generation空間沒變,表示此次ygc,沒有物件晉升到old generation。
  • gc之後,存活物件搬移到了另外一個survivor區域
  • 這裡由於是每個10秒取樣一次,存在延遲,即gc之後,立馬有新物件在eden區域分配了,因此這裡看到的eden區域有物件佔用。

real time > usr time + sys time

722914.974: [GC (Allocation Failure) 
Desired survivor size 109576192 bytes, new threshold 15 (max 15)
[PSYoungGen: 876522K->8608K(941568K)] 1526192K->658293K(1990144K), 0.0102709 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
722975.207: [GC (Allocation Failure) 
Desired survivor size 103284736 bytes, new threshold 15 (max 15)
[PSYoungGen: 843168K->39278K(941568K)] 1492853K->688988K(1990144K), 0.3607036 secs] [Times: user=0.17 sys=0.00, real=0.36 secs] 
複製程式碼

裡頭有大於將近300次的gc的real time時間大於usr time + sys time。

  • real:指的是操作從開始到結束所經過的牆鍾時間(WallClock Time)
  • user:指的是使用者態消耗的CPU時間;
  • sys:指的是核心態消耗的CPU時間。

牆鍾時間包括各種非運算的等待耗時,例如等待磁碟I/O、等待執行緒阻塞,而CPU時間不包括這些耗時,但當系統有多CPU或者多核的話,多執行緒操作會疊加這些CPU時間,所以看到user或sys時間超過real時間是完全正常的。

user + sys 就是CPU花費的實際時間,注意這個值統計了所有CPU上的時間,如果程式工作在多執行緒的環境下,疊加了多執行緒的時間,這個值是會超出 real 所記錄的值的,即 user + sys >= real 。

這裡300多次real time時間大於usr time + sys time,表明可能有兩個問題,一個是IO操作密集,另一個是cpu(分配)的額度不夠。

新生代垃圾回收機制

  • 新物件嘗試棧上分配,不行再嘗試TLAB分配,不行則考慮是否直接繞過eden區在年老代分配空間(-XX:PretenureSizeThreshold設定大物件直接進入年老代的閾值,當物件大小超過這個值時,將直接在年老代分配。),不行則最後考慮在eden申請空間
    頻繁GC (Allocation Failure)及young gc時間過長分析
  • 向eden申請空間建立新物件,eden沒有合適的空間,因此觸發minor gc
  • minor gc將eden區及from survivor區域的存活物件進行處理
    • 如果這些物件年齡達到閾值,則直接晉升到年老代
    • 若要拷貝的物件太大,那麼不會拷貝到to survivor,而是直接進入年老代
    • 若to survivor區域空間不夠/或者複製過程中出現不夠,則發生survivor溢位,直接進入年老代
    • 其他的,若to survivor區域空間夠,則存活物件拷貝到to survivor區域
  • 此時eden區及from survivor區域的剩餘物件為垃圾物件,直接抹掉回收,釋放的空間成為新的可分配的空間
  • minor gc之後,若eden空間足夠,則新物件在eden分配空間;若eden空間仍然不夠,則新物件直接在年老代分配空間

小結

從上面的分析可以看出,young generation貌似有點大,ygc時間長;另外每次ygc之後survivor空間基本是空的,說明新生物件產生快,生命週期也短,原本設計的survivor空間沒有派上用場。因此可以考慮縮小下young generation的大小,或者改為G1試試。

關於-XX:+PrintTenuringDistribution有幾個要點,要明確一下:

  • 這個列印的哪個區域的物件分佈(survivor)
  • 是在gc之前列印,還是在gc之後列印(gc之後列印)
  • 一個新生物件第一次到survivor時其age算0還是算1

物件的年齡就是他經歷的MinorGC次數,物件首次分配時,年齡為0,第一次經歷MinorGC之後,若還沒有被回收,則年齡+1,由於是第一次經歷MinorGC,因此進入survivor區。因此物件第一次進入survivor區域的時候年齡為1.

  • 晉升閾值(new threshold)動態調整

如果底下age的total大小大於Desired survivor size的大小,那麼就代表了survivor空間溢位了,被填滿,然後會重新計算threshold。

doc

相關文章