大家好，我是鴨血粉絲（大家會親切的喊我 「阿粉」），是一位喜歡吃鴨血粉絲的程式設計師，回想起之前線上出現 OOM 的場景，畢竟當時是第一次遇到這麼 緊髒 的大事，要好好記錄下來。

1 事情回顧

在某次週五，通過 Grafana 監控，發現線上環境突然出現CPU和記憶體飆升的情況：

但是看到網路輸出和輸入流量都不是很高，所以網站被別人攻擊的概率不高，後來其它伺服器的負荷居高不下。

阿粉先 dump 下當時的堆疊資訊，保留現場，接著進行了簡單的分析，為了穩住使用者，通知運維一臺一臺伺服器進行重新啟動，讓大家繼續使用服務。

接著就開始分析和回顧事情了

2 開始分析

2.1 日誌分析

建議大家瞭解一些常用的 Linux 語法，例如 Grep

既然伺服器在某個時間點出現了高負荷，於是就先去找一開始出現問題的伺服器，去找耗時比較長的服務，例如我當時去找資料庫耗時的服務，由於發生 OOM 時的日誌已經被刷掉，於是我大致描述一下：

[admin@xxx xxxyyyy]$ grep '15:14:' common-dal-digest.log |  grep -E '[0-9]{4,}ms'
2018-08-25 15:14:21,656 - [(xxxxMapper,getXXXListByParams,Y,1089ms)](traceId=5da451277e14418abf5eea18fd2b61bf)
 

很明顯，上述語句是 查詢在15:14那一分鐘內，在common-dal-digest.log檔案中，耗時超過1000ms的SQL服務（查的是耗時超過10秒的服務）。

日誌中有個特殊的標誌 traceId，在請求鏈路中是唯一的，所以根據這個標誌能分析單請求的全鏈路操作，建議大家的日誌框架中也加上這種欄位，讓服務可追溯和排查。

通過 traceId去查 http 儲存的訪問日誌，定位在該時間點內，分發到該伺服器上的使用者請求。還有根據該traceId，定位到整個呼叫流程所使用到的服務，發現的確十分耗時...

於是拿到了該請求具體資訊，包括使用者的登入手機號碼，因為這個時候，其它幾臺伺服器也出現了 CPU 和記憶體負載升高，於是根據手機號查詢了其它幾臺伺服器的訪問日誌，發現同一個請求，該使用者也呼叫了很多次...

於是初步確認了某個耗時介面

2.2 使用 MAT 分析 dump 檔案

官方介紹：

MAT 是 Memory Analyzer 的簡稱，它是一款功能強大的 Java 堆記憶體分析器。可以用於查詢記憶體洩露以及檢視記憶體消耗情況。MAT 是基於Eclipse開發的，是一款免費的效能分析工具。讀者可以在 http://www.eclipse.org/mat/ 下載並使用 MAT。

在前面提到，出現問題時，順手儲存了一份堆疊資訊，使用工具開啟後，效果圖如下所示：

整個應用的記憶體大小 1.6G，然後有一塊記憶體塊竟然佔用了 1.4G，佔比達到了 87.5%，這也太離譜了吧！

於是阿粉決定好好分析該物件的引用樹，右鍵選擇【class_reference】，檢視物件列表，和觀察 GC 日誌，定位到具體的物件資訊。

2.3 根本原因

通過日誌分析以及 dump 檔案分析，都指向了某個檔案匯出介面，接著在程式碼中分析該介面具體呼叫鏈路，發現匯出的資料很多，而且老程式碼進行計算的邏輯嵌套了很多 for 迴圈，而且是 for 迴圈呼叫資料庫，計算效率極低。

模擬了該使用者在這個介面的所呼叫資料量，需要查詢多個表，然後 for 迴圈中大概會計算個 100w+ 次，導致阻塞了其它請求，由於請求未結束，java 物件無法被 GC 回收，線上的伺服器 CPU 和記憶體使用情況一直飆升。

3 效能優化

3.1 業務、程式碼邏輯梳理

點開該段程式碼的 git 提交記錄，發現是我在實習期寫的時候，我的內心是崩潰的，當時對業務不熟悉，直接迴圈呼叫了老程式碼，而且也沒有測試過這麼大的資料量，所以 GG了。

然後我就開始做程式碼效能優化，首先仔細梳理了一下整個業務流程，通過增加 SQL 查詢條件，減少資料庫 IO 和查詢返回的資料量，優化判斷條件，減少 for 巢狀、迴圈次數和計算量。

3.2 通過 VisualVM 進行對比

官方描述：

VisualVM，能夠監控執行緒，記憶體情況，檢視方法的CPU時間和記憶體中的物件，已被GC的物件，反向檢視分配的堆疊(如100個String物件分別由哪幾個物件分配出來的).

該外掛不需要另外下載，在 ${JAVA_HOME}/bin 目錄下就能找到，所以安裝了 jdk 就能使用它~

對比了新老程式碼所佔用的 CPU 時間和記憶體狀態

優化前：

優化後：

通過上述優化之後，計算 1w 條資料量，進行匯出成報表檔案，在老程式碼需要 48s，新程式碼下降到了 8s，不過這是大資料量的情況下，實際使用者的資料沒有這麼多，所以基本上滿足了線上 99% 的使用者使用。（看到這個結果時，阿粉露出了「純潔的微笑」）

當然，由於這些資料是本地開發環境新增加的，與出現 OOM 問題的使用者資料量還有些差別，但通過優化後的程式碼，已經在資料庫查詢的時候就過濾掉很多無效的資料，在 for 迴圈計算前也加了過濾條件，所以真正計算起來起來就降低了很多計算量！

恩，自己程式碼優化好了，還要等測試爸爸們測試後才敢上線，這次要瘋狂造資料!

4 技術總結

阿粉週末會自己做點飯