日常Bug排查-系統失去響應-Redis使用不當

Al發表於2021-05-20
Redis

日常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

總結

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

相關文章