記一次耗時毛刺排查

前段時間的某天，注意到一個服務的平均耗時出現(xiàn)了如下圖的毛刺現(xiàn)象观堂。

耗時毛刺

注意到毛刺出現(xiàn)極其規(guī)律让网，每30分鐘出現(xiàn)一個毛刺∈郏考慮到這種規(guī)律性溃睹，并結(jié)合服務的流量較小（20 QPS）推測胰坟，可能是某個定時請求的接口進行了耗時操作因篇，由于流量較小放大了平均耗時，繼而出現(xiàn)了毛刺。但排查主調(diào)調(diào)用的接口竞滓，并沒有發(fā)現(xiàn)定時的調(diào)用咐吼，從而否定了這種可能性。
排除服務外部的原因?qū)е碌拿躺逃樱敲粗皇Ｏ路諆?nèi)部的原因了锯茄。該服務為JAVA應用，考慮到服務GC會導致應用暫停莉御，使外部請求耗時異常增長撇吞；但是，并不能解釋如此規(guī)律的毛刺礁叔。抱著“死馬當活馬醫(yī)”的想法牍颈，使用如下命令

jstat -gc pid 3000

查看了服務的GC情況，結(jié)果有了意外發(fā)現(xiàn)：產(chǎn)生毛刺時發(fā)生了多次GC琅关，GC情況如下圖：

毛刺時的GC情況

分析數(shù)據(jù)煮岁，得知產(chǎn)生一個毛刺時Young GC進行了237-231=6次，F(xiàn)ull GC進行了303-294=9次涣易，F(xiàn)ull GC的時間664-641=23秒画机，可知，正是由于GC停頓了20多秒新症，從而使得平均耗時顯著提高步氏。得益于良好的運維，服務啟動時加入了如下參數(shù)：

    -XX:+UseConcMarkSweepGC -Xloggc:jvm.log -verbosegc -XX:+PrintGCDetails
    -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps

由此徒爹，可以繼續(xù)分析具體的GC日志：

GC日志部分截圖

注意到GC時發(fā)生了兩次失敿孕选：Promotion Failed和Concurrent mode Failuer，分別是進程停頓6.8s和5s隆嗅。截圖中省去了部分日志界阁，實際之后還發(fā)生了兩次Concurrent mode Failuer從而使進程暫停20多秒。
那為什么連GC都如此有規(guī)律的每30分鐘進行呢胖喳？再次排查代碼泡躯，發(fā)現(xiàn)了如下類似的代碼：

    public static void refresh() {
        ConcurrentHashMap<String, Integer> newCache = DBUtil.getCache();
        cache = newCache;
        log.info("refresh cache, size:" + newCache.size());
    }

該服務是一個緩存服務，將數(shù)據(jù)庫中的數(shù)據(jù)讀取到內(nèi)存丽焊，然后提供接口查詢较剃。由于數(shù)據(jù)庫中的數(shù)據(jù)會更新，所以需要固定時間（每30分鐘）從數(shù)據(jù)庫重新讀取數(shù)據(jù)粹懒，刷新緩存重付。查詢數(shù)據(jù)庫中的數(shù)據(jù)，發(fā)現(xiàn)已經(jīng)有接近500萬行的數(shù)據(jù)凫乖。當加載這部分數(shù)據(jù)到內(nèi)存時，內(nèi)存需求暴漲，JVM進行了多次耗時的GC帽芽，導致進程暫停删掀，從而使得請求耗時出現(xiàn)毛刺。
找到了問題出現(xiàn)的原因导街，開始著手進行優(yōu)化披泪。由于主要是GC問題，故嘗試不修改業(yè)務代碼搬瑰，直接修改JVM參數(shù)的方式進行優(yōu)化款票。在優(yōu)化之前，需要弄明白Promotion Failed和Concurrent mode Failuer的原因泽论。
晉升失敗Promotion Failed的原因主要有：

Survivor區(qū)空間不足艾少，Survivor中的對象還不足以晉升到老年代，從年輕代晉升到Survivor的對象大于了Survivor剩余的空間翼悴。
從年輕代直接晉升到老年代的對象大于老年代剩余的空間缚够。

由于本例中的對象是突然暴漲的，所以可確定原因為后者鹦赎，所以需要增大老年代的空間谍椅。
并發(fā)模式失敗Concurrent mode Failuer的原因是：CMS GC回收對象的速度趕不上用戶申請對象的速度。當發(fā)生并發(fā)模式失敗后古话，CMS GC會退回到Serial Old GC使用串行回收雏吭，從而使得CMS GC不能發(fā)揮作用。解決該問題的方法有：

盡早進行CMS GC即調(diào)低-XX:CMSInitiatingOccupancyFraction參數(shù)陪踩，默認為68
增大老年代空間

由此杖们，將JVM參數(shù)由之前的：

    -Xmx2048m -Xms2048m -XX:NewSize=768m -XX:MaxNewSize=768m

調(diào)整為：

    -Xmx3072m -Xms3072m -XX:NewSize=1536m -XX:MaxNewSize=1536m

增大新生代的初衷是為了直接容納下服務刷新時的臨時對象，不需要晉升到老年代膊毁。觀察原來的老年代大約需要700M所以沒有進行大的擴容胀莹。修改后的效果如下：

請求耗時

高峰耗時減少一半，但依然存在毛刺婚温。查看GC日志描焰，依然存在一次concurrent mode failure。
繼續(xù)調(diào)整參數(shù)栅螟，增大老年代：

    -Xmx4096m -Xms4096m -XX:NewSize=1024m -XX:MaxNewSize=1024m

整個堆內(nèi)存從2G擴容到4G荆秦，老年代從1.25G擴容到3G，內(nèi)存已經(jīng)較為充足力图。調(diào)整后步绸，耗時大幅降低，也沒有出現(xiàn)concurrent mode failure吃媒，但依然沒有消除毛刺現(xiàn)象瓤介，效果圖如下：

請求耗時

再次查看GC日志吕喘，發(fā)現(xiàn)耗時主要集中在年輕代回收：

GC情況

嘗試使用UseParallelOldGC加快年輕代回收，但是年老代耗時過長刑桑。不能同時使用Parallel Scavenge回收年輕代氯质，CMS回收年老代真是大坑。最后更換為G1 GC大大減少了Full GC祠斧，毛刺抖動得到大大緩解闻察，效果如下：

請求耗時