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