日常Bug排查-系統失去響應-Redis使用不當
前言
日常Bug排查系列都是一些簡單Bug排查，筆者將在這里介紹一些排查Bug的簡單技巧，同時順便積累素材_。
Bug現場
開發反應線上系統出現失去響應的現象，收到業務告警已經頻繁MarkAndSweep(Full GC)告警。於是找到筆者進行排查。
看基礎監控
首先呢，當然是看我們的監控了，找到對應失去響應的系統的ip，看下我們的基礎監控。
機器內存持續上升。因為我們是java系統，堆的大小一開始已經設置了最大值。
--XX:Xms2g -Xmx2g
所以看上去像堆外內存泄露。而FullGC告警只是堆外內存后一些關聯堆內對象觸發。
看應用監控
第二步，當然就是觀察我們的應用監控，這邊筆者用的是CAT。觀察Cat中對應應用的情況，很容易發現，其ActiveThread呈現不正常的現象，竟然達到了5000+多個，同時和內存上升曲線保持一致。
jstack
java應用中遇到線程數過多的現象，首先我們考慮的是jstack，jstack出來對應的文件后。我們less一下，發現很多線程卡在下面的代碼棧上。
"Thread-1234
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park
......
at org.apache.commons.pool2.impl.LinkedBlockingQueue.takeFirst
......
at redis.clients.util.Pool.getResource
很明顯的，這個代碼棧值得是沒有獲取連接，從而卡住。至於為什么卡這么長時間而不釋放，肯定是由於沒設置超時時間。那么是否大部分線程都卡在這里呢，這里我們做一下統計。
cat jstack.txt | grep 'prio=' | wc -l
======> 5648
cat jstack.txt | grep 'redis.clients.util.Pool.getResource'
======> 5242
可以看到，一共5648個線程，有5242，也就是92%的線程卡在Redis getResource中。
看下redis情況
netstat -anp | grep 6379
tcp 0 0 1.2.3.4:111 3.4.5.6:6379 ESTABLISHED
......
一共5個，而且連接狀態為ESTABLISHED，正常。由此可見他們配置的最大連接數是5(因為別的線程正在得到獲取Redis資源)。
Redis連接泄露
那么很自然的想到，Redis連接泄露了，即應用獲得Redis連接后沒有還回去。這種泄露有下面幾種可能:
情況1:
情況2:
情況3：
調用Redis卡住，由於其它機器是好的，故排除這種情況。
如何區分
我們做個簡單的推理:
如果是情況1，那么這個RedisConn肯定可以通過內存可達性分析和Thread關聯上，而且這個關聯關系肯定會關聯到某個業務操作實體(例如code stack or 業務bean)。那么我們只要觀察其在堆內的關聯路線是否和業務相關即可,如果沒有任何關聯，那么基本斷定是情況2了。
可達性分析
我們可以通過jmap dump出應用內存，然后通過MAT(Memory Analysis Tool)來進行可達性分析。
首先找到RedisConn
將dump文件在MAT中打開，然后運行OQL:
select * from redis.clients.jedis.Jedis (RedisConn的實體類)
搜索到一堆Jedis類，然后我們執行
Path To GCRoots->with all references
可以看到如下結果:
redis.clients.jedis.Jedis
|->object
|->item
|->first
|->...
|->java.util.TimerThread
|->internalPool
由此可見，我們的連接僅僅被TimerThread和internalPool(Jedis本身的連接池)持有。所以我們可以判斷出大概率是情況2，即忘了歸還連接。翻看業務代碼:
偽代碼
void lock(){
conn = jedis.getResource()
conn.setNx()
// 結束,此處應該有finally{returnResource()}或者采用RedisTemplate
}
最后就是很簡單的，業務開發在執行setNx操作后，忘了將連接還回去。導致連接泄露。
如果是情況1如何定位卡住的代碼
到此為止，這個問題時解決了。但是如果是情況1的話，我們又該如何分析下去呢？很簡單，我們如果找到了jedis被哪個業務線程擁有，直接從heap dump找到其線程號，然后取Jstack中搜索即可知道其卡住的代碼棧。
jmap:
redis.clients.jedis.Jedis
|->Thread-123
jstack:
Thread-123 prio=...
at xxx.xxx.xxx.blocked
總結
這是一個很簡單的問題，知道套路之后排查起來完全不費事。雖然最后排查出來是個很低級的代碼，但是這種分析方法值得借鑒。
