背景
最近部門逐漸的將一些老專案遷移到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.Inflaterend 的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)); } }
相信聰明的你心中一定有了自己的結論，自己嘗試探索收穫才是最大的。
四、 結語
這一次出現的問題很明顯是同事們在遷移老舊程式碼，以及程式碼審查時的掉以輕心導致的。還好在測試階段被發現了，希望同學們多注意程式碼質量，細節決定成敗，寫出更加健壯的程式碼，共勉。如果文中有任何敘述錯誤或者不當的地方歡迎及時指出。