完了！線上又發(fā)生 OOM 了！

作者：艾小仙 2023-03-10 08:24:27

dump 出來(lái)的文件足有 4.8G，話不多說(shuō)祭出 jvisualvm 進(jìn)行分析，分析工具都被這個(gè)dump文件給搞掛了也報(bào)了個(gè)java.lang.OutOfMemoryError: Java heap space，加載成功之后就給出了導(dǎo)致OOM的線程。

本文轉(zhuǎn)載自微信公眾號(hào)「艾小仙」，作者艾小仙。轉(zhuǎn)載本文請(qǐng)聯(lián)系艾小仙公眾號(hào)。

現(xiàn)象

線上某個(gè)服務(wù)有接口非常慢，通過監(jiān)控鏈路查看發(fā)現(xiàn)，中間的 GAP 時(shí)間非常大，實(shí)際接口并沒有消耗很多時(shí)間，并且在那段時(shí)間里有很多這樣的請(qǐng)求。

原因分析

先從監(jiān)控鏈路分析了一波，發(fā)現(xiàn)請(qǐng)求是已經(jīng)打到服務(wù)上了，處理之前不知道為什么等了 3s，猜測(cè)是不是機(jī)器當(dāng)時(shí)負(fù)載太大了，通過 QPS 監(jiān)控查看發(fā)現(xiàn)，在接口慢的時(shí)候 CPU 突然增高，同時(shí)也頻繁的 GC ，并且時(shí)間很長(zhǎng)，但是請(qǐng)求量并不大，并且這臺(tái)機(jī)器很快就因?yàn)?Heap滿了而被下掉了。

去看了下日志，果然有 OOM 的報(bào)錯(cuò)，但是從報(bào)錯(cuò)信息上并沒辦法找到 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)

另外開發(fā)同學(xué)提供了線索，在發(fā)生問題的時(shí)候在跑一個(gè)大批量的一次性 JOB，懷疑是不是這個(gè) JOB 導(dǎo)致的，馬上把 JOB 代碼拉下來(lái)分析了下，JOB 做了分批處理，代碼也沒有發(fā)現(xiàn)什么問題。

雖然我們系統(tǒng)加了下面的 JVM 參數(shù)，但是由于容器部署的原因，這些文件在 pod 被 kill 掉之后沒辦法保留下來(lái)。

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

這個(gè)現(xiàn)象是最近出現(xiàn)的，猜測(cè)是最近提交的代碼導(dǎo)致的，于是去分析了最近提交的所有代碼，很不幸的都沒有發(fā)現(xiàn)問題。。。

在分析代碼的過程中，該服務(wù)又無(wú)規(guī)律的出現(xiàn)了兩次 OOM，只好聯(lián)系運(yùn)維同學(xué)優(yōu)先給這個(gè)服務(wù)加了 EFS （Amazon 文件系統(tǒng)）等待下次出現(xiàn)能抓住這個(gè)問題。

剛掛載完 EFS，很幸運(yùn)的就碰到了系統(tǒng)出現(xiàn) OOM 的問題。

找到了具體報(bào)錯(cuò)的代碼行號(hào)，翻一下業(yè)務(wù)代碼，竟然是一個(gè)查詢數(shù)據(jù)庫(kù)的count操作，這能有啥問題?

仔細(xì)看了下里面有個(gè)foreach?遍歷userId?的操作，難道這個(gè)userId的數(shù)組非常大?

找到class按照大小排序，占用最多的是一個(gè) byte 數(shù)組，有 1.07G，char 數(shù)組也有1.03G，byte 數(shù)組都是數(shù)字，直接查看 char 數(shù)組吧，點(diǎn)進(jìn)去查看具體內(nèi)容，果然是那條count語(yǔ)句，一條 SQL 1.03G 難以想象。。。

這個(gè)userId?的數(shù)據(jù)完全是外部傳過來(lái)的，并沒有做什么操作，從監(jiān)控上看，這個(gè)入?yún)⒂?64M，馬上聯(lián)系對(duì)應(yīng)系統(tǒng)排查為啥會(huì)傳這么多用戶過來(lái)查詢，經(jīng)過一番排查確認(rèn)他們有個(gè)bug，會(huì)把所有用戶都發(fā)過來(lái)查詢。。。到此問題排查清楚。

解決方案

對(duì)方系統(tǒng)控制傳入userId?的數(shù)量，我們自己的系統(tǒng)也對(duì)userId做一個(gè)限制，問題排查過程比較困難，修改方案總是那么的簡(jiǎn)單。

別急，還有一個(gè)

看到這個(gè)問題，就想起之前我們還有一個(gè)同樣類似的問題導(dǎo)致的故障。

也是突然收到很多告警,還有機(jī)器 down 機(jī)的告警，打開 CAT 監(jiān)控看的時(shí)候，發(fā)現(xiàn)內(nèi)存已經(jīng)被打滿了。

操作和上面的是一樣的，拿到 dump 文件之后進(jìn)行分析，不過這是一個(gè)漫長(zhǎng)的過程，因?yàn)?down了好幾臺(tái)機(jī)器，最大的文件有12GB。

通過 MAT 分析 dump 文件發(fā)現(xiàn)有幾個(gè)巨大的 String（熟悉的味道，熟悉的配方）。

接下來(lái)就是早具體的代碼位置了，去查看了下日志，這臺(tái)機(jī)器已經(jīng)觸發(fā)自我保護(hù)機(jī)制了，把代碼的具體位置帶了出來(lái)。

經(jīng)過分析代碼發(fā)現(xiàn)，代碼中的邏輯是查詢 TIDB（是有同步延遲的），發(fā)現(xiàn)在極端情況下會(huì)出現(xiàn)將用戶表全部數(shù)據(jù)加載到內(nèi)存中的現(xiàn)象。

于是找 DBA 拉取了對(duì)應(yīng)時(shí)間段 TIDB 的慢查詢，果然命中了。

總結(jié)

面對(duì) OOM 問題如果代碼不是有明顯的問題，下面幾個(gè)JVM參數(shù)相當(dāng)有用，尤其是在容器化之后。

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

另外提一個(gè)參數(shù)也很有用，正常來(lái)說(shuō)如果程序出現(xiàn) OOM 之后，就是有代碼存在內(nèi)存泄漏的風(fēng)險(xiǎn)，這個(gè)時(shí)候即使能對(duì)外提供服務(wù)，其實(shí)也是有風(fēng)險(xiǎn)的，可能造成更多的請(qǐng)求有問題，所以該參數(shù)非常有必要，可以讓 K8S 快速的再拉起來(lái)一個(gè)實(shí)例。