JVM之 DJL使用不當(dāng)和自身bug引起的內(nèi)存泄露排查

1. 背景

排序服務(wù)新上線一個(gè)DPP(Determinantal Point Process)重排算法邏輯，基于DJL(Deep Java Library)實(shí)現(xiàn)的, DJL目前提供了MXNet,、PyTorch和TensorFlow的實(shí)現(xiàn)，通過(guò)調(diào)用JNI或者JNA來(lái)調(diào)用相應(yīng)的底層操作。
新重排算法上線之服務(wù)調(diào)用方每隔一段時(shí)間就會(huì)出現(xiàn)超時(shí)報(bào)錯(cuò)，每個(gè)一段時(shí)間還會(huì)出現(xiàn)OOM，這是之前從來(lái)沒(méi)有的情況，因此開(kāi)始了JVM排查之路。
排序服務(wù)是部署在K8S集群上，配置是8C16G，使用的JDK11的ZGC。

調(diào)用方超時(shí)報(bào)錯(cuò)
排序服務(wù)OOM事件

2 排查之路

2.1 NDManager

  1. 監(jiān)控顯示18點(diǎn)30左右，排序服務(wù)調(diào)用方有超時(shí)報(bào)錯(cuò)。查看接口的平均響應(yīng)時(shí)間，確實(shí)有尖峰（因?yàn)榕判蚍?wù)被多個(gè)服務(wù)調(diào)用，所以截取的是服務(wù)調(diào)用方展示的接口平均耗時(shí)曲線）。
調(diào)用排序服務(wù)的平均響應(yīng)時(shí)間
  1. 查看CPU利用率發(fā)現(xiàn) 18:30 確實(shí)有提升，但是CPU throttled time還好。說(shuō)明響應(yīng)時(shí)間升高跟CPU throttled沒(méi)有關(guān)系，再結(jié)合OOM懷疑跟內(nèi)存泄露有關(guān)（廢話，都OOM了，肯定是跟內(nèi)存泄露有關(guān)系了，但是響應(yīng)時(shí)間升高是有很多因素引起的，還要排除CPU throttled的影響）。
CPU利用率
CPU throttled time
  1. 懷疑內(nèi)存泄露第一時(shí)間查看堆的使用情況和GC情況(頻率與耗時(shí))，但是18:30 左右都是正常的。
堆內(nèi)存使用情況
zgc次數(shù)
zgc耗時(shí)
  1. 問(wèn)題暫時(shí)陷入了僵局， 忽然發(fā)現(xiàn)18:30左右的超時(shí)報(bào)錯(cuò)大部分都跟某一臺(tái)機(jī)器有關(guān)，查看stdout日志，發(fā)現(xiàn) 18:31:27 Tomcat被重啟了，同樣09:20:34、12:22:34 Tomcat都被kill然后重啟。這樣CPU利用率在這幾個(gè)時(shí)間點(diǎn)彪高也能解釋了。
微服務(wù)接口統(tǒng)計(jì)
stdout日志
CPU利用率曲線
  1. 排查的過(guò)程中意外發(fā)現(xiàn)Direct BufferPool使用率隨著時(shí)間逐漸增加。每次重啟之后驟降，過(guò)一段時(shí)間又增加。堆內(nèi)的使用情況又正常， 懷疑跟堆外內(nèi)存有關(guān)。
BufferPool
堆內(nèi)內(nèi)存使用情況
  1. 堆外內(nèi)存主要包括：DirectByteBuffer分配的內(nèi)存，JNI里分配的內(nèi)存，線程棧分配占用的系統(tǒng)內(nèi)存，jvm本身運(yùn)行過(guò)程分配的內(nèi)存，codeCache，java 8里還包括metaspace元數(shù)據(jù)空間。而且之前也提到了新上線基于DJL的DPP重排邏輯，會(huì)有大量使用JNI。因?yàn)閷?duì)JNI不熟悉，只是簡(jiǎn)單了解過(guò)其機(jī)制，且堆外的內(nèi)存特別難以排查，所以試著查看代碼看看有沒(méi)有什么發(fā)現(xiàn)。DPP的主要代碼如下所示（省略部分代碼和參數(shù)）：
private void dppRank ( ) {
   DPPModel dppModel = new DPPModel(itemCount, topK);
   List<Integer> resDPP = dppModel.dppSW(/* 參數(shù)省略 */);
}

public class DPPModel {
    private NDArray rankScore;
    private NDArray kernelMatrix;
    private NDManager manager = NDManager.newBaseManager();
    // ... ...
}

這里使用的DJL的pytorch-engine:0.18.0，通過(guò)NDManger.create()創(chuàng)建NDArray，會(huì)調(diào)manager.attachInternal() 將創(chuàng)建的NDArray放到NDManager.resources中，以便統(tǒng)一管理。

    public PtNDArray(PtNDManager manager, long handle) {
        super(handle);
        this.manager = manager;
        this.ptNDArrayEx = new PtNDArrayEx(this);
        manager.attachInternal(getUid(), this);
    }

    public synchronized void attachInternal(String resourceId, AutoCloseable resource) {
        if (closed.get()) {
            throw new IllegalStateException("NDManager has been closed already.");
        }
        tempResources.compute(
                resourceId,
                (key, tempResource) -> {
                    if (tempResource != null) {
                        // This state occurs when this manager (manA) tempAttaches a resource that
                        // is later
                        // tempAttached to another manager (manB)
                        // When manB is closed, it will use attach to return the resource to this
                        // (manA)
                        // In that case, it should stay as a tempResource in this (manA)
                        tempResource.detached = false;
                    } else {
                        resources.put(resourceId, resource);
                    }
                    return tempResource;
                });
    }

PtNDManager繼承自BaseNDManager，實(shí)現(xiàn)AutoCloseable的close接口，會(huì)遍歷resources調(diào)所有NDArray的close方法

    public void close() {
        if (!closed.getAndSet(true)) {
            for (AutoCloseable closeable : resources.values()) {
                try {
                    closeable.close();
                } catch (Exception e) {
                    logger.error("Resource close failed.", e);
                }
            }
            for (TempResource resource : tempResources.values()) {
                resource.returnResource();
            }
            parent.detachInternal(uid);
            resources.clear();
            tempResources.clear();
        }
    }

查看PtNDManger的create 方法，會(huì)刪除NDArray的內(nèi)存。

    @Override
    public void close() {
        Long pointer = handle.getAndSet(null);
        if (pointer != null) {
            JniUtils.deleteNDArray(pointer);
        }
        manager.detachInternal(getUid());
        dataRef = null;

查到這里可以肯定是因?yàn)镈JL的使用不當(dāng)引起的， 可以通過(guò)try-with-resource方式使用NDManager，使用后會(huì)自動(dòng)釋放資源。

 try (NDManager manager = NDManager.newBaseManager(Device.cpu())) {
            NDArray rankScore = manager.create(rankScoreArray);
 }

修改后，重新發(fā)布后，可以發(fā)現(xiàn) BufferPool direct used 使用正常。

BufferPool direct使用情況

2.2 NDManager自身bug

但是故事到這里還沒(méi)有結(jié)束，本以為調(diào)整使用方式就萬(wàn)事大吉了，但是上線一段時(shí)間后系統(tǒng)仍然報(bào)OOM、Tomcat也被重啟，只是頻率比之前低了很多，又開(kāi)始漫長(zhǎng)的排查之路。

  1. 查看gc.log，發(fā)現(xiàn)確實(shí)有內(nèi)存泄露，如下圖所示，只是被之前誤用的問(wèn)題掩蓋起來(lái)了。這里介紹一個(gè)網(wǎng)站https://gceasy.io/ 可以分析GC日志，發(fā)現(xiàn)GC后的堆使用情況一直是增加的。 同時(shí)Mem RSS使用量也是不斷增加的。
GC后堆內(nèi)存使用情況
Mem Rss使用情況
  1. 查看堆內(nèi)存dump
    使用Memory Analyzer (MAT)查看堆內(nèi)存使用情況，直方圖如下所示，其中：
  • Retained Heap（深堆）代表對(duì)象本身和對(duì)象關(guān)聯(lián)的對(duì)象占用的內(nèi)存；
  • Shallow Heap（淺堆）代表對(duì)象本身占用的內(nèi)存。
內(nèi)存dump直方圖

其中有大量的PtNDManager，遠(yuǎn)超正常使用。通過(guò)list objects- with incoming referencs 查看， 發(fā)現(xiàn)被PtNDManager$SystemManager的resources引用。

每個(gè)一段時(shí)間執(zhí)行一下jmap -histo:live 也可以發(fā)現(xiàn)PtNDManager一直增加。

  1. 繼續(xù)查看DJL源碼
    NDManager.newBaseManager() 創(chuàng)建PtNDManager源碼如下所示, 會(huì)調(diào)用PtNDManager$SystemManager的attachUncappedInternal將創(chuàng)建的PtNDManager掛載到resoures里。
   PtNDManager manager = new PtNDManager(this, device);
   attachUncappedInternal(manager.uid, manager);
   return manager;

   resources.put(resourceId, resource);

當(dāng)PtNDManager執(zhí)行close方法時(shí)，會(huì)調(diào)用parent的detachInternal方法，parent是PtNDManager$SystemManager， PtNDManager$SystemManager的detachInternal什么都沒(méi)干

   public void close() {
        if (!closed.getAndSet(true)) {
             // ignore some code
            parent.detachInternal(uid);
            resources.clear();
            tempResources.clear();
        }
    }

@Override
 public void detachInternal(String resourceId) {}

查看pytorch-engine的0.17.0的源碼就正常多了，使用之后也沒(méi)有問(wèn)題，于是去DJL的github怒提issue： https://github.com/deepjavalibrary/djl/issues/1886

總結(jié)

此次內(nèi)存泄露有兩個(gè)原因：

  1. DJL使用不當(dāng)，NDManager創(chuàng)建之后沒(méi)有關(guān)閉，導(dǎo)致相應(yīng)的NDArray和JNI內(nèi)存都沒(méi)有被回收；
  2. DJL自身bug， NDManager即使執(zhí)行了close，但是還是被引用，導(dǎo)致自身無(wú)法被回收。

雖然排查之后再進(jìn)行復(fù)盤(pán)，根據(jù)各種現(xiàn)象，順理成章就排查了問(wèn)題的根源。 但是一開(kāi)始排查時(shí)，毫無(wú)頭緒，各種細(xì)節(jié)充斥其中，有些是原因，有些是結(jié)果， 比如最開(kāi)始懷疑是CPU彪高導(dǎo)致響應(yīng)時(shí)間變長(zhǎng)，但其實(shí)是因?yàn)镺OM導(dǎo)致tomcat 重啟導(dǎo)致的CPU彪高。只能不停地假設(shè)，然后根據(jù)現(xiàn)象驗(yàn)證假設(shè)，最終定位問(wèn)題。

總結(jié)內(nèi)存泄露的排查流程如下：

  1. 首先要熟悉JVM、包括垃圾收集器的原理，這樣才能有的放矢；
  2. 借助一些工具，事半功倍：本文涉及到有g(shù)raphana、cat、mat、jmap 等，每個(gè)工具都有自身的功能，幫忙定位一些問(wèn)題；
  3. 結(jié)合理論與工具，抓住線索，不停地去懷疑、假設(shè)，然后驗(yàn)證自己的假設(shè)；
  4. 剩下的就是交給時(shí)間，本次排查也耗時(shí)好久，開(kāi)始走了很多的彎路，但是硬剛到底最終會(huì)發(fā)現(xiàn)問(wèn)題根源。
    經(jīng)過(guò)此次排查，對(duì)很多東西的理解和工具的使用更上一層樓。

最后想說(shuō)一下DJL，雖然本文的內(nèi)存泄露與DJL有關(guān)，但是不得不說(shuō)DJL是一個(gè)難得的JAVA 機(jī)器學(xué)習(xí)工具包，可以在Java中開(kāi)發(fā)及應(yīng)用原生的機(jī)器學(xué)習(xí)和深度學(xué)習(xí)模型，同時(shí)簡(jiǎn)化了深度學(xué)習(xí)開(kāi)發(fā)的難度。通過(guò)DJL提供的直觀的、高級(jí)的API，Java開(kāi)發(fā)人員可以訓(xùn)練自己的模型，或者利用數(shù)據(jù)科學(xué)家用Python預(yù)先訓(xùn)練好的模型來(lái)進(jìn)行推理。如果恰好是對(duì)學(xué)習(xí)深度學(xué)習(xí)感興趣的Java開(kāi)發(fā)者，那么DJL無(wú)疑將是開(kāi)始深度學(xué)習(xí)應(yīng)用的一個(gè)最好的起點(diǎn)。

最后編輯于 ：
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點(diǎn)，簡(jiǎn)書(shū)系信息發(fā)布平臺(tái)，僅提供信息存儲(chǔ)服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容