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

GC(Allocation Failure)引發的一些JVM知識點梳理
2020-04-05
GCAIJVM
如何處理頻繁建立物件然後丟棄導致頻繁GC的情況
2011-10-29
物件GC
一次JVM_OLD區佔用過高、頻繁Full GC的解決過程
2018-10-31
JVMGC
一次對pool的誤用導致的.net頻繁gc的診斷分析
2023-03-28
GC
Minor GC、Major GC以及Full GC的介紹及對比
2015-04-24
GC
線上排查：記憶體異常使用導致full gc頻繁
2023-02-07
記憶體GC
一些長時間GC停頓問題的排查及解決辦法
2019-03-27
GC
gc current request等待時間處理
2013-02-26
GC
又抓了一個導致頻繁GC的鬼--陣列動態擴容
2020-05-28
GC陣列
RabbitMQ 處理過慢，原來是一個 SQL 快取框架導致的 GC 頻繁觸發
2021-11-15
MQSQL快取框架GC
python中頻繁的print到底能浪費多長時間
2017-11-24
Python
JAVA GC日誌分析
2019-06-07
JavaGC
jvm系列:Java GC 分析
2017-09-19
JVMJavaGC
一次JVM GC長暫停的排查過程
2023-01-12
JVMGC
一次JVM GC長暫停的排查過程！
2023-04-06
JVMGC
從CLR GC到CoreCLR GC
2019-06-18
GC
[Linux] kernel: page allocation failure
2016-11-02
LinuxAI
jvm系列(九):Java GC 分析
2017-09-19
JVMJavaGC
GC
2019-09-08
GC
Kafka 如何最佳化記憶體緩衝機制造成的頻繁 GC 問題？
2022-12-08
Kafka記憶體GC
Full GC (Metadata GC Threshold)
2018-11-28
GC
GC.MaxGeneration屬性【GC示例】
2018-06-29
GC
GC是什麼？為什麼要有GC？
2018-07-25
GC
Android GC，JVM MinorGC/ MajorGC/ FullGC，GC目的
2016-05-20
AndroidGCJVM
【4】JVM-GC設計思路分析
2017-05-25
JVMGC
gc伺服器慢的原因分析
2015-07-31
GC伺服器
定時收集gc事件的指令碼
2014-11-18
GC事件指令碼
win10頻繁藍屏kernel security check failure修復方法
2020-06-11
Win10AI
JVM 系列文章之 Full GC 和 Minor GC
2018-09-03
JVMGC
總結Minor GC、Full GC觸發條件
2020-12-18
GC
gc buffer busy
2019-06-24
GC
gc 檢視
2020-12-27
GC
System.gc()
2014-03-02
GC
GC故障2
2013-12-04
GC
GC故障3
2013-12-05
GC
P於GC
2003-10-27
GC
java GC Collector
2024-03-19
JavaGC
曹工改bug：cpu狂飆，old gc頻繁，執行緒神祕死亡連環案件調查報告
2020-08-25
GC執行緒