Java應用異常狀態監測

阿里巴巴中間件技術專欄

 

老板最近分派了一個任務，說線上客戶在部署應用的時候發生了系統級別的OOM，觸發了OOM Killer殺掉了應用，讓我們解決這個問題。

對於這個任務，我從如下幾點開始調研、分析與解決。

1、什么是系統級別的OOM（Out-Of-Memory）？

當創建進程時，進程都會建立起自己的虛擬地址空間（對於32位系統來說為4g）。這些虛擬地址空間並不等同於物理內存，只有進程訪問這些地址空間時，操作系統才會為其分配物理內存並建立映射。關於虛擬內存和物理內存有很多資料，這里不再贅述，這篇文章寫的通俗易懂，可以看下。

通過虛擬內存技術，操作系統可以允許多個進程同時運行，即便它們的虛擬內存加起來遠超過系統的物理內存（和swap空間）。如果這些進程不斷訪問其虛擬地址，操作系統不得不為它們分配物理內存，當到達一個臨界點時，操作系統耗盡了所有的物理內存和swap空間，此時OOM就發生了。

2、系統發生了OOM會怎么樣？

當發生了OOM，操作系統有兩個選擇：1）重啟系統；2）根據策略殺死特定的進程並且釋放其內存空間。這兩種策略當然是第二種影響面較小，由於我們線上系統也是采取殺死特定進程的策略，因此這里只展開第二種。

第二種行為也稱之為OOM Killer。那系統會殺死什么樣的進程釋放其內存呢？這篇文檔的“Selecting a Process”部分大概描述了Linux內核的操作系統選取算法：首先，根據badness_for_task = total_vm_for_task / (sqrt(cpu_time_in_seconds) * sqrt(sqrt(cpu_time_in_minutes)))來算起始值，total_vm_for_task為進程占用的實際內存，cpu_time_in_seconds為運行時間，這個公式會選取占用內存多且運行時間短的進程；

如果進程是root進程或者擁有超級用戶權限，那么上述得分會除以4；
如果進程能夠直接訪問硬件（也就是硬件驅動），那么將得分再除以4。
但文檔中描述並不完整，這個是Linux內核OOM_Killer的相關代碼，然后這篇文章對代碼進行了分析，除了上述因素之外還包含子進程內存、nice值、omkill_adj等因素。

操作系統會對每個進程進行計算得分，並記錄在/proc/[pid]/oom_score文件中；當發生系統OOM時，操作系統會選取評分最高的進程進行殺死。

3、如何實現系統OOM告警？

OOM告警有兩種方式，如下：

提前OOM告警：在系統即將發生OOM時，發出告警信息。
事中/事后告警：在系統完成OOM Killer殺死進程后，發出告警信息。
提前OOM告警是最好的方式，但實際上如果想達到不誤報、不漏報，實現難度極大。我們線上應用為Java應用，考慮這么個場景：客戶應用不斷申請內存，當系統物理內存占用率達到90%的時候，系統及應用下一步行為會是什么樣？個人認為有三種可能性：1）Java應用停止申請內存，並且進行了垃圾回收釋放內存，這樣系統將會恢復正常；2）應用繼續申請內存導致應用內存超過了堆大小，但此時系統仍然有部分物理內存，這樣會發生Java應用的OOM；3）應用繼續申請內存導致系統耗盡物理內存，但此時沒有超過堆內存的最大值，這樣會發生操作系統的OOM。對於這個場景來說，我們想准確預判出系統及應用的下一步行為難度極大。

另一方面，我們線上其實已經有基於機器內存使用率的報警，這個報警其實已經包含了三種可能性：1）應用本身有問題但不會導致堆溢出或者系統OOM；2）應用可能會導致堆溢出；3）應用可能會導致系統OOM。無論實際情況為哪一種，這個報警都是有意義的。

事中/事后告警也是一種可取的方式，原因在於：1）這種方式能夠實現不誤報、不漏報；2）對於即將發生OOM的應用來說，事中報警與事前報警時間相差其實並不大。另外，到目前為止客訴的情況都是抱怨其應用死了沒有任何通知，排查起來既浪費了客戶時間，也浪費了研發排查問題的時間。

綜合考慮，如果能夠實現Java應用的異常狀態檢測並提供事中/事后報警與現場分析，也是很有意義的！

4、Java應用的異常狀態為哪些？

這里定義的Java應用異常狀態有：

Java應用被用戶殺死（Kill、Kill -9）；
Java應用發生堆溢出；
Java應用被系統OOM（Kill -9）。

5、如何檢測出上述Java應用異常狀態？

首先，Java應用發生堆溢出可以通過-XX:+HeapDumpOnOutOfMemoryError參數來生成dump信息，我們可以通過輪詢方式即可發現是否發生堆溢出（當然基於事件通知方式更好，待調研）。

因此，現在問題在於我們怎么發現一個Java應用被用戶殺死或者被系統OOM Kill掉？

5.1 ShutdownHook/sun.misc.Signal

老司機可能很快就想到，通過注冊shutdownHook就可以檢測到系統信號了呀！注冊shutdownHook的確能檢測到SIGTERM信號（也就是通常不帶參數的Kill命令，如Kill pid），但不能檢測到SIGKILL信號（Kill -9）。另外，調研發現也可以通過sun.misc.Signal.handle方法來檢測系統信號，但遺憾的是還是不能檢測到SIGKILL信號。

5.2 strace

這個工具非常強大，它能夠攔截所有的系統調用（包括SIGKILL），並且具有系統已經內置、使用方便、輸出信息可讀性好等優點。下圖是我的一個實驗（進程24063是一個觸發系統OOM的Java進程）：

1

但這個工具的缺點是，被跟蹤的應用的性能影響非常大。應用原來進行系統調用（比如open、read、write、close）時會發生一次上下文切換（從用戶態到內核態），使用了strace之后會變成多次上下文調用，如下圖所示：
2
（更多信息可以參考這篇文章）

但無論如何，我們已經找到一種可行的解決方案，雖然性能影響很大，但可以作為debug方案開放給客戶。

5.3 ftrace + 系統日志

ftrace是Linux系統已經內置的工具（debugfs掛載情況見附錄），它的作用是幫助開發人員了解 Linux 內核的運行時行為，以便進行故障調試或性能分析。重要的是，它對應用本身的性能影響極小，而且我們可以只檢測Kill事件，這樣對客戶應用幾乎零影響（性能分析見第6節）。在我們的場景下，它也支持內核事件（包括進程SIGKILL信號）監聽。ftrace使用起來非常方便，可以參考這篇文檔，或者直接使用這個GITHUB腳本即可。下面是運行該GITHUB腳本的一個截圖：

3

在上圖中，SIGNAL為15的是我執行Kill 29265命令，SIGNAL為9的是我執行Kill -9 29428命令。但這個工具的問題在於，當Java進程觸發系統級別的OOM Killer時，並沒有檢測到相應的信號（待進一步調研）。

另外，當系統觸發OOM Killer時，會在系統日志（Centos的為/var/log/messages）中記錄下特定信息，如下所示：

4

5.4 auditd + 系統日志

（系統日志用來發現OOM信息，不再贅述，下文主要介紹auditd）

同事建議可以嘗試下auditd，因此這里調研auditd，發現它能滿足需求，而且測試性能影響比ftrace更小（性能分析見第6節）。auditd是Linux Auditing System（Linux審計系統）的一部分，它負責接收內核中發生的事件（系統調用、文件訪問），並將這些事件寫入日志供用戶分析。

下圖是Linux審計系統的框架：

5

其中：

左邊是我們的應用程序；

中間為Linux內核，內核中包含了審計模塊，可以記錄三類事件：1）User：記錄用戶產生的事件；2）Task：記錄任務類型（如fork子進程）事件；3）Exit：在系統調用結束時記錄該事件。同時，可以結合Exclude規則來過濾事件，最終將這些事件發送到用戶空間的auditd守護進程；

右邊是在用戶空間的應用程序，其中auditd是核心的守護進程，主要接收內核中產生的事件，並記錄到audit.log中，然后我們可以通過ausearch或者aureport來查看這些日志；auditd在啟動時會讀取auditd.conf文件來配置守護進程的各種行為（如日志文件存放位置），並讀取audit.rules中的事件規則來控制內核中的事件監聽及過濾行為；另外，我們也可以通過auditctl來控制內核事件監聽和過濾規則。 

關於更多信息可以自行搜索或者看下這篇文章。

內核已經內置審計模塊，而auditd守護進程也默認在centos（>=6.8）中啟動，下面我們來測試下該工具。首先，我們執行如下命令：

auditctl -a always,exit -F arch=b64 -S kill -k test_kill

這條命令作用是，在kill系統調用返回時記錄事件，並且綁定test_kill標記（以便后面進行日志篩選）。然后，我們可以隨便執行一個腳本並kill掉，可以在/var/log/audit/audit.log中看到如下輸出：

6

第一條SYSCALL日志記錄發送SIGKILL信號的進程信息，第二條OBJ_PID日志記錄接收SIGKILL信號的進程信息。

5.5 Shell + dmesg

如果我們能夠控制Java應用的啟動腳本，那么此方式是影響最小的方案。先看下面這個shell腳本：

7

這個腳本做了這幾個事情：

使用Java -Xms4g -Xmx4g Main來啟動一個Java應用；

Java應用退出后通過$?獲取程序退出狀態碼；

如果退出碼大於128，則為應用收到SIGNAL退出；如果為SIGKILL，則通過dmesg收集kernal ring buffer中的信息。

如果應用由於被OOM Killer殺死而退出，則dmesg-kill.log中會有如下信息：

8

此方案優點在於影響面最小，但進程殺死信息量相比auditd少，只知道收到何種SIGNAL信號；而auditd能夠知道SIGNAL信號來源於哪個進程、用戶、組。 

6、性能測試

6.1 測試環境

1

6.2 測試腳本

6.2.1 測試一：系統調用性能影響

測試方法

從/dev/zero中讀取500個字節數據並寫入到/dev/null中，循環執行1億次（也就是100M）：

dd if=/dev/zero of=/dev/null bs=500 count=100M

該腳本會產生大約2億次系統調用（read 1億次，write 1億次）。

測試結果

2

6.2.2 測試二：JAVA應用性能影響

測試方法：

構造consumer和provider應用，consumer向provider發起HSF調用，provider返回預定義數據，循環調用1百萬次，觀察consumer耗時。

測試結果：

4

7、總結

綜上，我們可以通過如下手段來解決客戶的應用OOM問題：

1. 使用機器的基於內存使用率報警來事前通知客戶；

2. JVM啟動參數可以添加-XX:+HeapDumpOnOutOfMemoryError等參數來協助收集JVM內存溢出信息；

3. 通過系統日志（/var/log/messages）或者dmesg來收集系統OOM Killer信息；

4. 使用啟動shell腳本（見5.5節）或auditd（見5.4節） ftrace 來獲取應用被Kill掉的信息（可能被客戶自身Kill掉）。

5. 【可選】開放strace工具來幫助客戶debug問題。

8、其他工具

8.1 trap

trap命令用於指定在接收到信號后將要采取的動作，通常在腳本程序被中斷時完成清理工作。當shell接收到sigspec指定的信號時，arg參數（命令）將會被讀取，並被執行。下面我試圖攔截當前腳本的SIGTERM和SIGKILL信號：

6

測試發現，trap命令能夠檢測到當前進程的SIGTERM信號，但是無法檢測SIGKILL信號。這個命令相當於Java應用中的shutdownHook或者Signal。

9、附錄

9.1 ftrace系統debugfs掛載情況

（注：以下統計阿里雲上主要的操作系統）

7
8