序
本文主要分析一個頻繁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
- jstat
- Size of Huge Objects directly allocated to Old Generation
- Java物件分配簡要流程
- 記一次JVM優化過程
- Survivor空間溢位例項
- Java 垃圾回收的log,為什麼 from和to大小不等?
- Useful JVM Flags – Part 5 (Young Generation Garbage Collection)
- JDK-6453675 : Request for documentation of -XX:+PrintTenuringDistribution output
- How to read the output of +PrintTenuringDistribution
- 一次GC Tuning小記
- JDK8 的FullGC 之 metaspace
- Java PermGen 去哪裡了?
- Metaspace
- MetaspaceSize的坑
- JVM原始碼分析之Metaspace解密
- About G1 Garbage Collector, Permanent Generation and Metaspace
- 聊聊jvm的PermGen與Metaspace
- GC LOGGING – USER, SYS, REAL – WHICH TIME TO USE? & GANDHI
- REAL TIME IS GREATER THAN USER AND SYS TIME
- GC日誌時間分析: user + sys < real
- What is promotion rate?