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

序

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

症狀

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

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引起的。git

Full GC (Metadata GC Threshold)

這裏使用的是java8，參數沒有明確指定metaspace的大小和上限，查看一下github

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)

相關參數segmentfault

-XX:MetaspaceSize，初始空間大小(也是初始的閾值，即初始的high-water-mark)，達到該值就會觸發垃圾收集進行類型卸載，同時GC會對該值進行調整：若是釋放了大量的空間，就適當下降該值；若是釋放了不多的空間，那麼在不超過MaxMetaspaceSize時，適當提升該值。
-XX:MaxMetaspaceSize，最大空間，默認是沒有限制的，取決於本地系統空間容量。
-XX:MinMetaspaceFreeRatio，在GC以後，最小的Metaspace剩餘空間容量的百分比(即元數據在當前分配大小的最大佔用大小)，若是空閒比小於這個參數(即超過了最大佔用大小)，那麼將對meta space進行擴容。
-XX:MaxMetaspaceFreeRatio，在GC以後，最大的Metaspace剩餘空間容量的百分比(即元數據在當前分配大小的最小佔用大小)，若是空閒比大於這個參數(即小於最小佔用大小)，那麼將對meta space進行縮容.

因爲沒有設置，在機器上的默認值爲：bash

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)主要分爲了三次markdown

第一次，[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 gcoracle

GC (Allocation Failure)

分析完full gc以後咱們看下young gc，看log裏頭99%都是GC (Allocation Failure)形成的young gc。Allocation Failure表示向young generation(eden)給新對象申請空間，可是young generation(eden)剩餘的合適空間不夠所需的大小致使的minor gc。jvm

-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申請空間
向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。