「舉報」阿里巴巴 Arthas，大幅下降 OOM Trouble shooting 門檻

做者 | Mason MA

【Arthas 官方社區正在舉行徵文活動，參加即有獎品拿哦~點擊投稿】

Arthas 是個不錯的工具，這裏要再安利一波，固然整個過程還用到了其餘工具，如 MAT、YourKIT（這個是付費的），結合起來使用更加便於發現和解決問題。期間還和開發大佬屢次溝通，分別獲取了不一樣的信息。

一鍵安裝並啓動 Arthas

• 方式一：經過 Cloud Toolkit 實現 Arthas 一鍵遠程診斷

Cloud Toolkit 是阿里雲發佈的免費本地 IDE 插件，幫助開發者更高效地開發、測試、診斷並部署應用。經過插件，能夠將本地應用一鍵部署到任意服務器，甚至雲端（ECS、EDAS、ACK、ACR 和 小程序雲等）；而且還內置了 Arthas 診斷、Dubbo工具、Terminal 終端、文件上傳、函數計算 和 MySQL 執行器等工具。不只僅有 IntelliJ IDEA 主流版本，還有 Eclipse、Pycharm、Maven 等其餘版本。

推薦使用 IDEA 插件下載 Cloud Toolkit 來使用 Arthas：http://t.tb.cn/2A5CbHWveOXzI7sFakaCw8 

• 方式二：直接下載

地址：https://github.com/alibaba/arthas。

現象

• 建索引的後臺應用，感受用不到那麼大內存，如今用到了而且隔兩天就會 oom，須要重啓；
• 有全量數據和增量數據，OOM 大多發生在全量數據寫入階段，且 OOM 基本都在凌晨首次觸發全量數據更新時出現；
• 業務應用使用了 G1 收集器（高級高級...）。

心裏 OS：糟糕，G1 還不熟可怎麼辦，先想個辦法把大佬們支開，我本身再慢慢研究。

我還有點別的事兒，我等會再看

苟膽假設

在現有掌握的信息下判斷，大膽假設一下，反正猜錯了又不會賠錢。

• 是不是由於全量數據寫入，超過了堆的承載能力，致使了 OOM？
• 業務是否有 static 容器使用不當，一直沒回收，一直往裏 put 元素，因此須要兩天 OOM 一次？
• 內存不夠，是哪些對象佔用最多，先找出來看看？
• 有沒有大對象？

發抖求證

基本信息

進程啓動參數

-Xms12g 
-Xmx12g
-XX:+UseG1GC 
-XX:InitiatingHeapOccupancyPercent=70 
-XX:MaxGCPauseMillis=200 
-XX:G1HeapWastePercent=20 
-XX:+PrintAdaptiveSizePolicy 
-XX:+UseStringDeduplication 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintTenuringDistribution 
-Xloggc:/home/search/fse2/gc.log
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=2 
-XX:GCLogFileSize=512M 
-XX:+UnlockDiagnosticVMOptions 
-XX:+PrintNMTStatistics 
-XX:NativeMemoryTracking=summary

能夠看到，使用了 G1 收集器，這個以前作業務開發的時候還不常見呢，畢竟是爲大內存打造的追求低延遲的垃圾回收器。關於 G1 收集器的一些基本特性，你們能夠去搜集一些資料。大概主要包括如下幾項：

• Region 分區機制
• SATB，全稱是 Snapshot-At-The-Beginning，由字面理解，是 GC 開始時活着的對象的一個快照
• Rset，全稱是 Remembered Set，是輔助 GC 過程的一種結構，空間換時間思想
• Pause Prediction Model 即停頓預測模型

從 G1 的這些屬性來看，它指望作到減小人爲操做調優，實現自動化的調優（說到這裏，感受本次出現的 OOM 彷佛跟垃圾收集器自己關聯並不大，並非由於業務量大堆內存不夠用，可能根本緣由在代碼邏輯層面），而且適應在硬件成本下降，大內存堆逐漸變多的場景（後面還有 ZGC 和 Shenandoah，一樣是能夠管理超大內存並停頓很低的神奇垃圾收集器）。

已經有GC日誌了，那先看看日誌，發現一處異常：

#### 這裏Heap回收的還只是300多M內存
[Eden: 316.0M(956.0M)->0.0B(1012.0M) Survivors: 48.0M->44.0M Heap: 359.2M(12.0G)->42.0M(12.0G)]
 [Times: user=0.31 sys=0.01, real=0.05 secs]
2020-06-09T02:59:23.489+0800: 2020-06-09T02:59:23.489+0800: 35.922: Total time for which application threads were stopped: 0.0578199 seconds, Stopping threads took: 0.0000940 seconds
35.922: [GC concurrent-root-region-scan-start]
......
......
......
#### 這個點Heap回收的就是11G內存了
[Eden: 724.0M(1012.0M)->0.0B(540.0M) Survivors: 44.0M->72.0M Heap: 11.5G(12.0G)->355.6M(12.0G)] 
 [Times: user=1.51 sys=0.07, real=0.26 secs]
2020-06-09T03:12:36.329+0800: 828.762: Total time for which application threads were stopped: 0.2605902 seconds, Stopping threads took: 0.0000600 seconds

初次調試

增長 -XX:G1ReservePercent 選項的值，爲「目標空間」增長預留內存量。

減小 -XX:InitiatingHeapOccupancyPercent 提早啓動標記週期

懷疑在 GC 的當時，有大量數據全量寫入，內存還沒回收完，寫進大量對象，致使了 OOM，因而調了啓動週期，佔比由 70 降低到55，提早觸發，預留更多堆空間。

GC 變得頻繁了，可是內存佔用過大的問題並無獲得解釋。而且是否會再次在凌晨出現 OOM 還須要等。。。因而還要繼續看看有沒有別的問題。

繼續挖掘

有疑點沒有解答，確定是要繼續挖掘的，抄起鍵盤就是幹，一頓操做猛如虎。

Arthas

不知道哪位已經安裝了，先拿來用用看吧，大概用到了如下幾個命令：

dashboard

看看基本狀況，線程數，堆大小，老年代大小，使用佔比狀況。首次看到這裏時，eden 和 old 區的佔用都挺高的， 70~80% 吧（當時忘了截圖）。內存使用率比較高。

thread

看看線程數有沒有異常，線程數正常，只是找出了資源佔用比較高的線程，其中一個線程在後面其餘信息統計中還會出現：

YJPAgent-Telemetry 
ctrl-bidsearch-rank-shard1
YJPAgent-RequestListener
ctrl-bidsearch-rank-shard1

竟然有兩個線程是 YourKit 監控工具的 agent，看來這個監控工具對性能影響還挺大的。

profiler

分別採集一下內存和 CPU 的火焰圖數據：

# 內存
profiler start --event alloc
###
profiler stop

# 默認CPU
profiler start
###
profiler stop

• CPU

• 內存

從 CPU 火焰圖看到，G1 收集器線程竟然佔了一半資源，可能採集當時正在進行 GC，不過，除此以外，基本都能定位到是一個叫 IncrementIndexService 的類，使用了比較多的 CPU 和內存資源。

若是業務代碼真的存在缺陷，那麼必定在這個流程裏，後來通過溝通，發現這個應用處理任務主要入口的確是在這裏面。先持有保留意見。

thread 看到的線程和 profiler 看到的 class，都最終定位到是同一個業務流程。

開始驗證以前的猜測：

1. 是否在全量數據寫入的時候有大量對象涌入內存？

計算了一些業務代碼獲取數據的量，元數據大約也就在 1.3G 左右，就算全量寫入，也不該該佔用 12G 的堆內存，因此猜想全量數據寫入時，代碼邏輯可能有什麼缺陷，致使 1.3G 的原數據被封裝成遠大於 1.3G 的對象了。

2. 是否有 static 容器？

有，可是通過 watch 觀察，沒有發現容器只 put 不 remove 的狀況，命令以下：

watch com.xxx.classname method "{params,target}" -x 3

3. 有沒有大對象？

對於 G1，默認將堆分紅 2048 個 Region，12G 的堆，一個 Region 是 6M，超過 3M 纔是大對象。

jmap histo 30123

至少輸出的數據中，大對象不是 G1 定義的大對象。

MAT

既然沒什麼發現，就把堆 dump 出來吧。若是不想或者不能 dump，也能夠用 jmap histo 查看內存佔用，優勢是不用 dump，缺點是一般不能很好的和業務代碼之間創建關聯。

警告：jmap 或者 Arthas 的 heapdump 操做以前必定要斷開流量。好在咱們這個服務沒有線上流量，建索引有延遲，可能短暫影響搜索體驗。

dump 出來以後，發現有 7 個 G，這麼大的文件通常很難傳到本地來分析了，因而用 MAT，佔用服務器 1 個 G 內存進行分析，分析完成的結果下載到本地。

線程名稱和以前發現的信息吻合，點開 detail 有驚喜。

一串奇怪的字符串，有點像 XML，好像在拼裝着什麼，因而找到業務大佬請教，發現的確有拼裝 solrDocument 的邏輯，並且，通過 YourKit 輸出部分對象值的片斷，能夠發現有大部分是在重複拼裝，大概意思以下：

<xml>
...
<country>CA</country>
<country>CA</country>
<country>CA</country>
<country>CA</country>
<country>CA</country>
...n次重複
<country>US</country>
<country>US</country>
<country>US</country>
<country>US</country>
<country>US</country>
<country>US</country>
...n次重複
<country>UK</country>
<country>UK</country>
...
</xml>

代碼邏輯修改其實比較簡單了，業務開發大佬們比較熟悉業務流程，很快就就有了修改方案。

調整以後發現，內存使用量降低了不少。

直接降到了 4-5G 左右，若是是這樣的話，即使全量數據寫入時，正在作垃圾回收，應該仍是夠用的。可是感受這個代碼邏輯裏面，應該還有優化空間，不過，先解決問題，優化能夠作下一步操做。

覆盤

不管從哪一個工具得出的數據，都顯示 IncrementIndexService 這個類的邏輯可能有問題，最終問題的根本和 G1 參數設置好像也沒什麼關係，代碼邏輯缺陷纔是根源，再擴大內存可能或者調整 JVM 參數，也只能將故障緩解，可是不能解決。

• 從進程到線程到代碼
• 獲取 JVM 基本信息，收集器，啓動參數等信息
• 查看現有的日誌，GC 日誌，業務日誌
• 溝通業務場景，瞭解輸入數據規模等等
• 猜測可能存在的緣由，大膽的猜
• 使用工具（Arthas、MAT、YourKit、JDK 自帶命令等等）挖掘信息，火焰圖、耗能線程、線程棧 堆dump，佔比分析 大對象 ...
• 結合數據從新梳理，發現業務代碼的關聯和可能存在的缺陷，能夠嘗試調整參數
• 業務代碼如有 bug，修復 bug

Arthas 徵文活動火熱進行中

Arthas 官方正在舉行徵文活動，若是你有：

• 使用 Arthas 排查過的問題
• 對 Arthas 進行源碼解讀
• 對 Arthas 提出建議
• 不限，其它與 Arthas 有關的內容

  歡迎參加徵文活動，還有獎品拿哦~點擊投稿

「 阿里巴巴雲原生關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，作最懂雲原生開發者的公衆號。」