我們有一個(gè)線上的項(xiàng)目，剛啟動(dòng)完就占用了使用 top 命令查看 RES 占用了超過(guò) 1.5G，這明顯不合理，于是進(jìn)行了一些分析找到了根本的原因，下面是完整的分析過(guò)程，希望對(duì)你有所幫助。

會(huì)涉及到下面這些內(nèi)容

• Linux 經(jīng)典的 64M 內(nèi)存問(wèn)題
• 堆內(nèi)存分析、Native 內(nèi)存分析的基本套路
• tcmalloc、jemalloc 在 native 內(nèi)存分析中的使用
• finalize 原理
• hibernate 毀人不倦

現(xiàn)象

程序啟動(dòng)的參數(shù)

ENV=FAT java
-Xms1g -Xmx1g 
-XX:MetaspaceSize=120m 
-XX:MaxMetaspaceSize=400m 
-XX:+UseConcMarkSweepGC  
-jar 
EasiCareBroadCastRPC.jar

啟動(dòng)后內(nèi)存占用如下，驚人的 1.5G，Java 是內(nèi)存大戶(hù)，但是你也別這么玩啊。

下面是愉快的分析過(guò)程。

柿子先挑軟的捏

先通過(guò) jcmd 或者 jmap 查看堆內(nèi)存是否占用比較高，如果是這個(gè)問(wèn)題，那很快就可以解決了。

可以看到堆內(nèi)存占用 216937K + 284294K = 489.48M，Metaspace 內(nèi)存雖然不屬于 Java 堆，這里也顯示了出來(lái)占用 80M+，這兩部分加起來(lái)，遠(yuǎn)沒(méi)有到 1.5G。

那剩下的內(nèi)存去了哪里？到這里，已經(jīng)可以知道可能是堆以外的部分占用了內(nèi)存，接下來(lái)就是開(kāi)始使用 NativeMemoryTracking 來(lái)進(jìn)行下一步分析。

NativeMemoryTracking 使用

如果要跟蹤其它部分的內(nèi)存占用，需要通過(guò) -XX:NativeMemoryTracking 來(lái)開(kāi)啟這個(gè)特性

java -XX:NativeMemoryTracking=[off | summary | detail]

加入這個(gè)啟動(dòng)參數(shù)，重新啟動(dòng)進(jìn)程，隨后使用 jcmd 來(lái)打印相關(guān)的信息。

$ jcmd `jps | grep -v Jps | awk '{print $1}'` VM.native_memory detail

Total: reserved=2656938KB, committed=1405158KB
-                 Java Heap (reserved=1048576KB, committed=1048576KB)
                            (mmap: reserved=1048576KB, committed=1048576KB)

-                     Class (reserved=1130053KB, committed=90693KB)
                            (classes #15920)
                            (malloc=1605KB #13168)
                            (mmap: reserved=1128448KB, committed=89088KB)

-                    Thread (reserved=109353KB, committed=109353KB)
                            (thread #107)
                            (stack: reserved=108884KB, committed=108884KB)
                            (malloc=345KB #546)
                            (arena=124KB #208)

-                      Code (reserved=257151KB, committed=44731KB)
                            (malloc=7551KB #9960)
                            (mmap: reserved=249600KB, committed=37180KB)

-                        GC (reserved=26209KB, committed=26209KB)
                            (malloc=22789KB #306)
                            (mmap: reserved=3420KB, committed=3420KB)

-                  Compiler (reserved=226KB, committed=226KB)
                            (malloc=95KB #679)
                            (arena=131KB #7)

-                  Internal (reserved=15063KB, committed=15063KB)
                            (malloc=15031KB #20359)
                            (mmap: reserved=32KB, committed=32KB)

-                    Symbol (reserved=22139KB, committed=22139KB)
                            (malloc=18423KB #196776)
                            (arena=3716KB #1)

很失望，這里面顯示的所有的部分，看起來(lái)都很正常，沒(méi)有特別大異常占用的情況，到這里我們基本上可以知道是不受 JVM 管控的 native 內(nèi)存出了問(wèn)題，那要怎么分析呢？

pmap 初步查看

通過(guò) pmap 我們可以查看進(jìn)程的內(nèi)存分布，可以看到有大量的 64M 內(nèi)存區(qū)塊區(qū)域，這部分是 linux 內(nèi)存 ptmalloc 的典型現(xiàn)象

那這 64M 的內(nèi)存區(qū)域塊，是不是在上面 NMT 統(tǒng)計(jì)的內(nèi)存區(qū)域里呢？

NMT 工具的地址輸出 detail 模式會(huì)把每個(gè)區(qū)域的起始結(jié)束地址輸出出來(lái)，如下所示。

寫(xiě)一個(gè)簡(jiǎn)單的代碼（自己正則搞一下就行了）就可以將 pmap、nmt 兩部分整合起來(lái)，看看真正的堆、棧、GC 等內(nèi)存占用分布在內(nèi)存地址空間的哪一個(gè)部分。

可以看到大量 64M 部分的內(nèi)存區(qū)域不屬于任何 NMT 管轄的部分。

tcmalloc、jemalloc 來(lái)救場(chǎng)

我們可以通過(guò) tcmalloc 或者 jemalloc 可以做 native 內(nèi)存分配的追蹤，它們的原理都是 hook 系統(tǒng) malloc、free 等內(nèi)存申請(qǐng)釋放函數(shù)的實(shí)現(xiàn)，增加 profile 的邏輯。

下面以 tcmalloc 為例。

從源碼編譯 tcmalloc（github.com/gperftools/… LD_PRELOAD 來(lái) hook 內(nèi)存分配釋放的函數(shù)。

HEAPPROFILE=./heap.log 
HEAP_PROFILE_ALLOCATION_INTERVAL=104857600 
LD_PRELOAD=./libtcmalloc_and_profiler.so
java -jar xxx ...

啟動(dòng)過(guò)程中就會(huì)看到生成了很多內(nèi)存 dump 的分析文件，接下來(lái)使用 pprof 將 heap 文件轉(zhuǎn)為可讀性比較好的 pdf 文件。

pprof --pdf /path/to/java heap.log.xx.heap > test.pdf

內(nèi)存申請(qǐng)的鏈路如下圖所示。

可以看到絕大部分的內(nèi)存申請(qǐng)都耗在了 Java_java_util_zip_Inflater_inflateBytes，jar 包本質(zhì)就是一個(gè) zip 包， 在讀取 jar 包文件過(guò)程中大量使用了 jni 中的 cpp 代碼來(lái)處理，這里面大量申請(qǐng)釋放了內(nèi)存。

不用改代碼的解決方式

既然是因?yàn)樽x取 jar 包這個(gè) zip 文件導(dǎo)致的內(nèi)存瘋長(zhǎng)，那我不用 java -jar，直接把原 jar 包解壓，然后用 java -cp . AppMain 來(lái)啟動(dòng)是不是可以避免這個(gè)問(wèn)題呢？因?yàn)槲覀冺?xiàng)目因?yàn)闅v史原因是使用 shade 的方式，里面已經(jīng)沒(méi)有任何 jar 包了，全是 class 文件。奇跡出現(xiàn)了，不用 jar 包啟動(dòng)，RES 占用只有 400M，神奇不神奇！

到這里，我們更加確定是 jar 包啟動(dòng)導(dǎo)致的問(wèn)題，那為什么 jar 包啟動(dòng)會(huì)導(dǎo)致問(wèn)題呢？

探究根本原因

通過(guò) tcmalloc 可以看到大量申請(qǐng)釋放內(nèi)存的地方在 java.util.zip.Inflater 類(lèi)，調(diào)用它的 end 方法會(huì)釋放 native 的內(nèi)存。

我本以為是 end 方法沒(méi)有調(diào)用導(dǎo)致的，這種的確是有可能的，java.util.zip.InflaterInputStream 類(lèi)的 close 方法在一些場(chǎng)景下是不會(huì)調(diào)用 Inflater.end 方法，如下所示。

但是 Inflater 類(lèi)有實(shí)現(xiàn) finalize 方法，在 Inflater 對(duì)象不可達(dá)以后，JVM 會(huì)幫忙調(diào)用 Inflater 類(lèi)的 finalize 方法，

public class Inflater {

    public void end() {
        synchronized (zsRef) {
            long addr = zsRef.address();
            zsRef.clear();
            if (addr != 0) {
                end(addr);
                buf = null;
            }
        }
    }

    /**
     * Closes the decompressor when garbage is collected.
     */
    protected void finalize() {
        end();
    }

    private native static void initIDs();
    // ...
    private native static void end(long addr);
}

有兩種可能性

• Inflater 因?yàn)楸黄渌鼘?duì)象引用，沒(méi)能釋放，導(dǎo)致 finalize 方法不能被調(diào)用，內(nèi)存自然沒(méi)法釋放
• Inflater 的 finalize 方法被調(diào)用，但是被 libc 的 ptmalloc 緩存，沒(méi)能真正釋放回操作系統(tǒng)
  第二種可能性我在之前的一篇文章中已經(jīng)驗(yàn)證過(guò)，不是這個(gè)問(wèn)題

我們來(lái)看第一個(gè)可能性，通過(guò) dump 堆內(nèi)存來(lái)查看。果然，有 8 個(gè) Inflater 對(duì)象還存活沒(méi)能被 GC，除了被 JVM 內(nèi)部的 java.lang.ref.Finalizer 引用，還有其它的引用，導(dǎo)致 Inflater 在 GC 時(shí)無(wú)法被回收。

那這些內(nèi)存是不是真的跟 64M 的內(nèi)存區(qū)塊有關(guān)呢？空口無(wú)憑，我們來(lái)確認(rèn)一把。Inflater 類(lèi)有一個(gè) zsRef 字段，其實(shí)它就是一個(gè)指針地址，我們看看未釋放的 Inflater 的 zsRef 地址是不是位于我們所說(shuō)的 64M 內(nèi)存區(qū)塊里。

public class Inflater {
    private final ZStreamRef zsRef;
}

class ZStreamRef {
    private volatile long address;
    ZStreamRef (long address) {
        this.address = address;
    }

    long address() {
        return address;
    }

    void clear() {
        address = 0;
    }
}

通過(guò)一個(gè) ZStreamRef 找到 address 等于 140686448095872，轉(zhuǎn)為 16 進(jìn)制為 0x7ff41dc37280，這個(gè)地址位于的虛擬地址空間在這里：

正是在我們所說(shuō)的 64M 內(nèi)存區(qū)塊中。

如果你還不信，我們可以 dump 這塊內(nèi)存，我這里寫(xiě)了一個(gè)腳本

cat /proc/$1/maps | grep -Fv ".so" | grep " 0 " | awk '{print $1}' | grep $2 | ( IFS="-"
while read a b; do
dd if=/proc/$1/mem bs=$( getconf PAGESIZE ) iflag=skip_bytes,count_bytes \
skip=$(( 0x$a )) count=$(( 0x$b - 0x$a )) of="$1_mem_$a.bin"
done )

通過(guò)傳入進(jìn)程號(hào)和你想 dump 的內(nèi)存起始地址，就可以把這塊內(nèi)存 dump 出來(lái)。

./dump.sh `pidof java` 7ff41c000000

執(zhí)行上面的腳本，傳入兩個(gè)參數(shù)，一個(gè)是進(jìn)程 id，一個(gè)地址，會(huì)生成一個(gè) 64M 的內(nèi)存 dump 文件，通過(guò) strings 查看。

strings 6095_mem_7ff41c000000.bin

輸出結(jié)果如下，滿(mǎn)屏的都是類(lèi)文件相關(guān)的信息。

到這里已經(jīng)應(yīng)該無(wú)需再證明什么了，剩下的就是分析的事了。

那到底是被誰(shuí)引用的呢？展開(kāi)引用鏈，看到出現(xiàn)了一堆 ClassLoader。

一個(gè)意外的發(fā)現(xiàn)（與本問(wèn)題關(guān)系不大，順手解決一下）

這里出現(xiàn)了一個(gè)很奇怪的 nashorn 相關(guān)的 ClassLoader，眾所周不知，nashorn 是處理 JavaScript 相關(guān)的邏輯的，那為毛這個(gè)項(xiàng)目會(huì)用到 nashorn 呢？經(jīng)過(guò)仔細(xì)搜索，項(xiàng)目代碼并沒(méi)有使用。

那是哪個(gè)坑貨中間件引入的呢？debug 一下馬上就找到了原因，原來(lái)是臭名昭著的 log4j2，用了這么多年 log4j，頭一回知道，原來(lái) log4j2 是支持 javaScript、Groovy 等腳本語(yǔ)言的。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="RoutingTest">
  <Scripts>
    <Script name="selector" language="javascript"><![CDATA[
            var result;
            if (logEvent.getLoggerName().equals("JavascriptNoLocation")) {
                result = "NoLocation";
            } else if (logEvent.getMarker() != null && logEvent.getMarker().isInstanceOf("FLOW")) {
                result = "Flow";
            }
            result;
            ]]></Script>
    <ScriptFile name="groovy.filter" path="scripts/filter.groovy"/>
  </Scripts>
</Configuration>

我們項(xiàng)目中并沒(méi)有用到類(lèi)似的特性（因?yàn)椴恢溃?，只能說(shuō)真是無(wú)語(yǔ)，你好好的當(dāng)一個(gè)工具人日志庫(kù)不好嗎，搞這么多花里胡哨的東西，膚淺！

代碼在這里

這個(gè)問(wèn)題我粗略看了一下，截止到官方最新版還沒(méi)有一個(gè)開(kāi)關(guān)可以關(guān)掉 ScriptEngine，不行就自己上，自己拉取項(xiàng)目中 log4j 對(duì)應(yīng)版本的代碼，做了修改，重新打包運(yùn)行，

重新運(yùn)行后 nashorn 部分的 ClassLoader 確實(shí)沒(méi)有了，不過(guò)這里只是一個(gè)小插曲，native 內(nèi)存占用的問(wèn)題并沒(méi)有解決。

兇手浮出水面

接下來(lái)我們就要找哪些代碼在瘋狂調(diào)用 java.util.zip.Inflater.inflateBytes 方法

使用 watch 每秒 jstack 一下線程，馬上就看到了 hibernate 在瘋狂的調(diào)用。

hibernate 是我們歷史老代碼遺留下來(lái)的，一直沒(méi)有移除掉，看來(lái)還是踩坑了。

找到這個(gè)函數(shù)對(duì)應(yīng)代碼 org.hibernate.jpa.boot.archive.internal.JarFileBasedArchiveDescriptor#visitArchive#146

垃圾代碼，jarFile.getInputStream( zipEntry ) 生成了一個(gè)新的流但沒(méi)有做關(guān)閉處理。

其實(shí)我也不知道，為啥 hibernate 要把我 jar 包中所有的類(lèi)都掃描解析一遍，完全有毛病。

我們來(lái)把這段代碼扒出來(lái)，寫(xiě)一個(gè)最簡(jiǎn) demo。

public class JarFileTest {
    public static void main(String[] args) throws IOException {
        new JarFileTest().process();
        System.in.read();
    }

    public static byte[] getBytesFromInputStream(InputStream inputStream) throws IOException {
        // 省略 read 的邏輯
        return result;
    }

    public void process() throws IOException {
        JarFile jarFile = null;
        try {
            jarFile = new JarFile("/data/dev/broadcast/EasiCareBroadCastRPC.jar");
            final Enumeration<? extends ZipEntry> zipEntries = jarFile.entries();
            while (zipEntries.hasMoreElements()) {
                final ZipEntry zipEntry = zipEntries.nextElement();
                if (zipEntry.isDirectory()) {
                    continue;
                }

                byte[] bytes = getBytesFromInputStream(jarFile.getInputStream(zipEntry));

                System.out.println("processing: " + zipEntry.getName() + "\t" + bytes.length);
            }
        } finally {
            try {
                if (jarFile != null) jarFile.close();
            } catch (Exception e) {
            }
        }
    }
}

運(yùn)行上面的代碼。

javac JarFileTest.java
java -Xms1g -Xmx1g -XX:MetaspaceSize=120m -XX:MaxMetaspaceSize=400m -XX:+UseConcMarkSweepGC  -cp . JarFileTest

內(nèi)存 RES 占用立馬飆升到了 1.2G 以上，且無(wú)論如何 GC 都無(wú)法回收，但堆內(nèi)存幾乎等于 0。

堆內(nèi)存占用如下所示，經(jīng)過(guò) GC 以后新生代占用為 0，老年代占用為 275K

全被 64M 內(nèi)存占滿(mǎn)。

通過(guò)修改代碼，將流關(guān)閉

while (zipEntries.hasMoreElements()) {
    final ZipEntry zipEntry = zipEntries.nextElement();
    if (zipEntry.isDirectory()) {
        continue;
    }

    InputStream is = jarFile.getInputStream(zipEntry);
    byte[] bytes = getBytesFromInputStream(is);

    System.out.println("processing: " + zipEntry.getName() + "\t" + bytes.length);
    try {
        is.close();
    } catch (Exception e) {

    }
}

再次測(cè)試，問(wèn)題解決了，native 內(nèi)存占用幾乎消失了，接下來(lái)就是解決項(xiàng)目中的問(wèn)題。一種是徹底移除 hibernate，將它替換為我們現(xiàn)在在用的 mybatis，這個(gè)我不會(huì)。我打算來(lái)改一下 hibernate 的源碼。

嘗試修改

修改這段代碼（ps這里是不成熟的改動(dòng)，close 都應(yīng)該放 finally，多個(gè) close 需要分別捕獲異常，但是為了簡(jiǎn)單，這里先簡(jiǎn)化），加入 close 的邏輯。

重新編譯 hibernate，install 到本地，然后重新打包運(yùn)行。此時(shí) RES 占用從 1.5G 左右降到了 700 多 M。

而且比較可喜的是，64M 區(qū)塊的 native 內(nèi)存占用非常非常小，這里 700M 內(nèi)存有 448M 是 dirty 的 heap 區(qū)，這部分只是 JVM 預(yù)留的。

到這里，我們基本上已經(jīng)解決了這個(gè)問(wèn)題。后面我去看了一下 hibernate 的源碼，在新版本里面，已經(jīng)解決了這個(gè)問(wèn)題，但是我不打算升級(jí)了，干掉了事。

詳見(jiàn)：

github.com/hibernate/h…

后記

因?yàn)椴皇潜疚牡闹攸c(diǎn)，文章涉及的一些工具的使用，我沒(méi)有展開(kāi)來(lái)聊，大家感興趣可以自己搞定。

其實(shí) native 內(nèi)存泄露沒(méi)有我們想象的那么復(fù)雜，可以通過(guò) NMT、pmap、tcmalloc 逐步逐步進(jìn)行分析，只要能復(fù)現(xiàn)，都不叫 bug。

最后珍愛(ài)生命，遠(yuǎn)離 hibernate。

作者：挖坑的張師傅
鏈接：https://juejin.cn/post/7078624931826794503