業(yè)務(wù)小姐姐說圖片訪問不了泣港，我開始慌了：
看到業(yè)務(wù)小姐姐發(fā)的這個(gè)圖片骑歹，你說能不慌嘛？但是再慌也要排查問題呀坞淮！對(duì)于這種前端響應(yīng)不過來的問題茴晋，首先就用瀏覽器的F12看看接口響應(yīng)速度（獲取圖片地址的接口）從而確認(rèn)是接口響應(yīng)慢還是網(wǎng)絡(luò)等其他問題。我勒個(gè)去碾盐，耗時(shí)10多秒呀晃跺！這時(shí)候我的心里更慌了。
問題排查
既然能確認(rèn)問題在服務(wù)端毫玖，那么就查看服務(wù)端日志掀虎，準(zhǔn)備尋找蛛絲馬跡。由于服務(wù)端日志都有通過AOP記錄耗時(shí)情況的付枫，實(shí)時(shí)觀察一下就能發(fā)現(xiàn)問題所在（說明：這個(gè)服務(wù)還沒有對(duì)接APM烹玉，否則這種問題更好定位）。不看不知道阐滩，一看嚇一跳二打，接口耗時(shí)都是10多秒，甚至20多秒掂榔，你說這客戶端能不轉(zhuǎn)圈圈嘛：
2019-04-19 10:11:18.533 http-nio-8007-exec-14 INFO com.xxx.image.advice.LogRequestBodyAdvice:40
2019-04-19 10:11:38.543 http-nio-8007-exec-14 INFO com.xxx.image.advice.LogResponseBodyAdvice:35 elapsed time: 20s
... ...
2019-04-19 10:31:10.111 http-nio-8007-exec-11 INFO com.xxx.image.advice.LogRequestBodyAdvice:40
2019-04-19 10:31:22.121 http-nio-8007-exec-11 INFO com.xxx.image.advice.LogResponseBodyAdvice:35 elapsed time: 12s
... ...
2019-04-19 10:45:16.244 http-nio-8007-exec-13 INFO com.xxx.image.advice.LogRequestBodyAdvice:40
2019-04-19 10:45:29.678 http-nio-8007-exec-13 INFO com.xxx.image.advice.LogResponseBodyAdvice:35 elapsed time: 13s
而且出問題的不是某一個(gè)接口继效，而是所有接口。那么装获，接下來準(zhǔn)備從我懷疑的地方開始排查：
- 數(shù)據(jù)庫問題（數(shù)據(jù)庫服務(wù)器一切指標(biāo)正常瑞信，也沒有慢日志）；
- 同步日志阻塞問題（此問題也不存在）穴豫；
- 系統(tǒng)問題凡简，如SWAP等（sar命令以及zabbix查看一切OK）；
- GC問題精肃；
- ... ...
說明：我們這個(gè)服務(wù)的特點(diǎn)是秤涩，只會(huì)訪問數(shù)據(jù)庫，沒有任何其他HTPP和RPC調(diào)用司抱，也沒有緩存筐眷。
接下來就是懷疑的GC問題了，因?yàn)橐郧耙才龅竭^頻繁FGC導(dǎo)致系統(tǒng)無法響應(yīng)状植，jstat命令用起來浊竟，輸出結(jié)果如下：
bash-4.4$ /app/jdk1.8.0_192/bin/jstat -gc 1 2s
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
170496.0 170496.0 0.0 0.0 171008.0 130368.9 1024000.0 590052.8 70016.0 68510.8 8064.0 7669.0 983 13.961 1400 275.606 289.567
170496.0 170496.0 0.0 0.0 171008.0 41717.2 1024000.0 758914.9 70016.0 68510.8 8064.0 7669.0 987 14.011 1401 275.722 289.733
170496.0 170496.0 0.0 0.0 171008.0 126547.2 1024000.0 770587.2 70016.0 68510.8 8064.0 7669.0 990 14.091 1403 275.986 290.077
170496.0 170496.0 0.0 0.0 171008.0 45488.7 1024000.0 650767.0 70016.0 68531.9 8064.0 7669.0 994 14.148 1405 276.222 290.371
170496.0 170496.0 0.0 0.0 171008.0 146029.1 1024000.0 714857.2 70016.0 68531.9 8064.0 7669.0 995 14.166 1406 276.366 290.531
170496.0 170496.0 0.0 0.0 171008.0 118073.5 1024000.0 669163.2 70016.0 68531.9 8064.0 7669.0 998 14.226 1408 276.736 290.962
170496.0 170496.0 0.0 0.0 171008.0 3636.1 1024000.0 687630.0 70016.0 68535.6 8064.0 7669.6 1001 14.342 1409 276.871 291.213
170496.0 170496.0 0.0 0.0 171008.0 87247.2 1024000.0 704977.5 70016.0 68535.6 8064.0 7669.6 1005 14.463 1411 277.099 291.562
如果你以前沒有排查太多的GC問題怨喘，那么可能你看到這段日子有點(diǎn)頭暈。筆者以前的文章說過很多次怎么排查GC問題振定，有興趣的同學(xué)可以翻看筆者公眾號(hào)的JVM專欄必怜。首先，我們要把注意力放在最后幾列（YGC后频、YGCT梳庆、FGC、FGCT卑惜、GCT）膏执，對(duì)應(yīng)的結(jié)果如下：
bash-4.4$ /log/plms/jdk1.8.0_192/bin/jstat -gc 1 2s
... ... YGC YGCT FGC FGCT GCT
... ... 983 13.961 1400 275.606 289.567
... ... 987 14.011 1401 275.722 289.733
... ... 990 14.091 1403 275.986 290.077
... ... 994 14.148 1405 276.222 290.371
... ... 995 14.166 1406 276.366 290.531
... ... 998 14.226 1408 276.736 290.962
... ... 1001 14.342 1409 276.871 291.213
... ... 1005 14.463 1411 277.099 291.562
這樣就容易理解多了，看看FGC那一列：幾乎每1秒都有一次FGC（說明露久，筆者這個(gè)服務(wù)用的是默認(rèn)的PS垃圾回收器更米，所以FGC這一列的值一定是FullGC的次數(shù)）。而且毫痕，再看FGCT這一列征峦，停頓時(shí)間那是相當(dāng)恐怖。那么會(huì)是什么原因呢消请？
繼續(xù)分析問題前栏笆，筆者先介紹3個(gè)JVM參數(shù)：MaxRAMPercentage、InitialRAMPercentage臊泰、MinRAMPercentage蛉加。這三個(gè)參數(shù)是JDK8U191為適配Docker容器新增的幾個(gè)參數(shù)，類比Xmx缸逃、Xms针饥，至于-XX:InitialRAMFraction、-XX:MaxRAMFraction需频、-XX:MinRAMFraction已經(jīng)被標(biāo)記為deprecated 打厘。這幾個(gè)參數(shù)的好處是什么呢？Docker容器模式下贺辰，我們可以給每個(gè)JVM實(shí)例所屬的POD分配任意大小的內(nèi)存上限。比如嵌施，給每個(gè)賬戶服務(wù)分配4G饲化，給每個(gè)支付服務(wù)分配8G。如此一來吗伤，啟動(dòng)腳本就不好寫成通用的了吃靠，指定3G也不是，指定6G也不是足淆。但是巢块，有了這三個(gè)新增參數(shù)礁阁，我們就可以在通用的啟動(dòng)腳本中指定75%（-XX:MaxRAMPercentage=75 -XX:InitialRAMPercentage=75 -XX:MinRAMPercentage=75）。那么族奢，賬戶服務(wù)就相當(dāng)于設(shè)置了-Xmx3g -Xms3g姥闭。而支付服務(wù)相當(dāng)于設(shè)置了-Xmx6g -Xms6g，是不是很贊越走。
再給出我們的JVM參數(shù)配置（說明：POD內(nèi)存限制是6G）：
-XX:MaxRAMPercentage=75 -XX:InitialRAMPercentage=75 -XX:MinRAMPercentage=75
-XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m
等價(jià)于：
-Xmx4608m -Xms4608m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m
原因分析
再回到前面那一段完整的GC日志（jstat的輸出結(jié)果）棚品，我們分析命令結(jié)果輸出時(shí)這個(gè)JVM的一些情況：
- S0/S1區(qū)容量為170496K（對(duì)應(yīng)S0C/S1C兩列）；
- Eden區(qū)容量為171008K（對(duì)應(yīng)EC列）廊敌；
- Old區(qū)容量為1024000K（對(duì)應(yīng)OC列）铜跑；
- Metaspace容量為70M；
根據(jù)各個(gè)區(qū)的容量大小骡澈，發(fā)現(xiàn)和JVM參數(shù)配置的4.5G內(nèi)存出入非常大锅纺。整個(gè)堆的大小縮容了很多，從4.5G縮小到現(xiàn)在的大概1.5G（170496K*2+171008K+1024000K+70M ≈ 1.5G）肋殴，WHY ?
如果對(duì)默認(rèn)的PS垃圾回收器有一定了解的同學(xué)囤锉，可能大概知道問題所在了。沒錯(cuò)疼电，就是參數(shù)-XX:+UseAdaptiveSizePolicy的鍋嚼锄。這個(gè)參數(shù)在PS前提下默認(rèn)是開啟的，其作用是自動(dòng)調(diào)整堆的大小蔽豺，以及對(duì)象從S區(qū)晉升到Old區(qū)的年齡閾值（threshold）区丑，調(diào)節(jié)threshold邏輯為：判斷Young GC和Full GC消耗的時(shí)間差：
- 如果Young gc > 1.1 * Full GC，threshold就會(huì)一直減少修陡。
- 如果1.1* Young GC < Full GC沧侥，threshold就會(huì)一直增加。
也就是說魄鸦，如果Young GC比較頻繁宴杀，那么threshold可能會(huì)一直減小，直到最小值1拾因，這時(shí)候S區(qū)的對(duì)象很容易晉升到Old區(qū)旺罢，導(dǎo)致Old區(qū)空間漲幅過快而觸發(fā)Full GC的頻率也加快。另外绢记，這個(gè)參數(shù)是如何調(diào)整堆的大小就不在這里介紹了扁达，因?yàn)楹軓?fù)雜，我也不知道蠢熄，哈哈哈：
問題驗(yàn)證
默認(rèn)PS垃圾回收器調(diào)整堆大小的這個(gè)問題很好驗(yàn)證跪解，筆者寫了一段簡(jiǎn)短的代碼，如下所示：
/**
* @author afei, 公眾號(hào)：阿飛的博客
*/
public class ParallelGcTest {
private static final int _1M = 1024 * 1024;
public static void main(String[] args) {
allocate();
}
private static void allocate(){
// 強(qiáng)引用分配的對(duì)象, 為了觸發(fā)FGC
List<byte[]> holder = new ArrayList<>();
for (int i = 0; i < Integer.MAX_VALUE; i++) {
byte[] tmp = new byte[_1M];
// 不要讓FGC來的太快
if (i%10==0) {
holder.add(tmp);
}
}
}
}
配置JVM參數(shù)（-Xmx256m -Xms256m -Xmn128m -XX:+PrintGCDetails）運(yùn)行的GC日志如下签孔，默認(rèn)情況下叉讥，即-XX:+UseAdaptiveSizePolicy時(shí)窘行，初始第一次YGC時(shí)堆大小為245760K，OOM之前最后一次FGC時(shí)堆大小為224768K图仓，從而驗(yàn)證了堆縮小的現(xiàn)象：
[GC (Allocation Failure) [PSYoungGen: 97896K->10497K(114688K)] 97896K->10505K(245760K), 0.0030860 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 108661K->16312K(114688K)] 108669K->20424K(245760K), 0.0057851 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
... ...
[Full GC (Ergonomics) [PSYoungGen: 82946K->81922K(93696K)] [ParOldGen: 130906K->130906K(131072K)] 213852K->212828K(224768K), [Metaspace: 3308K->3308K(1056768K)], 0.0054117 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
[Full GC (Ergonomics) [PSYoungGen: 82946K->82946K(93696K)] [ParOldGen: 130906K->130906K(131072K)] 213852K->213852K(224768K), [Metaspace: 3308K->3308K(1056768K)], 0.0150534 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
配置JVM參數(shù)（-Xmx256m -Xms256m -Xmn128m -XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy）運(yùn)行的GC日志如下罐盔，配置了-XX:-UseAdaptiveSizePolicy后，無論是初始第一次YGC時(shí)透绩，還是OOM之前最后一次FGC時(shí)堆大小都是245760K：
[GC (Allocation Failure) [PSYoungGen: 97896K->10545K(114688K)] 97896K->10553K(245760K), 0.0030478 secs] [Times: user=0.03 sys=0.03, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 108709K->16264K(114688K)] 108717K->20376K(245760K), 0.0053165 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
... ...
[Full GC (Ergonomics) [PSYoungGen: 97282K->96258K(114688K)] [ParOldGen: 130906K->130906K(131072K)] 228189K->227164K(245760K), [Metaspace: 3308K->3308K(1056768K)], 0.0026970 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (Ergonomics) [PSYoungGen: 97282K->97282K(114688K)] [ParOldGen: 130906K->130906K(131072K)] 228189K->228189K(245760K), [Metaspace: 3308K->3308K(1056768K)], 0.0058994 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
解決方案
已經(jīng)知道問題所在翘骂，那么就把這個(gè)參數(shù)關(guān)閉（ -XX:-UseAdaptiveSizePolicy），優(yōu)化后重啟服務(wù)帚豪，運(yùn)行一天的springboot-admin截圖如下碳竟，業(yè)務(wù)小姐姐訪問速度又飛起來了，圖片看都看不過來狸臣，嘿嘿：
如圖所示莹桅，每天還是有9次FGC，還能再優(yōu)化么烛亦？后面分析業(yè)務(wù)發(fā)現(xiàn)诈泼，有個(gè)每分鐘運(yùn)行的JOB，其作用是將用戶上傳的PDF轉(zhuǎn)成PNG圖片煤禽，一個(gè)PDF有多少頁就會(huì)轉(zhuǎn)成多少?gòu)垐D片铐达。并且，根據(jù)統(tǒng)計(jì)信息發(fā)現(xiàn)檬果，一個(gè)有20頁的PDF轉(zhuǎn)成圖片總計(jì)需要幾十秒瓮孙。那么就會(huì)導(dǎo)致YGC時(shí)，很可能這些正在壓縮的圖片任務(wù)還沒有完成选脊，從而導(dǎo)致這些對(duì)象（而且比較大的對(duì)象）晉升到S區(qū)杭抠，甚至?xí)x升到Old區(qū)。所以恳啥，這個(gè)FGC不好再降低偏灿。當(dāng)然，事實(shí)上也沒必要再優(yōu)化钝的，因?yàn)槲檀梗F(xiàn)在的FGC次數(shù)已經(jīng)對(duì)業(yè)務(wù)基本上無感知了：每天9次FGC，每次FGC停頓時(shí)間才不到1秒（8411ms/9 ≈ 935ms）硝桩，而且我們的系統(tǒng)并不是OLTP系統(tǒng)沮峡，而是給業(yè)務(wù)人員使用的。所以亿柑，有時(shí)候沒必要過度優(yōu)化，因?yàn)檫€要考慮付出的成本和獲得的收益棍弄，判斷是否值得我們?nèi)プ鲞@件事情望薄。
