上午剛到公司,準備開始一天的摸魚之旅時忽然收到了一封監控中心的郵件。java
心中暗道很差,由於監控系統歷來不會告訴我應用完美無 bug
,其實系統挺猥瑣。數據庫
打開郵件一看,果真告知我有一個應用的線程池隊列達到閾值觸發了報警。緩存
因爲這個應用出問題很是影響用戶體驗;因而立馬讓運維保留現場 dump
線程和內存同時重啓應用,還好重啓以後恢復正常。因而開始着手排查問題。安全
首先了解下這個應用大概是作什麼的。服務器
簡單來講就是從 MQ
中取出數據而後丟到後面的業務線程池中作具體的業務處理。併發
而報警的隊列正好就是這個線程池的隊列。運維
跟蹤代碼發現構建線程池的方式以下:jsp
ThreadPoolExecutor executor = new ThreadPoolExecutor(coreSize, maxSize,
0L, TimeUnit.MILLISECONDS,
new LinkedBlockingQueue<Runnable>());;
put(poolName,executor);
複製代碼
採用的是默認的 LinkedBlockingQueue
並無指定大小(這也是個坑),因而這個隊列的默認大小爲 Integer.MAX_VALUE
。ide
因爲應用已經重啓,只能從僅存的線程快照和內存快照進行分析。網站
先利用 MAT
分析了內存,的到了以下報告。
其中有兩個比較大的對象,一個就是以前線程池存聽任務的 LinkedBlockingQueue
,還有一個則是 HashSet
。
固然其中隊列佔用了大量的內存,因此優先查看,HashSet
一下子再看。
因爲隊列的大小給的夠大,因此結合目前的狀況來看應當是線程池裏的任務處理較慢,致使隊列的任務越堆越多,至少這是目前能夠得出的結論。
再來看看線程的分析,這裏利用 fastthread.io 這個網站進行線程分析。
由於從表現來看線程池裏的任務遲遲沒有執行完畢,因此主要看看它們在幹嗎。
正好他們都處於 RUNNABLE 狀態,同時堆棧以下:
發現正好就是在處理上文提到的 HashSet
,看這個堆棧是在查詢 key
是否存在。經過查看 312 行的業務代碼確實也是如此。
這裏的線程名字也是個坑,讓我找了很久。
分析了內存和線程的堆棧以後其實已經大概猜出一些問題了。
這裏其實有一個前提忘記講到:
這個告警是凌晨三點
發出的郵件,但並無電話提醒之類的,因此你們都不知道。
到了早上上班時才發現並當即 dump
了上面的證據。
全部有一個很重要的事實:這幾個業務線程在查詢 HashSet
的時候運行了 6 7 個小時都沒有返回。
經過以前的監控曲線圖也能夠看出:
操做系統在以前一直處於高負載中,直到咱們早上看到報警重啓以後才下降。
同時發現這個應用生產上運行的是 JDK1.7
,因此我初步認爲應該是在查詢 key 的時候進入了 HashMap
的環形鏈表致使 CPU
高負載同時也進入了死循環。
爲了驗證這個問題再次 review 了代碼。
整理以後的僞代碼以下:
//線程池
private ExecutorService executor;
private Set<String> set = new hashSet();
private void execute(){
while(true){
//從 MQ 中獲取數據
String key = subMQ();
executor.excute(new Worker(key)) ;
}
}
public class Worker extends Thread{
private String key ;
public Worker(String key){
this.key = key;
}
@Override
private void run(){
if(!set.contains(key)){
//數據庫查詢
if(queryDB(key)){
set.add(key);
return;
}
}
//達到某種條件時清空 set
if(flag){
set = null ;
}
}
}
複製代碼
大體的流程以下:
Set
。Set
中。這裏有一個很明顯的問題,那就是做爲共享資源的 Set 並無作任何的同步處理。
這裏會有多個線程併發的操做,因爲 HashSet
其實本質上就是 HashMap
,因此它確定是線程不安全的,因此會出現兩個問題:
第一個問題相對於第二個還能接受。
經過上文的內存分析咱們已經知道這個 set 中的數據已經很多了。同時因爲初始化時並無指定大小,僅僅只是默認值,因此在大量的併發寫入時候會致使頻繁的擴容,而在 1.7 的條件下又可能會造成環形鏈表。
不巧的是代碼中也有查詢操做(contains()
),觀察上文的堆棧狀況:
發現是運行在 HashMap
的 465 行,來看看 1.7 中那裏具體在作什麼:
已經很明顯了。這裏在遍歷鏈表,同時因爲造成了環形鏈表致使這個 e.next
永遠不爲空,因此這個循環也不會退出了。
到這裏其實已經找到問題了,但還有一個疑問是爲何線程池裏的任務隊列會越堆越多。我第一直覺是任務執行太慢致使的。
仔細查看了代碼發現只有一個地方可能會慢:也就是有一個數據庫的查詢。
把這個 SQL 拿到生產環境執行發現確實不快,查看索引起現都有命中。
但我一看錶中的數據發現已經快有 7000W 的數據了。同時通過運維得知 MySQL
那臺服務器的 IO
壓力也比較大。
因此這個緣由也比較明顯了:
因爲每消費一條數據都要去查詢一次數據庫,MySQL 自己壓力就比較大,加上數據量也很高因此致使這個 IO 響應較慢,致使整個任務處理的就比較慢了。
但還有一個緣由也不能忽視;因爲全部的業務線程在某個時間點都進入了死循環,根本沒有執行完任務的機會,然後面的數據還在源源不斷的進入,因此這個隊列只會越堆越多!
這實際上是一個老應用了,可能會有人問爲何以前沒出現問題。
這是由於以前數據量都比較少,即便是併發寫入也沒有出現併發擴容造成環形鏈表的狀況。這段時間業務量的暴增正好把這個隱藏的雷給揪出來了。因此仍是得信墨菲他老人家的話。
至此整個排查結束,而咱們後續的調整措施大概以下:
HashSet
不是線程安全的,換爲 ConcurrentHashMap
同時把 value
寫死同樣能夠達到 set
的效果。ConcurrentHashMap
的大小盡可能大一些,避免頻繁的擴容。MySQL
中不少數據都已經不用了,進行冷熱處理。儘可能下降單表數據量。同時後期考慮分表。JDK1.8
。HashMap
的死循環問題在網上層出不窮,沒想到還真被我遇到了。如今要知足這個條件仍是挺少見的,好比 1.8 如下的 JDK
這一條可能大多數人就碰不到,正好又證明了一次墨菲定律。
同時我會將文章更到這裏,方便你們閱讀和查詢。
你的點贊與分享是對我最大的支持