一次尋常的堆外記憶體洩漏排查

山河墨畫發表於2020-11-01

背景

最近部門逐漸的將一些老專案遷移到Spring體系下，對於業務複雜的系統這個過程實在讓人受苦不少，藉助Spring框架和已經建立的微服務體系倒是的確能改善這些老程式碼。也有一些處理邏輯非常簡單的系統只需要稍微修改一下即可繼續提供服務，這次出問題的就是一個邏輯上非常簡單的系統，JVM啟動引數設定了2G的最大堆記憶體，但在經過短暫的壓測後記憶體佔用漲到了5G左右。

該圖片由ksyfffka07在Pixabay上釋出

PS：在記錄這篇文章時問題已經被解決，文中用圖均為筆者自行復現，可能會出現一點與描述的偏差。之所以標題為“尋常”的堆外記憶體洩漏，是因為結局讓人感到情理之外，意料之中。

一、猜測

由於這個專案的遷移並不是我本人負責，內部的程式碼一開始也不是很熟悉，只是壓測時這個服務部署在了我負責的測試環境中的幾臺機器，所以第一時間是我開始分析，隨後通知同事也開始在程式碼中尋找可能的異常點。首先從伺服器現場開始：

上圖為應用剛剛啟動時的資源佔用

上圖為正常服務時的資源佔用

用jmeter壓一下：

e: 100 Started: 100 Finished: 0
summary +  46772 in 00:00:30 = 1559.2/s Avg:    64 Min:     0 Max:  1070 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要結果 = 697903 in 00:08:04 = 1443.4/s Avg:    69 Min:     0 Max:  5442 Err:     0 (0.00%)
summary = 697903 in 00:08:04 = 1443.4/s Avg:    69 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要結果 +  46700 in 00:00:30 = 1556.7/s Avg:    63 Min:     0 Max:  1046 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要結果 = 744603 in 00:08:34 = 1450.0/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
summary +  46700 in 00:00:30 = 1556.6/s Avg:    63 Min:     0 Max:  1046 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 744603 in 00:08:34 = 1450.0/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要結果 +  46945 in 00:00:30 = 1564.9/s Avg:    64 Min:     0 Max:   986 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要結果 = 791548 in 00:09:04 = 1456.3/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
summary +  46945 in 00:00:30 = 1564.9/s Avg:    64 Min:     0 Max:   986 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 791548 in 00:09:04 = 1456.3/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要結果 +  47176 in 00:00:30 = 1572.5/s Avg:    63 Min:     0 Max:   978 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要結果 = 838724 in 00:09:34 = 1462.4/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
summary +  47176 in 00:00:30 = 1572.4/s Avg:    63 Min:     0 Max:   978 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 838724 in 00:09:34 = 1462.4/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要結果 +  46890 in 00:00:30 = 1562.9/s Avg:    63 Min:     0 Max:  1062 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary +  46890 in 00:00:30 = 1563.0/s Avg:    63 Min:     0 Max:  1062 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 885614 in 00:10:04 = 1467.4/s Avg:    67 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要結果 = 885614 in 00:10:04 = 1467.4/s Avg:    67 Min:     0 Max:  5442 Err:     0 (0.00%)
......

不久，記憶體佔用突破了JVM引數限制( 下圖為筆者後期復現的情況，沒有繼續壓到更高 )

[java_server@iZm5e8a3w80j********* ***]$ ps -ef |grep [*********]
java_se+ 19307     1 52 09:35 pts/0    01:06:46 java -Xmx2048m -Xms512m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -jar /data/java_server/*********.jar --spring.profiles.active=test *********

進入arthas，檢視堆區情況：

顯然，實際佔用的記憶體遠高於堆區內的情況，基本可以斷定是堆外記憶體洩漏。粗略的瀏覽一下程式碼，程式碼質量較差，大部分是很簡單的邏輯，完全沒有主動涉及到NIO。那麼是某個Spring Boot依賴或者Tomcat引起的嗎？

二、排查

看到了表面症狀，筆者開始著手分析，首先應用啟動時沒有加-XX:NativeMemoryTracking=detail 引數，所以不能通過java直接看到記憶體分佈情況，但並不能確定這種情況是可復現的，所以也沒有打算直接重啟加引數。

pmap檢視記憶體分佈情況：pmap -x 19307| sort -k 3 -n -r

[java_server@iZm5e8a3w80jylw*** ***]$ pmap -x 19307| sort -k 3 -n -r
total kB         7107804 3100028 3085344
00000000d5580000  698368  697856  697856 rw---   [ anon ]
0000000080000000  523264  147496  147496 rw---   [ anon ]
0000000001eff000  127628  119200  119200 rw---   [ anon ]
00007f7cd4000000   65536   60984   60984 rw---   [ anon ]
00007f7cbc000000   65532   60296   60296 rw---   [ anon ]
00007f7cb8000000   65532   60284   60284 rw---   [ anon ]
00007f7c80000000   65516   59844   59844 rw---   [ anon ]
00007f7c6c000000   65492   59676   59676 rw---   [ anon ]
00007f7c78000000   65524   58816   58816 rw---   [ anon ]
00007f7cf0000000   65500   58692   58692 rw---   [ anon ]
00007f7c7c000000   65536   58372   58372 rw---   [ anon ]
00007f7c74000000   65536   58164   58164 rw---   [ anon ]
00007f7ca8000000   65532   58012   58012 rw---   [ anon ]
00007f7ca0000000   65528   57552   57552 rw---   [ anon ]
00007f7c84000000   65500   57300   57300 rw---   [ anon ]
00007f7cd8000000   65532   56996   56996 rw---   [ anon ]
00007f7ca4000000   65512   56992   56992 rw---   [ anon ]
00007f7cc4000000   65484   56104   56104 rw---   [ anon ]
00007f7cdc000000   65512   55752   55752 rw---   [ anon ]
00007f7ce0000000   65536   55720   55720 rw---   [ anon ]
00007f7ce8000000   65420   54644   54644 rw---   [ anon ]
00007f7cc0000000   65528   54552   54552 rw---   [ anon ]
00007f7c9c000000   63364   54396   54396 rw---   [ anon ]
00007f7cac000000   65304   54144   54144 rw---   [ anon ]
00007f7cb0000000   65508   53692   53692 rw---   [ anon ]
00007f7c90000000   65516   53588   53588 rw---   [ anon ]
00007f7cd0000000   63620   52376   52376 rw---   [ anon ]
00007f7cb4000000   65528   52344   52344 rw---   [ anon ]
00007f7c70000000   65512   51856   51856 rw---   [ anon ]
00007f7c88000000   65532   51652   51652 rw---   [ anon ]
00007f7c94000000   65504   51372   51372 rw---   [ anon ]

。。。。

發現上面一大堆看起來不正常的64M記憶體空間，使用strace追蹤系統記憶體申請：strace -f -e "brk,mmap,munmap" -p 19307（主要的幾種記憶體分配途徑）

[java_server@iZm5e8a3w80jylwqc85v5rZ crypto-oom]$ strace -f -e "brk,mmap,munmap" -p 19307
strace: Process 19307 attached with 44 threads
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000

無請求的時候很正常，jmeter開啟：

一些奇怪的記憶體申請記錄開始出現，符合開頭描述的一堆64M記憶體空間，從smaps檔案裡找到這段記憶體地址：cat /proc/19307/smaps > smaps.txt

進入gdb：gdb -p 19307 ，注意從smaps檔案裡拿出來的是16進位制的記憶體地址，但是在gdb中操作的時候需要為地址加上0x

嘗試dump這段記憶體：dump memory gdb-dump.mem 0x7f7c04000000 0x7f7c04141000

檢視記憶體內容：strings gdb-dump.mem

[java_server@iZm5e8a3w80jylw**** *****]$ strings gdb-dump.mem 
1599
4325625
159
LFMA
LSGGF53W
15996
4325625
15996
LSVFB6
ss23
0q526
LSVFB6
LSVFB61
43256
e.coyot
tProces 
e.coyot
tProces0
ache/co
rState;@
Erro`
le;)V
~Y6     2Y:
LSGGF
LSVFB61

這一段看起來像是請求中的引數（涉及手機號等資訊均刪減過，非完整資訊），而且片段中出現了 "coyot"，看起來是Tomcat中的聯結器Coyote，難道真是Tomcat的原因？雖然知道不大可能，但是抱著好奇的心態還是去翻了tomcat專案的issues目錄，並沒有發現類似的情況，何況jmeter指令碼只把吞吐量加到了1000/s ，線上的其他服務可是比這個吞吐量大多了都沒出現過問題啊。

回到正題，我們繼續從strace給出的資訊著手，下面是另一段strace的資訊，表示19319號執行緒正在取消某塊64M記憶體空間的對映

那使用jstack dump執行緒資訊看看：jstack 19307 > stack.txt ，將19319轉化為16進位制: 4B77,進入執行緒棧搜尋：

嗯？這是一個Finalizer執行緒？這是哪部分的程式碼用了finalize方法來釋放資源的嗎？好一頓找，最終在服務內部發現了兩個未手動關閉的流，問題結束。。。

三、探究

筆者當時排查這裡，將結論定為"服務內未關閉的流"就開始改程式碼，最終解決了問題。照著這個思路走下去，我們需要探究的點就從堆外記憶體洩漏排查變成了“未釋放的流會導致堆外記憶體洩漏嗎？”

我相信一些同學會表示比較茫然，從我們初學Java時，各種資料都會告訴我們“最好”及時釋放掉使用完成的資源，但是如果使用的流過多而不釋放的話會導致什麼結果呢？例如這個問題：https://stackoverflow.com/questions/22889075/do-unclosed-streams-cause-memory-leaks-in-java。bmargulies的回答非常準確：

Failing to close a stream is not a memory leak in this sense. Streams that have native resources have finalizers; the GC will eventually close them down. Unless you hold a reference to the unclosed stream it isn't a leak.

事實也的確如此。那麼筆者最後的結論是錯誤的嗎？以下給出一些片段性的資訊供同學們一起思考。

系統中未關閉流的類為 java.util.zip.GZIPInputStream
《Java核心技術》卷二第二章第一小節的描述：

當你完成對輸入／輸出流的讀寫時，應該通過呼叫close 方法來關閉它，這個呼叫會釋放掉十分有限的作業系統資源。如果一個應用程式開啟了過多的輸入／輸出流而沒有關閉，那麼系統資源將被耗盡。

《Java核心思想》第二章第七條：避免使用finalize方法

GZIPInputStream原始碼片段：

    public void close() throws IOException {
        if (!closed) {
            super.close();
            eos = true;
            closed = true;
        }
    }

java.util.zip.Inflater原始碼片段：


    /**
     * Creates a new decompressor. If the parameter 'nowrap' is true then
     * the ZLIB header and checksum fields will not be used. This provides
     * compatibility with the compression format used by both GZIP and PKZIP.
     * <p>
     * Note: When using the 'nowrap' option it is also necessary to provide
     * an extra "dummy" byte as input. This is required by the ZLIB native
     * library in order to support certain optimizations.
     *
     * @param nowrap if true then support GZIP compatible compression
     */
    public Inflater(boolean nowrap) {
        zsRef = new ZStreamRef(init(nowrap));
    }

    private native static long init(boolean nowrap);

	/**
     * Closes the decompressor and discards any unprocessed input.
     * This method should be called when the decompressor is no longer
     * being used, but will also be called automatically by the finalize()
     * method. Once this method is called, the behavior of the Inflater
     * object is undefined.
     */
    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 end(long addr);

java.util.zip.Inflater end 的native方法呼叫底層Inflater.c檔案部分程式碼（來自openjdk）：

Java_java_util_zip_Inflater_init(JNIEnv *env, jclass cls, jboolean nowrap)
{
    z_stream *strm = calloc(1, sizeof(z_stream));

    if (strm == NULL) {
        JNU_ThrowOutOfMemoryError(env, 0);
        return jlong_zero;
    } else {
        const char *msg;
        int ret = inflateInit2(strm, nowrap ? -MAX_WBITS : MAX_WBITS);
        switch (ret) {
          case Z_OK:
.....

Java_java_util_zip_Inflater_end(JNIEnv *env, jclass cls, jlong addr)
{
    if (inflateEnd(jlong_to_ptr(addr)) == Z_STREAM_ERROR) {
        JNU_ThrowInternalError(env, 0);
    } else {
        free(jlong_to_ptr(addr));
    }
}

相信聰明的你心中一定有了自己的結論，自己嘗試探索收穫才是最大的。

四、結語

這一次出現的問題很明顯是同事們在遷移老舊程式碼，以及程式碼審查時的掉以輕心導致的。還好在測試階段被發現了，希望同學們多注意程式碼質量，細節決定成敗，寫出更加健壯的程式碼，共勉。如果文中有任何敘述錯誤或者不當的地方歡迎及時指出。

一次 Java 記憶體洩漏的排查
2020-03-15
Java記憶體
netty 堆外記憶體洩露排查盛宴
2018-09-03
Netty記憶體洩露
Spring Boot引起的“堆外記憶體洩漏”排查及經驗總結
2019-01-04
Spring Boot記憶體
記一次使用windbg排查記憶體洩漏的過程
2020-05-31
記憶體
記一次 Ruby 記憶體洩漏的排查和修復
2019-04-03
記憶體
一次排查Java專案記憶體洩漏的過程
2018-08-17
Java記憶體
一波三折！記一次非堆記憶體洩漏(CXF+Jackson)的排查
2022-11-23
記憶體
JAVA堆外記憶體排查小結
2019-03-31
Java記憶體
JVM堆外記憶體問題排查
2018-07-15
JVM記憶體
分散式 | 令人頭疼的堆外記憶體洩露怎麼排查？
2022-12-16
分散式記憶體洩露
記一次 .NET 某外貿Web站記憶體洩漏分析
2021-09-09
Web記憶體
記憶體洩漏
2008-10-07
記憶體
記憶體洩漏與排查流程——安卓效能優化
2019-01-07
記憶體安卓優化
造成記憶體洩漏的異常處理
2022-04-10
記憶體
記一次"記憶體洩露"排查過程
2019-10-15
記憶體洩露
分析記憶體洩漏和goroutine洩漏
2021-10-22
記憶體Go
javascript的記憶體管理以及3種常見的記憶體洩漏
1970-01-01
JavaScript記憶體
記憶體洩漏的原因
2018-07-10
記憶體
解Bug之路-記一次JVM堆外記憶體洩露Bug的查詢
2020-08-18
JVM記憶體洩露
Bulk 異常引發的 Elasticsearch 記憶體洩漏
2018-08-29
Elasticsearch記憶體
js記憶體洩漏
2019-02-16
JS記憶體
Java記憶體洩漏
2020-12-06
Java記憶體
webView 記憶體洩漏
2016-05-24
WebView記憶體
Javascript記憶體洩漏
2013-04-05
JavaScript記憶體
一次django記憶體異常排查
2020-07-30
Django記憶體
記一次使用 laravel-s 記憶體洩漏
2022-01-08
Laravel記憶體
Android常見記憶體洩漏總結
2019-02-14
Android記憶體
記錄一次記憶體洩漏排查過程
2023-11-06
記憶體
一次Kafka記憶體洩露排查經過
2022-02-16
Kafka記憶體洩露
WebView引起的記憶體洩漏
2019-09-25
WebView記憶體
ARC下的記憶體洩漏
2018-01-25
記憶體
【轉】Java的記憶體洩漏
2009-01-08
Java記憶體
異常連線導致的記憶體洩漏排查
2019-08-03
記憶體
記憶體分析與記憶體洩漏定位
2017-11-03
記憶體
記憶體洩漏和記憶體溢位
2015-07-11
記憶體溢位
valgrind 記憶體洩漏分析
2021-05-17
記憶體
Android 記憶體洩漏
2020-11-19
Android記憶體
Android記憶體洩漏
2018-03-11
Android記憶體

一次尋常的堆外記憶體洩漏排查

背景

一、 猜測

二、排查

三、探究

四、 結語

相關文章

一、猜測

四、結語