前言

日常Bug排查系列都是一些簡單Bug排查，筆者將在這里介紹一些排查Bug的簡單技巧，同時順便積累素材^_^。

Bug現(xiàn)場

開發(fā)反應線上系統(tǒng)出現(xiàn)失去響應的現(xiàn)象，收到業(yè)務告警以及頻繁MarkAndSweep(Full GC)告警。于是找到筆者進行排查。

看基礎(chǔ)監(jiān)控

首先呢，當然是看我們的監(jiān)控了，找到對應失去響應的系統(tǒng)的ip，看下我們的基礎(chǔ)監(jiān)控。

機器內(nèi)存持續(xù)上升。因為我們是java系統(tǒng)，堆的大小一開始已經(jīng)設置了最大值。

1. --XX:Xms2g -Xmx2g 

所以看上去像堆外內(nèi)存泄露。而FullGC告警只是堆外內(nèi)存后一些關(guān)聯(lián)堆內(nèi)對象觸發(fā)。

看應用監(jiān)控

第二步，當然就是觀察我們的應用監(jiān)控，這邊筆者用的是CAT。觀察Cat中對應應用的情況，很容易發(fā)現(xiàn)，其ActiveThread呈現(xiàn)不正常的現(xiàn)象，竟然達到了5000+多個，同時和內(nèi)存上升曲線保持一致。

jstack

java應用中遇到線程數(shù)過多的現(xiàn)象，首先我們考慮的是jstack，jstack出來對應的文件后。我們less一下，發(fā)現(xiàn)很多線程卡在下面的代碼棧上。

1. "Thread-1234 
2.     java.lang.Thread.State: WAITING (parking) 
3.         at sun.misc.Unsafe.park 
4.         ...... 
5.         at org.apache.commons.pool2.impl.LinkedBlockingQueue.takeFirst 
6.         ...... 
7.         at redis.clients.util.Pool.getResource 

很明顯的，這個代碼棧指的是沒有獲取連接，從而卡住。至于為什么卡這么長時間而不釋放，肯定是由于沒設置超時時間。那么是否大部分線程都卡在這里呢，這里我們做一下統(tǒng)計。

1. cat jstack.txt | grep 'prio=' | wc -l  
2. ======> 5648 
3. cat jstack.txt | grep 'redis.clients.util.Pool.getResource'  
4. ======> 5242 

可以看到，一共5648個線程，有5242，也就是92%的線程卡在Redis getResource中。

看下redis情況

1. netstat -anp | grep 6379  
2. tcp 0 0 1.2.3.4:111 3.4.5.6:6379 ESTABLISHED 
3. ...... 

一共5個，而且連接狀態(tài)為ESTABLISHED，正常。由此可見他們配置的最大連接數(shù)是5(因為別的線程正在等待獲取Redis資源)。

Redis連接泄露

那么很自然的想到，Redis連接泄露了，即應用獲得Redis連接后沒有還回去。這種泄露有下面幾種可能:

情況1:

情況2:

情況3：

調(diào)用Redis卡住，由于其它機器是好的，故排除這種情況。

如何區(qū)分

我們做個簡單的推理:

如果是情況1，那么這個RedisConn肯定可以通過內(nèi)存可達性分析和Thread關(guān)聯(lián)上，而且這個關(guān)聯(lián)關(guān)系肯定會關(guān)聯(lián)到某個業(yè)務操作實體(例如code stack or 業(yè)務bean)。那么我們只要觀察其在堆內(nèi)的關(guān)聯(lián)路線是否和業(yè)務相關(guān)即可,如果沒有任何關(guān)聯(lián)，那么基本斷定是情況2了。

可達性分析

我們可以通過jmap dump出應用內(nèi)存，然后通過MAT(Memory Analysis Tool)來進行可達性分析。

首先找到RedisConn

將dump文件在MAT中打開，然后運行OQL:

1. select * from redis.clients.jedis.Jedis (RedisConn的實體類) 

搜索到一堆Jedis類，然后我們執(zhí)行

1. Path To GCRoots->with all references 

可以看到如下結(jié)果:

1. redis.clients.jedis.Jedis 
2.     |->object  
3.         |->item 
4.             |->first 
5.                 |->... 
6.                     |->java.util.TimerThread 
7.                 |->internalPool 

由此可見，我們的連接僅僅被TimerThread和internalPool(Jedis本身的連接池)持有。所以我們可以判斷出大概率是情況2，即忘了歸還連接。翻看業(yè)務代碼:

1. 偽代碼 
2. void lock(){ 
3.     conn = jedis.getResource() 
4.     conn.setNx() 
5.     // 結(jié)束,此處應該有finally{returnResource()}或者采用RedisTemplate 
6. } 

最后就是很簡單的，業(yè)務開發(fā)在執(zhí)行setNx操作后，忘了將連接還回去。導致連接泄露。

如果是情況1如何定位卡住的代碼

到此為止，這個問題是解決了。但是如果是情況1的話，我們又該如何分析下去呢?很簡單，我們?nèi)绻业搅薺edis被哪個業(yè)務線程擁有，直接從heap dump找到其線程號，然后取Jstack中搜索即可知道其卡住的代碼棧。

1. jmap: 
2. redis.clients.jedis.Jedis 
3.     |->Thread-123 
4.  
5. jstack: 
6.  
7. Thread-123 prio=... 
8.     at xxx.xxx.xxx.blocked 

總結(jié)

這是一個很簡單的問題，知道套路之后排查起來完全不費事。雖然最后排查出來是個很低級的代碼，但是這種分析方法值得借鑒。

原文鏈接：https://mp.weixin.qq.com/s/kbtqc3oz0_pT91dVK_oU9A