1. 程式人生 > 實用技巧 >震驚!神祕 Bug 竟導致 8 核伺服器 load 破百!

震驚!神祕 Bug 竟導致 8 核伺服器 load 破百!

好吧我承認我也加入了 “UC 震驚部”,那麼大家請跟隨我的文章,一步步走進當天的場景。

場景復現

陽光明媚的一個上午,身為“Bug 小王子”的我正在開開心心的敲著自己的新需求程式碼。此時,業務反饋群中突然反饋:頁面響應變慢!業務報錯!整個平臺陷入僵死狀態!我的心裡頓時一驚,開始想早上吃了什麼 開始想昨晚有沒有更新,最近有沒有上什麼可能會導致平臺卡死的需求。同時我的手上動作並沒有停,快速的開啟 4 臺業務機器並輸入了 top 指令。此時發現了一臺伺服器的如下一幕
業務機器
四臺機器 CPU 幾乎滿載,但此時 load 還不高。但不到一分鐘,1號機的 load 直接飆至 100+
 load 破百
是的你沒看錯,8 核伺服器 load average 竟然破百了!我的天,這業務跑得動才有鬼呢!這時 8 個 CPU 的 us 也很快飆到了近 100;啥也別想了,抓緊時間查。但先讓業務跑起來,於是先重啟了兩臺機器,讓兩臺伺服器先恢復業務。

排查問題

在歷經了懷疑昨日更新程式碼,懷疑MySQL、Redis、ES,懷疑阿里雲宿主機等各種靠譜的離譜的原因之後(整個過程過於艱辛,此處不再贅述),開始了我“迴歸正軌”的排錯歷程。首先我在這臺機器上使用 top -Hp [pid] 指令,檢視 Java 程序裡到底是哪幾個執行緒把 CPU 跑的都要炸了。然後發現了幾個 id 連著的執行緒。趕緊通過 jstack -l [pid] 命令去打一個新鮮的 ThreadDump 下來看。然後把上面 top 命令看到的幾個執行緒 id 拿出來進行 16 進位制化,並把轉化後的去 threadDump 的日誌檔案中搜索。發現是 GC 執行緒:
threadDump
欸,奇了怪。這裡為什麼 GC 會佔用這麼高的 CPU 啊?再去伺服器上 jstat -gcutil [pid]

看一下,不看不要緊,一看嚇一跳!
gc
我滴個乖乖,這 E 區和 O 區全都近 100% 了,FGC 1-2 秒執行一次,這不卡死才有鬼呢!找到原因了,記憶體洩漏了唄(其實最終並不是這個原因)!由於前段時間自己為了降低 Redis 的 QPS,使用 Hutool 的快取工具在記憶體中快取了一份熱點資料,那肯定就是這個問題咯。然後狠狠罵了 Hutool 一頓(對不起對不起,錯怪你了)之後,暫時關掉本地快取,重啟,美滋滋的等著問題解決。是的,沒過 5 分鐘,又炸了。上伺服器一看,依然是 GC 不掉。我急眼了,逼老子用 jmap 做 heapDump 是不是(jmap 會引起 STW,可能會導致應用問題,所以使用時需謹慎)!這時候也顧不上會不會 STW 了,畢竟 CPU 100% 了,就算不 STW 他也跑不動了。但是很快現實打了我的臉,CPU 都給你跑滿了,你想做 dump?做夢!敲完 jmap -dump:format=b,file=filename [pid]
命令後,伺服器毫不留情的扔了我一個錯誤(此處沒有截圖,所以大家只能看文字版啦)

20176: Unable to open socket file: target process not responding or HotSpot VM not loaded
The -F option can be used when the target process is not responding

大致意思就是 JVM 沒響應,等著吧。經過重啟、等待和不停的嘗試後,終於趕在 CPU 跑滿前做好了一個 dump。
看到 1.2 G 的 dump 檔案被下載下來時,我彷彿能聽到我電腦的哀嚎聲。那也得幹啊,開啟 mat,熟悉的介面展現在我眼前。毫不猶豫,Leak Suspects Report (洩漏嫌疑人報告,即記憶體洩露分析,幫助檢視哪些物件正在存活,和為什麼不會被 GC)。
mat
當看到下面這張圖時,我的內心是狂喜的。
逃逸
終於找到你了!讓我們來看看到底是什麼東西佔了這麼大記憶體還特喵的不給我釋放!

洩露分析
洩露分析-2
到這裡就已經能看到是 Mysql 的問題了,然後接著往下看堆疊
洩露分析-3
終於找到元凶了,原來是查詢資料庫的時候資料物件過大。但是為什麼會這麼大且回收不掉呢?我突然想到了之前排查問題時看到的有一個慢 SQL 返回了 2000w 的行數。接著往下看堆疊也印證了我的猜想,就是那裡的業務問題。再往後找,就是前端引數漏傳,導致一次性查詢了表中所有資料約 2000w 行的資料量。
所以導致這次問題的罪魁禍首就是這個查詢。幾次查詢把記憶體打滿,這時 GC 會過來回收,但是因為在把行資料轉化為物件資料,所以強引用回收不掉,於是 GC 就不停的過來空轉。空轉的結果就是把 CPU 打滿,load 增高,導致剛才說的轉化過程變慢。這邊越慢,那邊空轉越快。於是這個惡性迴圈就造成了 load 飆高,CPU 打滿,業務停擺的現象。

總結

總結一下本次事故的排查過程吧

  1. top [pid] 發現 load 增高,cpu 打滿
  2. top -Hp [pid] 查詢高 cpu 的執行緒 id
  3. jstack -l 做一個執行緒 dump
  4. 將步驟 2 中的 id 轉化為 16 進位制,在 jstack 中查詢這個執行緒在做什麼
  5. 發現是 gc 的執行緒後,jstat -gcutil [pid] 1s 查詢每秒鐘的記憶體回收情況
  6. 發現 E 區 和 O 區記憶體滿載,回收不掉後。用 jmap -dump:format=b,file=filename [pid] 做 heapdump 檢視問題
  7. 利用 mat 工具將 heapdump 開啟。檢視、定位洩露物件是什麼。檢視堆疊定位程式碼位置、業務邏輯等
  8. 追看慢 SQL 加以確認,修改邏輯加上驗證,重啟恢復

得到的教訓就是這種大資料量的表和業務,一定要做查詢上的限制,必須分頁查詢等。如果漏傳引數一定要做兜底保護,避免這種查全表的情況出現。

嘮嘮叨叨用了一天的時間才找到問題解決問題,希望自己下次再碰到這種問題不會再去走彎路,可以快速找到吧。


讀書越多越發現自己的無知,Keep Fighting!

歡迎友善交流,不喜勿噴~

Hope can help~

微信搜尋 程式設計師的起飛之路 或微信掃描下方二維碼可以加我公眾號,保證一有乾貨就更新~
公眾號