生產事故-記一次特殊的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的記憶體模型：

JDK8記憶體模型

不難發現，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錯誤，如下圖所示：

模擬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公司相關負責人連夜撰寫事故報告一份，

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/549268.html

標籤：Java

上一篇：萬字詳解 | Java 流式編程

下一篇：selenium 小技巧集合（一）