一次線上OOM問題分析

2023-02-28 21:00:41

現象

線上某個服務有介面非常慢,通過監控鏈路檢視發現,中間的 GAP 時間非常大,實際介面並沒有消耗很多時間,並且在那段時間裡有很多這樣的請求。

原因分析

先從監控鏈路分析了一波,發現請求是已經打到服務上了,處理之前不知道為什麼等了 3s,猜測是不是機器當時負載太大了,通過 QPS 監控檢視發現,在介面慢的時候 CPU 突然增高,同時也頻繁的 GC ,並且時間很長,但是請求量並不大,並且這臺機器很快就因為 Heap滿了而被下掉了。

去看了下紀錄檔,果然有 OOM 的報錯,但是從報錯資訊上並沒辦法找到 Root Cause。

system error: org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: Java heap space   at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1055)   at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)   at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)   at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)   at javax.servlet.http.HttpServlet.service(HttpServlet.java:681) 

另外開發同學提供了線索,在發生問題的時候在跑一個大批次的一次性 JOB,懷疑是不是這個 JOB 導致的,馬上把 JOB 程式碼拉下來分析了下,JOB 做了分批次處理,程式碼也沒有發現什麼問題。

雖然我們系統加了下面的 JVM 引數,但是由於容器部署的原因,這些檔案在 pod 被 kill 掉之後沒辦法保留下來。

-XX:+HeapDumpOnOutOfMemoryError -XX:ErrorFile=/logs/oom_dump/xxx.log -XX:HeapDumpPath=/logs/oom_dump/xxx.hprof

這個現象是最近出現的,猜測是最近提交的程式碼導致的,於是去分析了最近提交的所有程式碼,很不幸的都沒有發現問題。。。

在分析程式碼的過程中,該服務又無規律的出現了兩次 OOM,只好聯絡運維同學優先給這個服務加了 EFS (Amazon 檔案系統)等待下次出現能抓住這個問題。

剛掛載完 EFS,很幸運的就碰到了系統出現 OOM 的問題。

dump 出來的檔案足有 4.8G,話不多說祭出 jvisualvm 進行分析,分析工具都被這個dump檔案給搞掛了也報了個java.lang.OutOfMemoryError: Java heap space,載入成功之後就給出了導致OOM的執行緒。

找到了具體報錯的程式碼行號,翻一下業務程式碼,竟然是一個查詢資料庫的count操作,這能有啥問題?

仔細看了下里面有個foreach遍歷userId的操作,難道這個userId的陣列非常大?

找到class按照大小排序,佔用最多的是一個 byte 陣列,有 1.07G,char 陣列也有1.03G,byte 陣列都是數位,直接檢視 char 陣列吧,點進去檢視具體內容,果然是那條count語句,一條 SQL 1.03G 難以想象。。。

這個userId的資料完全是外部傳過來的,並沒有做什麼操作,從監控上看,這個入參有 64M,馬上聯絡對應系統排查為啥會傳這麼多使用者過來查詢,經過一番排查確認他們有個bug,會把所有使用者都發過來查詢。。。到此問題排查清楚。

解決方案

對方系統控制傳入userId的數量,我們自己的系統也對userId做一個限制,問題排查過程比較困難,修改方案總是那麼的簡單。

別急,還有一個

看到這個問題,就想起之前我們還有一個同樣類似的問題導致的故障。

也是突然收到很多告警,還有機器 down 機的告警,開啟 CAT 監控看的時候,發現記憶體已經被打滿了。

操作和上面的是一樣的,拿到 dump 檔案之後進行分析,不過這是一個漫長的過程,因為 down了好幾臺機器,最大的檔案有12GB。

通過 MAT 分析 dump 檔案發現有幾個巨大的 String(熟悉的味道,熟悉的配方)。

接下來就是早具體的程式碼位置了,去檢視了下紀錄檔,這臺機器已經觸發自我保護機制了,把程式碼的具體位置帶了出來。

經過分析程式碼發現,程式碼中的邏輯是查詢 TIDB(是有同步延遲的),發現在極端情況下會出現將使用者表全部資料載入到記憶體中的現象。

於是找 DBA 拉取了對應時間段 TIDB 的慢查詢,果然命中了。

總結

面對 OOM 問題如果程式碼不是有明顯的問題,下面幾個JVM引數相當有用,尤其是在容器化之後。

-XX:+HeapDumpOnOutOfMemoryError -XX:ErrorFile=/logs/oom_dump/xxx.log -XX:HeapDumpPath=/logs/oom_dump/xxx.hprof

另外提一個引數也很有用,正常來說如果程式出現 OOM 之後,就是有程式碼存在記憶體漏失的風險,這個時候即使能對外提供服務,其實也是有風險的,可能造成更多的請求有問題,所以該引數非常有必要,可以讓 K8S 快速的再拉起來一個範例。

-XX:+ExitOnOutOfMemoryError

另外,針對這兩個非常類似的問題,對於 SQL 語句,如果監測到沒有where條件的全表查詢應該預設增加一個合適的limit作為限制,防止這種問題拖垮整個系統。