記一次Native memory leak排查程序-有解無憂

1 問題現象

路由計算服務是路由系統的核心服務，負責運單路由計劃的計算以及實操與計劃的匹配，在運維程序中，發現在長期不重啟的情況下，有TP99緩慢爬坡的現象，此外，在每周例行調度的試算程序中，能明顯看到記憶體的上漲，以下截圖為這兩個例外情況的監控，

TP99爬坡

記憶體爬坡

機器配置如下

CPU: 16C RAM: 32G

Jvm配置如下：

-Xms20480m （后面切換到了8GB） -Xmx20480m （后面切換到了8GB） -XX:MaxPermSize=2048m -XX:MaxGCPauseMillis=200 -XX:+ParallelRefProcEnabled -XX:+PrintReferenceGC -XX:+UseG1GC -Xss256k -XX:ParallelGCThreads=16 -XX:ConcGCThreads=4 -XX:MaxDirectMemorySize=2g -Dsun.net.inetaddr.ttl=600 -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -Dlog4j2.asyncQueueFullPolicy=Discard -XX:MetaspaceSize=1024M -XX:G1NewSizePercent=35 -XX:G1MaxNewSizePercent=35

例行任務調度情況：

每周一凌晨2:00觸發執行，上面截圖，共包含了兩個周期的任務，可以看到，在第一次執行時，記憶體直接從33%爬升至75%，在第二次執行時，爬坡至88%后，OOM例外退出，

2 問題排查

由于有兩種現象，所以排查有兩條主線，第一條是以追蹤OOM原因為目的的記憶體使用情況排查，簡稱記憶體問題排查，第二條是TP99緩慢增長原因排查，簡稱性能下降問題排查，

2.1 性能下降問題排查

由于是緩慢爬坡，而且爬坡周期與服務重啟有直接關系，所以可以排出外部介面性能問題的可能，優先從自身程式找原因，因此，首先排查GC情況和記憶體情況，下面是經過長期未重啟的GC log，這是一次YGC，總耗時1.16秒，其中Ref Proc環節消耗了1150.3 ms，其中的JNI Weak Reference的回收消耗了1.1420596秒，而在剛重啟的機器上，JNI Weak Reference的回收時間為0.0000162秒，所以可以定位到，TP99增加就是JNI Weak Reference回收周期增長導致的，

JNI Weak Reference顧名思義，應該跟Native memory的使用有關，不過由于Native memory排查難度較大，所以還是先從堆的使用情況開始排查，以碰碰運氣的心態，看是否能發現蛛絲馬跡，

2.2 記憶體問題排查

回到記憶體方面，經過建哥提示，應該優先復現問題，并且在每周觸發的任務都會穩定復現記憶體上漲，所以從調度任務這個方向，排查更容易一些，通過@柳巖的幫助，具備了在試算環境隨時復現問題的能力，

記憶體問題排查，仍然是從堆內記憶體開始，多次dump后，盡管java行程的總記憶體使用量持續上漲，但是堆記憶體使用量并未見明顯增長，通過申請root權限，并部署arthas后，通過arthas的dashbord功能，可以明顯看到，堆(heap)和非堆(nonheap)都保持平穩，

arthas dashboard

記憶體使用情況，存在翻倍現象

由此可以斷定，是native memory使用量增長，導致整個java應用的記憶體使用率增長，分析native的第一步是需要jvm開啟-XX:NativeMemoryTracking=detail，

2.2.1 使用jcmd查看記憶體整體情況

jcmd可以列印java行程所有記憶體分配情況，當開啟NativeMemoryTracking=detail引數后，可以看到native方法呼叫堆疊資訊，在申請root權限后，直接使用yum安裝即可，

安裝好后，執行如下命令，

jcmd <pid> VM.native_memory detail

jcmd結果展示

上圖中，共包含兩部分，第一部分是記憶體總體情況摘要，包括總記憶體使用量，以及分類使用情況，分類包括：Java Heap、Class、Thread、Code、GC、Compiler、Internal、Symbol、Native Memory Tracking、Arena Chunk、Unknown，每個分類的介紹，可以看這篇檔案；第二部分是詳情，包括了每段記憶體分配的起始地址和結束地址，具體大小，和所屬的分類，比如截圖中的部分，是描述了為Java heap分配了8GB的記憶體（后面為了快速復現問題，heap size從20GB調整為8GB），后面縮進的行，代表了記憶體具體分配的情況，

間隔2小時，使用jcmd dump兩次后，進行對比，可以看到Internal這部分，有明顯的增長，Internal是干什么的，為什么會增長？經過Google，發現此方面的介紹非常少，基本就是命令列決議、JVMTI等呼叫，請教@崔立群后，了解到JVMTI可能與java agent相關，在路由計算中，應該只有pfinder與java agent有關，但是底層中間件出問題的影響面，不應該只有路由一家，所以只是問了一下pfinder研發，就沒再繼續投入跟進，

2.2.2 使用pmap和gdb分析記憶體

首先給出此方式的結論，這種分析由于包含了比較大的猜測的成分，所以不建議優先嘗試，整體的思路是，使用pmap將java行程分配的所有記憶體進行輸出，挑選出可疑的記憶體區間，使用gdb進行dump，并編碼可視化其內容，進行分析，
網上有很多相關博客，都通過分析存在大量的64MB記憶體分配塊，從而定位到了鏈接泄漏的案例，所以我也在我們的行程上查看了一下，確實包含很多64MB左右的記憶體占用，按照博客中介紹，將記憶體編碼后，內容大部分為JSF相關，可以推斷是JSF netty 使用的記憶體池，我們使用的1.7.4版本的JSF并未有記憶體池泄漏問題，所以應當與此無關，
pmap：https://docs.oracle.com/cd/E56344_01/html/E54075/pmap-1.html
gdb：https://segmentfault.com/a/1190000024435739

2.2.3 使用strace分析系統呼叫情況

這應該算是碰運氣的一種分析方法了，思路就是使用strace將每次分配記憶體的系統呼叫輸出，然后與jstack中執行緒進行匹配，從而確定具體是由哪個java執行緒分配的native memory，這種效率最低，首先系統呼叫非常頻繁，尤其在RPC較多的服務上面，所以除了比較明顯的記憶體泄漏情況，容易用此種方式排查，如本文的緩慢記憶體泄漏，基本都會被正常呼叫淹沒，難以觀察，

2.3 問題定位

經過一系列嘗試，均沒有定位根本原因，所以只能再次從jcmd查出的Internal記憶體增長這個現象入手，到目前，還有記憶體分配明細這條線索沒有分析，盡管有1.2w行記錄，只能順著捋一遍，希望能發現Internal相關的線索，

通過下面這段內容，可以看到分配32k Internal記憶體空間后，有兩個JNIHandleBlock相關的記憶體分配，分別是4GB和2GB，MemberNameTable相關呼叫，分配了7GB記憶體，

[0x00007fa4aa9a1000 - 0x00007fa4aa9a9000] reserved and committed 32KB for Internal from
    [0x00007fa4a97be272] PerfMemory::create_memory_region(unsigned long)+0xaf2
    [0x00007fa4a97bcf24] PerfMemory::initialize()+0x44
    [0x00007fa4a98c5ead] Threads::create_vm(JavaVMInitArgs*, bool*)+0x1ad
    [0x00007fa4a952bde4] JNI_CreateJavaVM+0x74

[0x00007fa4aa9de000 - 0x00007fa4aaa1f000] reserved and committed 260KB for Thread Stack from
    [0x00007fa4a98c5ee6] Threads::create_vm(JavaVMInitArgs*, bool*)+0x1e6
    [0x00007fa4a952bde4] JNI_CreateJavaVM+0x74
    [0x00007fa4aa3df45e] JavaMain+0x9e
Details:

[0x00007fa4a946d1bd] GenericGrowableArray::raw_allocate(int)+0x17d
[0x00007fa4a971b836] MemberNameTable::add_member_name(_jobject*)+0x66
[0x00007fa4a9499ae4] InstanceKlass::add_member_name(Handle)+0x84
[0x00007fa4a971cb5d] MethodHandles::init_method_MemberName(Handle, CallInfo&)+0x28d
                             (malloc=7036942KB #10)

[0x00007fa4a9568d51] JNIHandleBlock::allocate_handle(oopDesc*)+0x2f1
[0x00007fa4a9568db1] JNIHandles::make_weak_global(Handle)+0x41
[0x00007fa4a9499a8a] InstanceKlass::add_member_name(Handle)+0x2a
[0x00007fa4a971cb5d] MethodHandles::init_method_MemberName(Handle, CallInfo&)+0x28d
                             (malloc=4371507KB #14347509)

[0x00007fa4a956821a] JNIHandleBlock::allocate_block(Thread*)+0xaa
[0x00007fa4a94e952b] JavaCallWrapper::JavaCallWrapper(methodHandle, Handle, JavaValue*, Thread*)+0x6b
[0x00007fa4a94ea3f4] JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)+0x884
[0x00007fa4a949dea1] InstanceKlass::register_finalizer(instanceOopDesc*, Thread*)+0xf1
                             (malloc=2626130KB #8619093)

[0x00007fa4a98e4473] Unsafe_AllocateMemory+0xc3
[0x00007fa496a89868]
                             (malloc=239454KB #723)

[0x00007fa4a91933d5] ArrayAllocator<unsigned long, (MemoryType)7>::allocate(unsigned long)+0x175
[0x00007fa4a9191cbb] BitMap::resize(unsigned long, bool)+0x6b
[0x00007fa4a9488339] OtherRegionsTable::add_reference(void*, int)+0x1c9
[0x00007fa4a94a45c4] InstanceKlass::oop_oop_iterate_nv(oopDesc*, FilterOutOfRegionClosure*)+0xb4
                             (malloc=157411KB #157411)

[0x00007fa4a956821a] JNIHandleBlock::allocate_block(Thread*)+0xaa
[0x00007fa4a94e952b] JavaCallWrapper::JavaCallWrapper(methodHandle, Handle, JavaValue*, Thread*)+0x6b
[0x00007fa4a94ea3f4] JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)+0x884
[0x00007fa4a94eb0d1] JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*)+0x321
                             (malloc=140557KB #461314)

通過對比兩個時間段的jcmd的輸出，可以看到JNIHandleBlock相關的記憶體分配，確實存在持續增長的情況，因此可以斷定，就是JNIHandles::make_weak_global 這部分記憶體分配，導致的泄漏，那么這段邏輯在干什么，是什么導致的泄漏？

通過Google，找到了Jvm大神的文章，為我們解答了整個問題的來龍去脈，問題現象與我們的基本一致，博客：https://blog.csdn.net/weixin_45583158/article/details/100143231

其中，寒泉子給出了一個復現問題的代碼，在我們的代碼中有一段幾乎一摸一樣的，這確實包含了運氣成分，

// 博客中的代碼
public static void main(String args[]){

        while(true){

            MethodType type = MethodType.methodType(double.class, double.class);

            try {

                MethodHandle mh = lookup.findStatic(Math.class, "log", type);

            } catch (NoSuchMethodException e) {

                e.printStackTrace();

            } catch (IllegalAccessException e) {

                e.printStackTrace();

            }

        }

    }
}

jvm bug：https://bugs.openjdk.org/browse/JDK-8152271

就是上面這個bug，頻繁使用MethodHandles相關反射，會導致過期物件無法被回收，同時會引發YGC掃描時間增長，導致性能下降，

3 問題解決

由于jvm 1.8已經明確表示，不會在1.8處理這個問題，會在java 重構，但是我們短時間也沒辦法升級到java ，所以沒辦法通過直接升級JVM進行修復，由于問題是頻繁使用反射，所以考慮了添加快取，讓頻率降低，從而解決性能下降和記憶體泄漏的問題，又考慮到執行緒安全的問題，所以將快取放在ThreadLocal中，并添加LRU的淘汰規則，避免再次泄漏情況發生，

最終修復效果如下，記憶體增長控制在正常的堆記憶體設定范圍內（8GB），增漲速度較溫和，重啟2天后，JNI Weak Reference時間為0.0001583秒，符合預期，

4 總結

Native memory leak的排查思路與堆內記憶體排查類似，主要是以分時dump和對比為主，通過觀察例外值或例外增長量的方式，確定問題原因，由于工具差異，Native memory的排查程序，難以將記憶體泄漏直接與執行緒相關聯，可以通過strace方式碰碰運氣，此外，根據有限的線索，在搜索引擎上進行搜索，也許會搜到相關的排查程序，收到意外驚喜，畢竟jvm還是非常可靠的軟體，所以如果存在比較嚴重的問題，應該很容易在網上找到相關的解決辦法，如果網上的內容較少，那可能還是需要考慮，是不是用了過于小眾的軟體依賴，

在開發方面，盡量使用主流的開發設計模式，盡管技術沒有好壞之分，但是像反射、AOP等實作方式，需要限制使用范圍，因為這些技術，會影響代碼的可讀性，并且性能也是在不斷增加的AOP中，逐步變差的，另外，在新技術嘗試方面，盡量從邊緣業務開始，在核心應用中，首先需要考慮的就是穩定性問題，這種意識可以避免踩一些別人難以遇到的坑，從而減少不必要的麻煩，

作者：京東物流陳昊龍

來源：京東云開發者社區

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/556397.html

標籤：其他

上一篇：狂收 3.2k star！百度開源壓測工具，可模擬幾十億的并發場景，太強悍了！

下一篇：返回列表