生產事故-記一次特殊的OOM排查

入職多年，面對生產環境，儘管都是小心翼翼，慎之又慎，還是難免捅出簍子。輕則滿頭大汗，面紅耳赤。重則系統停擺，損失資金。每一個生產事故的背後，都是寶貴的經驗和教訓，都是項目成員的血淚史。為了更好地防範和遏制今後的各類事故，特開此專題，長期更新和記錄大大小小的各類事故。有些是親身經歷，有些是經人耳傳口授，但無一例外都是真實案例。

註意：為了避免不必要的麻煩和商密問題，文中提到的特定名稱都將是化名、代稱。

0x00 大綱

• 0x00 大綱
• 0x01 事故背景
• 0x02 事故分析
• 0x03 事故原因
• 0x04 事故復盤
• 0x05 事故影響

0x01 事故背景

2023年3月10日14時19分，C公司開發人員向A公司開發人員反映某開放介面從2023年3月10日14時許開始無法訪問和使用。該系統為某基礎數據介面服務，基於 HTTP 協議進行通信。按照慣例，首先排查網路是否異常，經運維人員檢查，證明網路連通性沒有問題。A公司開發組於2023年3月10日14時30分通知運維人員重啟應用服務，期間短暫恢復正常。但是，很快，十分鐘後，電話再次響起，告知服務又出現異常，無法訪問。為了避免影響進一步擴大，A公司決定將程式緊急回滾至上一穩定版本。回滾後，系統業務功能恢復正常。短暫松一口氣後，開始排查問題。

0x02 事故分析

讓運維拷貝和固定了更新前後的系統日誌和應用包。根據前面的故障現象，初步猜測是記憶體問題，好在應用啟停腳本中增加了參數-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/app/logs/app.dump（對於無法在生產環境上使用jstack、jmap等命令直接查錯的——事實上大多數時候都不能，dump文件顯得尤為重要），果不其然，日誌目錄下出現了app.dump文件，在日誌中搜索，找到了若幹處記憶體溢出錯誤java.lang.OutOfMemoryError: Java heap space，但是令人費解的是每次出現OOM錯誤的位置居然都不一樣，事情逐漸變得複雜起來。

用MAT(Memory Analyzer Tool)工具打開轉儲文件，原以為會發現某個類型對象占用大量的記憶體，結果出乎意料，Histogram（直方圖）中顯示活躍對象居然只有100多M！嘗試 Calculate Precise Retained Size（計算精確大小），計算結果與前面相差不大。檢查 Outgoing References （追蹤引用對象）和 Incoming References（追蹤被引用對象）也未見明顯異常，令人頭大。

擦擦汗，日誌已經明確提示我們java.lang.OutOfMemoryError: Java heap space，首先肯定這是一個堆記憶體空間引起的問題，可能的原因有：

• 記憶體載入數據量過大

  例如不受行數限制的資料庫查詢語句，或者不限制位元組數的文件讀取等，事故系統顯然沒有這些情況；

• 記憶體泄漏（資源未關閉/無法回收）

  當系統存在大量未關閉的 IO 資源，或者錯誤使用ThreadLocal等場景時也會發生OOM，經排查，也不存在這種情況；

• 系統記憶體不足

  系統記憶體不足以支撐當前業務場景所需要的記憶體，過小的機器記憶體或者不合理的JVM記憶體參數。

如果排除所有合理選項，最不合理那個會不會就是答案呢？遂開始檢查機器的記憶體，根據運維的說法，機器記憶體為16GB，top命令查看java進程占用記憶體約為7.8GB，看起來似乎沒毛病。

但是隨後另一個同事註意到了一個事情，最後一次系統升級的時候，改動過應用啟停腳本，對比舊版本的腳本，發現差異部分就是記憶體參數：

舊版本原為：

-Xms8g -Xmx8g -Xmn3g

新版本改為：

-Xms8g -Xmx8g -Xmn8g

看到這裡，屏幕前的一眾同事都無語啊……

0x03 事故原因

為什麼-Xmn參數設置成與-Xmx參數一樣的大小會導致OOM呢？該項目使用的JDK版本為1.8，看看JDK 8的記憶體模型：

不難發現，Heap Space Size = Young Space Size + Old Space Size，而-Xmn參數控制的正是 Young 區的大小，當堆區被 Young Gen 完全擠占，又有對象想要升代到 Old Gen 時，發現 Old 區空間不足，於是觸發 Full GC，觸發 Full GC 以後呢，通常又會面臨兩種情況：

• Young 區又剛好騰出來一點空間，對象又不用放到 Old 區裡面了，皆大歡喜
• Young 區空間還是不夠，對象還是得放到 Old 區，Old 區空間不夠，卒，喜提OOM
• 誒，就是奔著 Old 區去的，管你 Young 不 Young，Old 區空間不夠，卒，喜提OOM

這個就解釋了為什麼系統剛剛啟動時，會有一個短時間正常工作的現象，隨後，當某段程式觸發 Old Gen 升代時，就會發生隨機的OOM錯誤。那麼什麼時候對象會進入老年代呢？這裡也很有意思，不妨結合日誌裡面出現OOM的地方，對號入座：

• 經歷足夠多次數 GC 依然存活的對象
• 申請一個大對象（比如超過 Eden 區一半大小）
• GC 後 Eden 區對象大小超過 S 區之和
• Eden 區 + S0 區 GC 後，S1 區放不下

換言之，正常情況下，-Xmn參數總是應當小於-Xmx參數，否則就會觸發OOM錯誤。我們可以構造一個簡單的例子來驗證這個場景。首先是一個簡單的SpringBoot程式：

package com.example.oom;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.Random;

@SpringBootApplication
public class OomApplication {
    static final byte[] ARRAY = new byte[128 * 1024 * 1024];

    public static void main(String[] args) {
        SpringApplication.run(OomApplication.class, args);
    }

    @RestController
    public static class OomExampleController {
        @GetMapping("/oom")
        public int oom() {
            byte[] temp = new byte[128 * 1024 * 1024];
            temp[0] = (byte) 0xff;
            temp[temp.length - 1] = (byte) 0xef;
            int noise = new Random().nextInt();
            ARRAY[0] = (byte) (temp[0] + temp[temp.length - 1] + noise);
            return ARRAY[0];
        }
    }
}

使用mvn clean package命令打包後，我們用下麵的命令啟動它：

java -Xms512m -Xmx512m -Xmn512m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:gc.log -jar oom-1.0.0-RELEASE.jar

然後藉助Apache的ab.exe，完成我們的驗證測試。先是以1個併發訪問100次上面的SpringBoot介面：

ab -c 1 -n 100 http://localhost:8080/oom

你會發現，它居然是可以正常運行的，然後我們模擬用戶負載上來之後的情況，使用2個併發訪問100次：

ab -c 2 -n 100 http://localhost:8080/oom

如果前面的步驟都沒錯，此時應該在SpringBoot應用控制台看到大量的OOM錯誤，如下圖所示：

然後在 GC 日誌裡面會看到，觸發 GC 的前後，Old 區幾乎都沒有空間，僅有的一點點還是JDK強行分配的（在啟動JVM時強制覆寫了我們的-Xmn參數）：

{Heap before GC invocations=279 (full 139):
 PSYoungGen      total 458752K, used 273877K [0x00000000e0080000, 0x0000000100000000, 0x0000000100000000)
  eden space 393728K, 69% used [0x00000000e0080000,0x00000000f0bf5798,0x00000000f8100000)
  from space 65024K, 0% used [0x00000000fc080000,0x00000000fc080000,0x0000000100000000)
  to   space 65024K, 0% used [0x00000000f8100000,0x00000000f8100000,0x00000000fc080000)
 ParOldGen       total 512K, used 506K [0x00000000e0000000, 0x00000000e0080000, 0x00000000e0080000)
  object space 512K, 98% used [0x00000000e0000000,0x00000000e007e910,0x00000000e0080000)
 Metaspace       used 35959K, capacity 38240K, committed 38872K, reserved 1083392K
  class space    used 4533K, capacity 4953K, committed 5080K, reserved 1048576K
2023-04-07T01:44:25.348+0800: 57.446: [GC (Allocation Failure) --[PSYoungGen: 273877K->273877K(458752K)] 274384K->274384K(459264K), 0.0441401 secs] [Times: user=0.06 sys=0.30, real=0.04 secs] 
Heap after GC invocations=279 (full 139):
 PSYoungGen      total 458752K, used 273877K [0x00000000e0080000, 0x0000000100000000, 0x0000000100000000)
  eden space 393728K, 69% used [0x00000000e0080000,0x00000000f0bf5798,0x00000000f8100000)
  from space 65024K, 0% used [0x00000000fc080000,0x00000000fc080000,0x0000000100000000)
  to   space 65024K, 9% used [0x00000000f8100000,0x00000000f86e2070,0x00000000fc080000)
 ParOldGen       total 512K, used 506K [0x00000000e0000000, 0x00000000e0080000, 0x00000000e0080000)
  object space 512K, 98% used [0x00000000e0000000,0x00000000e007e910,0x00000000e0080000)
 Metaspace       used 35959K, capacity 38240K, committed 38872K, reserved 1083392K
  class space    used 4533K, capacity 4953K, committed 5080K, reserved 1048576K
}
{Heap before GC invocations=280 (full 140):
 PSYoungGen      total 458752K, used 273877K [0x00000000e0080000, 0x0000000100000000, 0x0000000100000000)
  eden space 393728K, 69% used [0x00000000e0080000,0x00000000f0bf5798,0x00000000f8100000)
  from space 65024K, 0% used [0x00000000fc080000,0x00000000fc080000,0x0000000100000000)
  to   space 65024K, 9% used [0x00000000f8100000,0x00000000f86e2070,0x00000000fc080000)
 ParOldGen       total 512K, used 506K [0x00000000e0000000, 0x00000000e0080000, 0x00000000e0080000)
  object space 512K, 98% used [0x00000000e0000000,0x00000000e007e910,0x00000000e0080000)
 Metaspace       used 35959K, capacity 38240K, committed 38872K, reserved 1083392K
  class space    used 4533K, capacity 4953K, committed 5080K, reserved 1048576K
2023-04-07T01:44:25.392+0800: 57.490: [Full GC (Ergonomics) [PSYoungGen: 273877K->142631K(458752K)] [ParOldGen: 506K->506K(512K)] 274384K->143137K(459264K), [Metaspace: 35959K->35959K(1083392K)], 0.0248171 secs] [Times: user=0.14 sys=0.00, real=0.03 secs] 

接著無需改動任何代碼，我們調整下啟動參數，像這樣：

java -Xms512m -Xmx512m -Xmn64m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:gc.log -jar oom-1.0.0-RELEASE.jar

你會發現它又可以了。這是一個為了驗證而打造的極端例子，實際上生產的應用情況會比這個複雜得多，但這並不妨礙我們理解它的意圖。

0x04 事故復盤

這是一場典型的”人禍“，來源於某個同事的”調優“，比起追究責任，更重要的是帶給我們的啟發：

• 即使是應用啟停腳本，也應該作為程式的一部分，納入測試驗證流程和上線檢查清單，禁止隨意變更；
• 很多時候，預設的就是最好的，矯枉則常常過正。

0x05 事故影響

造成C公司關鍵業務停擺半小時，生產系統緊急回滾一次。A公司相關負責人連夜編寫事故報告一份。