作者 | Mason MA

【Arthas 官方社群正在舉行徵文活動，參加即有獎品拿哦~[**點選投稿**](http://alibabacloud.mikecrm.com/9khcRrs)】

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](http://t.tb.cn/2A5CbHWveOXzI7sFakaCw8)

- **方式二：直接下載**

地址：[https://github.com/alibaba/arthas](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% 吧（當時忘了截圖）。記憶體使用率比較高。

![1.png](https://ucc.alicdn.com/pic/developer-ecology/60a28823578e417faddadfb9602593e4.png)

### 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

![2.png](https://ucc.alicdn.com/pic/developer-ecology/b557c9a0444741949d4f26e166c6a287.png)

- 記憶體

![3.png](https://ucc.alicdn.com/pic/developer-ecology/a92b9a0699104ebe90c822a8499ac2e1.png)

從 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 記憶體進行分析，分析完成的結果下載到本地。

![4.png](https://ucc.alicdn.com/pic/developer-ecology/b967d9f69af24e468092f5ca91d0af07.png)

執行緒名稱和之前發現的資訊吻合，點開 detail 有驚喜。

![5.png](https://ucc.alicdn.com/pic/developer-ecology/0f97972b9db14c8ab36c9ecd7b3b5119.png)

一串奇怪的字串，有點像 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>
```

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

調整之後發現，記憶體使用量下降了很多。

![6.png](https://ucc.alicdn.com/pic/developer-ecology/fb79036489df4e9ea703566108db78ef.png)

直接降到了 4-5G 左右，如果是這樣的話，即便全量資料寫入時，正在做垃圾回收，應該還是夠用的。但是感覺這個程式碼邏輯裡面，應該還有最佳化空間，不過，先解決問題，最佳化可以做下一步操作。

# 覆盤

無論從哪個工具得出的資料，都顯示 `IncrementIndexService` 這個類的邏輯可能有問題，最終問題的根本和 G1 引數設定好像也沒什麼關係，程式碼邏輯缺陷才是根源，再擴大記憶體可能或者調整 JVM 引數，也只能將故障緩解，但是不能解決。

- 從程式到執行緒到程式碼

- 獲取 JVM 基本資訊，收集器，啟動引數等資訊

- 檢視現有的日誌，GC 日誌，業務日誌

- 溝通業務場景，瞭解輸入資料規模等等

- 猜想可能存在的原因，大膽的猜

- 使用工具（Arthas、MAT、YourKit、JDK 自帶命令等等）挖掘資訊，火焰圖、耗能執行緒、執行緒棧 堆dump，佔比分析 大物件 ...

- 結合資料重新梳理，發現業務程式碼的關聯和可能存在的缺陷，可以嘗試調整引數

- 業務程式碼若有 bug，修復 bug

# Arthas 徵文活動火熱進行中
Arthas 官方正在舉行徵文活動，如果你有：

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

歡迎參加徵文活動，還有獎品拿哦~[點選投稿](http://alibabacloud.mikecrm.com/9khcRrs)

> “[阿里巴巴雲原生](http://mp.weixin.qq.com/s?__biz=MzUzNzYxNjAzMg==&mid=2247489867&idx=1&sn=1e52e16f370541de77f84d4a3b100a2d&chksm=fae51284cd929b926bbed215cd609da749ba265693ebc08b1af1f027bf8a1b0e0d9aa682d99b&token=1335200991&lang=zh_CN#rd)關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，做最懂雲原生開發者的公眾號。”

“舉報”阿里巴巴 Arthas，大幅降低 OOM Trouble shooting 門檻

相關文章