現(xiàn)象

• 某個大版本上線后倔喂，某服務(wù)頻繁報(bào)警: load過高铝条，但很快就會恢復(fù)，即間歇性load過高席噩，原因難以定位班缰。

觀察

• 從報(bào)警系統(tǒng)觀察報(bào)警時間分布，有一些周期性悼枢，但周期會在1小時到2小時之間埠忘，不穩(wěn)定
  • 初步排除是定時任務(wù)導(dǎo)致
• 觀察gc日志，發(fā)現(xiàn)報(bào)警時間點(diǎn)與gc時間開銷較高的點(diǎn)比較吻合馒索，因此著重觀察GC
• 發(fā)現(xiàn)JVM GC相關(guān)的配置不是很合理莹妒，做了簡單的優(yōu)化：將old區(qū)的并行收集改為CMS，情況有所改善绰上，但問題依然存在
• 該現(xiàn)象是上線后才出現(xiàn)的旨怠，可以認(rèn)定是業(yè)務(wù)邏輯所致。著重查看了業(yè)務(wù)邏輯的diff蜈块，因業(yè)務(wù)邏輯改動較多鉴腻，未能直接找到原因。
• 既然是GC所致百揭，就先看看GC為何這么慢吧爽哎！

初步定位

• 用jmap做了兩份內(nèi)存的dump，一份是old快滿（用jstat來實(shí)時觀察）即即將發(fā)生full gc之前的dump器一，另一份是GC剛剛結(jié)束的dump
  • 這樣可以明顯地對二者做對比课锌。
• 用mat打開（在機(jī)群上開了個vncserver，在本地用vncviewer連接上）兩份dump,發(fā)現(xiàn)兩份dump中reachable objects均只有400m不到祈秕，而unreachable objects有3G多
• 觀察unreachable objects渺贤，按shallow heap大小排序雏胃，忽略byte和char等基本類型（復(fù)雜類型數(shù)據(jù)都是由基本類型組成的）發(fā)現(xiàn)TreeMap占了300M+，讓人懷疑癣亚。
• 然而因?yàn)槭莡nreachable的丑掺，無法直接查看這些TreeMap對象的引用。如何才有知道到底誰引用它們呢述雾？在代碼里grep了一下，發(fā)現(xiàn)自己項(xiàng)目中沒有任何地方用到TreeMap吭露，從而判斷應(yīng)該是第三方庫用到的隶校。
• 從另外一個角度考慮饲常，我可以先看一下reachable objects中TreeMap的引用。
• 發(fā)現(xiàn)其中對treeMap有引用的對象中黍翎，個數(shù)較多的是JDBC4ResultSet和ShardedJedis。先看前者在unreachable objects中的情況艳丛，共有22158個垃圾對象匣掸。
• 在mat的dominator tree中看JDBC4ResultSet的大小，可以知道每個JDBC4ResultSet的retained heap大小為4.928k（也有不同氮双，但出入不大）碰酝，從而22158個的retained heap大小為22158 * 5k 約100M，遠(yuǎn)小于heap區(qū)的大小戴差，因此不是造成問題的原因送爸，忽略。
• 再看后者ShardedJedis暖释，從unreachable objects中可以看到共有4214個垃圾對象袭厂。
• 同時從dominator tree中可以看出每個ShardedJedis的Retained heap大小為323k,從而4214個的retained heap大小的4214*323k約為1.4G
• 至此，可以基本認(rèn)定sharedeJedis為主要的垃圾球匕，load間歇性過高的原因正是因?yàn)檫@些垃圾快速的生成和回收所致纹磺。

進(jìn)一步分析

• 看一下我們對SharededJedisPool的配置：

    #最大分配的對象數(shù)
    redis.pool.maxActive=500
    #最大能夠保持idel狀態(tài)的對象數(shù)
    redis.pool.maxIdle=100
    #當(dāng)池內(nèi)沒有返回對象時，最大等待時間
    redis.pool.maxWait=200
    #當(dāng)調(diào)用borrow Object方法時亮曹，是否進(jìn)行有效性檢查
    redis.pool.testOnBorrow=false
    #當(dāng)調(diào)用return Object方法時橄杨，是否進(jìn)行有效性檢查
    redis.pool.testOnReturn=false
  

• 該配置與dump中的pool配置一致。

• 通過netstat grep redisserver的端口乾忱，可以查到只有100個連接讥珍，即可預(yù)估在“夠用”的情況下，redis的連接池中通常只會有100個左右（大多為空閑）

• 那么問題來了：為什么會有這么多ShardedJedis的垃圾呢窄瘟？

• 我們r(jià)edis連接池是用GenericObjectPool來管理的, 需要時從里面借(borrow object)衷佃，用完了再還回去(return object)蹄葱。如果借的時候不夠氏义，就會new一個SharededJedis來給借用者锄列。同時還有一個清理機(jī)制，每隔一段時間去把多余的空閑對象清理掉惯悠。從上圖中可以看出邻邮，這個清理機(jī)制的間隔時間_timeBetweenEvictionRunsMills是30000ms，即30s.

• 進(jìn)一步克婶，這些ShardedJedis能度過Young GC并進(jìn)入old區(qū)筒严，必然是在young區(qū)gc時沒有被清理，從而可推斷該進(jìn)程做一次young GC的周期會遠(yuǎn)小于GenericObjectPool的清理周期情萤。用jstat –gctuil查看：

    [love@love21 ~]$ jstat -gcutil 21416 1000
      S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
      8.67   0.00  43.38  16.74  52.69  56012 2064.246   143   24.948 2089.193
      8.67   0.00  77.59  16.74  52.69  56012 2064.246   143   24.948 2089.193
      0.00   7.91   1.92  16.84  52.69  56013 2064.278   143   24.948 2089.225
      0.00   7.91  34.35  16.84  52.69  56013 2064.278   143   24.948 2089.225
      0.00   7.91  64.58  16.84  52.69  56013 2064.278   143   24.948 2089.225
      0.00   7.91  78.19  16.84  52.69  56013 2064.278   143   24.948 2089.225
      9.43   0.00   0.00  16.90  52.69  56014 2064.311   143   24.948 2089.258
      9.43   0.00  22.36  16.90  52.69  56014 2064.311   143   24.948 2089.258
      9.43   0.00  55.95  16.90  52.69  56014 2064.311   143   24.948 2089.258
      9.43   0.00  90.86  16.90  52.69  56014 2064.311   143   24.948 2089.258
      0.00   8.99  18.07  16.95  52.69  56015 2064.344   143   24.948 2089.292
      0.00   8.99  51.25  16.95  52.69  56015 2064.344   143   24.948 2089.292
      0.00   8.99  72.06  16.95  52.69  56015 2064.344   143   24.948 2089.292
      0.00   8.99  92.20  16.95  52.69  56015 2064.344   143   24.948 2089.292
      7.41   0.00  30.01  17.07  52.69  56016 2064.379   143   24.948 2089.326
      7.41   0.00  65.24  17.07  52.69  56016 2064.379   143   24.948 2089.326
      7.41   0.00  97.34  17.07  52.69  56016 2064.379   143   24.948 2089.326
  

• 可以看到約5s左右就會進(jìn)行一次young GC鸭蛙，與推斷相符。

• 現(xiàn)在筋岛，基本有了一些思路：1. 業(yè)務(wù)中有向GenericObjectPool borrow大量的object(應(yīng)該遠(yuǎn)大于100)的邏輯娶视，2. 并且很可能是定時性的任務(wù)(crontab 或 scheduleTask).

• 結(jié)合上述兩點(diǎn)并結(jié)合代碼最新的改動，發(fā)現(xiàn)有地方將獲取50個數(shù)據(jù)對象改為了獲取250個睁宰，而為了提交性能肪获，會用future模式開多個線程并發(fā)向一個ThreadPoolExecutor 提交大量的任務(wù)，并且該任務(wù)對redis有請求操作柒傻，而這個ThreadPoolExecutor的coreSize是200(注意孝赫，遠(yuǎn)大于redis pool的100):

    private static final ThreadPoolExecutor executor = new ThreadPoolExecutor(200, 400, 3600, TimeUnit.SECONDS, 
            new LinkedBlockingQueue<Runnable>(500), new ThreadFactory() {
        
                private AtomicInteger id = new AtomicInteger(0);
                @Override
                public Thread newThread(Runnable r) {
                    Thread thread = new Thread(r);
                    thread.setName("Love-" + id.addAndGet(1));
                    return thread;
                }
            }, new ThreadPoolExecutor.CallerRunsPolicy());
  

• 再追溯這個50到250的改動，實(shí)際上是可以很簡單的做優(yōu)化的诅愚。

• 至此寒锚，問題定位到，優(yōu)化并上線违孝，不再頻繁出現(xiàn)load過高的問題刹前，即GC不再如此頻繁

經(jīng)驗(yàn)

• 解決一個性能問題好比偵察案件，可以多采集利用分析各種信息雌桑，不要死磕喇喉。雖然最終發(fā)現(xiàn)問題很簡單，并一開始就認(rèn)定問題出在業(yè)務(wù)邏輯上校坑，可幾個人花了不少時間去查代碼拣技，都沒能找到原因。（該問題被一些設(shè)計(jì)模式“隱藏”的較深）