問題背景&現(xiàn)象

ExitCode:137 OOMkill

問題現(xiàn)象137.png

線上環(huán)境的后臺(tái)服務(wù)頻繁重啟，重啟的原因日志是ExitCode:137 OOMkill 。OOMkill是服務(wù)器的一種保護(hù)行為，服務(wù)器會(huì)定時(shí)的掃描服務(wù)器中的各個(gè)進(jìn)程，每個(gè)進(jìn)程根據(jù)一種機(jī)制得到一個(gè)分?jǐn)?shù)，如果這個(gè)分?jǐn)?shù)最高則會(huì)被服務(wù)器主動(dòng)kill掉。OOMkill的具體機(jī)制在此不做過多贅述。而進(jìn)程得到高分的原因一般情況是內(nèi)存資源占用過高導(dǎo)致的。被OOMkill后總是難于保留當(dāng)時(shí)具體情況，每次都是服務(wù)被重啟了才發(fā)現(xiàn)問題。還好運(yùn)維平臺(tái)可以支持OOMkill保護(hù)，發(fā)現(xiàn)資源超限情況不讓直接OOMkill而是先保護(hù)現(xiàn)場并發(fā)出告警。

Memory hit original limit

Memory hit original limit告警.png

果然設(shè)置了保護(hù)之后，告警就接踵而至了。而且確實(shí)是內(nèi)存超限導(dǎo)致的，如果沒有保護(hù)又事一次煩人的OOMkill 。知道是內(nèi)存的問題接下來問題定位的方向就更明了了。

問題定位&分析

先dump堆內(nèi)存再說

第一個(gè)首先懷疑的是應(yīng)用服務(wù)的堆內(nèi)存。但是dump堆內(nèi)存下來分析后，發(fā)現(xiàn)占用的并不高。總內(nèi)存只有200M左右。

3.堆內(nèi)存分析.png

看來堆內(nèi)存并不是罪魁禍?zhǔn)住?br> 總結(jié):dump命令，jmap -dump:format=b,file= /文件路徑/dump文件名稱.hprof 進(jìn)程ID ，如：jmap -dump:format=b,file=/home/heap.hprof 1

是堆外內(nèi)存的原因嗎？

不是堆內(nèi)存，那應(yīng)該就是堆外內(nèi)存的原因了。項(xiàng)目中有些開源框架使用到Netty，Netty是有使用堆外內(nèi)存的。而且JDK8的元空間也是屬于堆外。

JDK8元空間觀測

通過查看JVM的配置，發(fā)現(xiàn)元空間的大小并沒有限制。

4元空間大小沒做限制.png

原因是項(xiàng)目以前使用的是JDK8以前的版本，升級到了JDK8后對應(yīng)的JVM配置沒有對應(yīng)更新。運(yùn)維平臺(tái)觀測到的非堆內(nèi)存占用確實(shí)也是不小。

image.png

netty堆外內(nèi)存占用觀測

不是元空間占用的大量內(nèi)存，那會(huì)不會(huì)是項(xiàng)目其他地方使用到了堆內(nèi)存呢？ 查看了整個(gè)項(xiàng)目的業(yè)務(wù)代碼和相關(guān)的依賴，只有Netty使用到堆外內(nèi)存。那么就想辦法觀測一下Netty使用堆外內(nèi)存的情況。關(guān)于Netty的堆外內(nèi)存如何使用，因篇幅有限此處不做擴(kuò)展；只是通過以下工具可以監(jiān)控到堆外內(nèi)存的大?。?/p>

public static List<String> startReport() {
        Field field = ReflectionUtils.findField(PlatformDependent.class, "DIRECT_MEMORY_COUNTER");
        field.setAccessible(true);
        try {
            AtomicLong directMemory = (AtomicLong) field.get(PlatformDependent.class);
            int memoryInKb = (int) (directMemory.get() / 1024);
            log.info("堆外內(nèi)存大小：{}",memoryInKb);
            if (list.size() <=100) {
                list.add("時(shí)間：" + LocalDateTime.now()
                                              .toString() + "  堆外內(nèi)存:" + memoryInKb + "k ");
            }else {
                list.clear();
            }
            return list;
        } catch (IllegalAccessException e) {
            e.printStackTrace();
        }
        return list;
    }

并通過一個(gè)上帝接口持續(xù)觀測:

image.png

但是經(jīng)過一段時(shí)間的觀測，占用的內(nèi)存并沒有異常增長。

page cache占用總內(nèi)存情況

無奈之下，只能進(jìn)一步的通過運(yùn)維監(jiān)控平臺(tái)繼續(xù)找一些觀測數(shù)據(jù)。經(jīng)過長時(shí)間的觀測對比。發(fā)現(xiàn)page cache的變化對總內(nèi)存變化影響很明顯，而且發(fā)出內(nèi)存超限提醒的服務(wù)節(jié)點(diǎn)page cache都沒法正?；厥?。

5pc對總內(nèi)存的影響很明顯.png

vmtouch觀測文件緩存情況

梳理了整個(gè)業(yè)務(wù)項(xiàng)目的代碼，并沒有發(fā)現(xiàn)有大量讀寫文件的地方。懷疑是日志文件的讀寫，導(dǎo)致一直在產(chǎn)生page cache。為了驗(yàn)證個(gè)問題需要使用到vmtouch命令，關(guān)于此命令的介紹可以參見官方文檔：https://hoytech.com/vmtouch
此命令可以查看磁盤文件被加載到內(nèi)存中的情況。
查看日志文件被加載到內(nèi)存的情況：

image.png

image.png

image.png

page cache數(shù)據(jù)觀測

為什么page cache這么多？

page cache為什么這么多，是因?yàn)槿罩疚募罅藛?？為了?yàn)證這個(gè)問題，通過修改log4j的配置，將每個(gè)日志文件分割成500M以內(nèi)，但是問題依舊。而且日志文件被切割后，不再寫入的日志文件在依然被加載到內(nèi)存中，說明是讀日志文件的原因。

企業(yè)微信截圖_16235175941830.png

企業(yè)微信截圖_16235176181799.png

日志文件的讀場景，是運(yùn)維平臺(tái)做日志采集的情況才會(huì)觸發(fā)的。于是找了運(yùn)維平臺(tái)的同事反饋。

為什么page cache沒正?；厥?？

反饋問題后自己也持續(xù)觀察，發(fā)現(xiàn)有問題的節(jié)點(diǎn)。發(fā)現(xiàn)page cache的掃描速度很慢，而且臟頁閾值配置的也不一樣。和運(yùn)維同事溝通后，得知服務(wù)器節(jié)點(diǎn)是被隨機(jī)分配的，可能節(jié)點(diǎn)屬于不同的物理機(jī)，而臟頁閾值的配置使用的應(yīng)該是物理機(jī)的配置。


問題解決&防范

曲線救國

既然問題原因是讀日志文件導(dǎo)致的，那就不讓監(jiān)控程序主動(dòng)來讀取日志，而是主動(dòng)將數(shù)據(jù)通過消息隊(duì)列推送給監(jiān)控系統(tǒng)。公司基于log4j自研封裝了日志工具，可以根據(jù)配置將日志直接通過kafka推送給監(jiān)控系統(tǒng)，這樣就能避免讀日志文件，page cache的問題也可以避免了。

問題根治

主動(dòng)推送日志的方法只能是避免問題的發(fā)生，要根治問題還是得從page cache的相關(guān)配置入手。page cache難回收的原因一般有三個(gè)(具體可以參見：Page Cache難以回收問題)：
1.直接內(nèi)存回收導(dǎo)致
2.系統(tǒng)臟頁內(nèi)存積壓過多導(dǎo)致
3.系統(tǒng)NUMA策略配置不當(dāng)導(dǎo)致
其中情況1 通過sar -B命令觀測可以排插，因?yàn)閜gscand并沒有發(fā)生

企業(yè)微信截圖_16235198212630.png