记一次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%。第二次执行时，OOM在爬到88%后异常退出。

因为有两种现象，调查有两条主线。一是跟踪OOM的内存使用情况，简称内存问题调查。二是TP99增长缓慢的原因调查，简称性能下降问题调查。

由于爬坡速度慢，爬坡周期与服务重启直接相关，因此可以排出外部接口性能问题的可能性。优先从自己的程序中找出原因。因此，首先要调查GC和内存的情况。以下是GC长期未重启的GC log。这是一次YGC，总耗时1.16秒。其中Ref Proc消耗了1150.3 ms，其中JNI Weak Reference的回收消耗了1.1420596秒。在刚刚重启的机器上，JNI Weak Reference的回收时间为0.000162秒。因此，TP99的增加可以定位为JNI Weak 由于Reference回收周期的增长。

JNI Weak 顾名思义，Reference应该和Native一起使用 使用memory有关。但是因为Native memory的调查比较困难。所以还是从堆的使用情况开始，以碰运气的心态，看能不能找到线索。

回到内存方面，建哥提示后，应优先复制问题。而且每周触发的任务都会稳步复制内存，所以从调度任务的方向更容易调查。在@柳岩的帮助下，我们有能力在试算环境中随时复制问题。

内存问题的调查仍然从堆内存开始。经过多次dump，虽然java过程中的总内存使用量继续增加，但堆内存使用量并没有显著增加。在申请root权限并部署arthas后，通过arthas的dashbord功能，可以清楚地看到堆(heap)和非堆(nonheap)都保持稳定。

arthas dashboard

内存使用有翻倍现象

可以断定是native。 memory的使用量增加，导致整个java应用的内存利用率增加。分析native的第一步是需要jvm打开-XX:NativeMemoryTracking=detail。

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)。例如，截图中的部分描述了Java heap分配8GB内存(以后为了快速复制问题，heap size从20GB调整为8GB)。后缩行代表了内存的具体分配。

间隔2小时，使用jcmd 两次dump后，进行比较。可见Internal这部分，增长明显。Internal是做什么的，为什么会增长？Google发现，这方面的介绍很少，基本上是命令行分析、JVMTI等调用。了解到JVMTI可能与Java后，请教@崔立群 在路由计算中，只有pfinder和java agent是相关的，但不应该只有路由一个影响底层中间件的问题，所以我只是问pfinder研发，没有继续投资跟进。

首先给出这种方法的结论，这种分析不建议优先考虑，因为它包含了相对较大的猜测成分。总体思路是使用pmap输出java过程中分配的所有内存，选择可疑的内存范围，使用gdbdump，编码可视化对其内容进行分析。通过对64MB内存分配块的分析，网上有很多相关博客，从而定位到链接泄漏的案例。所以我也在我们的过程中查了一下，确实包含了很多64MB左右的内存占用。根据博客中的介绍，内存编码后，大部分内容都与JSF有关，可以推断为JSF netty 使用的内存池。我们使用的1.7.JSF版本没有内存池泄漏问题，所以应该与此无关。pmap：https://docs.oracle.com/cd/E56344_01/html/E54075/pmap-1.htmlgdb：https://segmentfault.com/a/1190000024435739

这应该算是一种分析碰运气的方法。思路是使用strace调用输出每个分配内存的系统，然后匹配jstack中线程。从而确定native是由哪个java线程分配的 memory。这种效率最低。首先，系统调用非常频繁，特别是在RPC服务方面。因此，除了明显的内存泄漏外，很容易以这种方式进行调查。如本文内存泄漏缓慢，基本上会被正常调用淹没，难以观察。

经过一系列的尝试，没有根本原因来定位。因此，我们只能从jcmd发现的internal内存增长现象入手。到目前为止，还没有分析内存分配细节的线索。虽然有1.2w行记录，但我们只能再次触摸它，希望能找到与internal相关的线索。

通过以下内容，可以看到32k的分配 在Internal内存空间之后，有两个与JNIHandleBlock相关的内存分配，分别是与4GB和2GB、MemberNameTable相关的调用，分配7GB内存。

[00007fa4a9a - 00007fa4a90000 reserved and committed 32KB for Internal from    [0x0007fa4a97be272] PerfMemory::create_memory_region(unsigned long)+0xaf2    [0x0007fa4a97bcf24] PerfMemory::initialize()+0x44    [0x0007fa4a98c5ead] Threads::create_vm(JavaVMInitArgs*, bool*)+0x1ad    [0x0007fa4a952bde4] JNI_CreateJavaVM+00x74[00007fa4a9de00000 - 00007fa4aa1f000 reserved and committed 260KB for Thread Stack from    [0x0007fa4a98c5ee6] Threads::create_vm(JavaVMInitArgs*, bool*)+0x1e6    [0x0007fa4a952bde4] JNI_CreateJavaVM+0x74    [0x0007fa4a3df45e] JavaMain+0x9edetails:[0x0007fa4a946d1bd] GenericGrowableArray::raw_allocate(int)+0x17d[0007fa4a971b36] MemberNameTable::add_member_name(_jobject*)+0x66[0x0007fa449ae4] InstanceKlass::add_member_name(Handle)+0x84[00007fa4a971cb5d] MethodHandles::init_method_MemberName(Handle, CallInfo&)+0x28d                             (malloc=7036942KB #10.[0007fa4a9568d51] JNIHandleBlock::allocate_handle(oopDesc*)+0x2f1[00007fa4a958db1] JNIHandles::make_weak_global(Handle)+0x41[00007fa4a949a8a] InstanceKlass::add_member_name(Handle)+0x2a[00007fa4a971cb5d] MethodHandles::init_method_MemberName(Handle, CallInfo&)+0x28d                             (malloc=4371507KB #14347509[0x0007fa4a95621a] JNIHandleBlock::allocate_block(Thread*)+0xaa[00007fa4a94e952b] JavaCallWrapper::JavaCallWrapper(methodHandle, Handle, JavaValue*, Thread*)+0x6b[00007fa44ea3f4] JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)+0x84[00007fa449dea1] InstanceKlass::register_finalizer(instanceOopDesc*, Thread*)+0xf1                             (malloc=2626130KB #8619093[0x0007fa48e473] Unsafe_AllocateMemory+0xc3[00007fa496a8988]                             (malloc=239454KB #723[0007fa4a9193d5] ArrayAllocator<unsigned long, (MemoryType)7>::allocate(unsigned long)+0x175[00007fa4a9191cbb] BitMap::resize(unsigned long, bool)+0x6b[00007fa44839] OtherRegionsTable::add_reference(void*, int)+0x1c9[00007fa4a945c4] InstanceKlass::oop_oop_iterate_nv(oopDesc*, FilterOutOfRegionClosure*)+0xb4                             (malloc=157411KB #157411[0x0007fa4a95621a] JNIHandleBlock::allocate_block(Thread*)+0xaa[00007fa4a94e952b] JavaCallWrapper::JavaCallWrapper(methodHandle, Handle, JavaValue*, Thread*)+0x6b[00007fa44ea3f4] JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)+0x84[00007fa4a94eb0d1] JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*)+0x321                             (malloc=140557KB #461314)

JNIHandleBlock相关的内存分配可以通过比较两个时间段的Jcmd输出来看出，确实有持续增长。因此，可以得出JNIHandles的结论::make_weak_global 这部分内存分配导致泄漏。那么这个逻辑在做什么，是什么导致了泄漏呢？

通过谷歌，我们找到了Jvm大神的文章，回答了整个问题的来龙去脉。问题现象与我们基本一致。博客:https://blog.csdn.net/weixin_45583158/article/details/100143231

其中，寒泉子给出了一个复制问题的代码。在我们的代码中，有一段几乎是一样的，它确实包含了运气。

// 代码publicic在博客中 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扫描时间增加，性能下降。

由于jvm 1.8已明确表示，这个问题不会在1.8处理，会在java处理 重构。但是，我们不能在短时间内升级到java 。因此，无法通过直接升级JVM进行修复。因为问题是反射频繁，所以考虑添加缓存来降低频率，从而解决性能下降和内存泄漏的问题。考虑到线程安全，将缓存放在ThreadLocal中，并添加LRU的淘汰规则，以避免再次泄漏。

最终修复效果如下，内存增长控制在正常堆内存设置范围内(8GB)，增长速度温和。重启2天后，JNI Weak Reference时间0.001583秒，符合预期。

Native memory leak的故障排除思路与堆内存故障排除类似，主要以分时dump和对比为主。问题的原因是通过观察异常值或异常增长来确定的。由于工具的差异，Native 在memory的排查过程中，很难将内存泄漏直接与线程相关联，可以通过strace触碰运气。另外，根据有限的线索，在搜索引擎上搜索，可能会发现相关的调查过程，收到意想不到的惊喜。毕竟jvm仍然是一个非常可靠的软件，因此如果存在较严重的问题，应该很容易在网上找到相关的解决方案。如果网上内容少，可能还是需要考虑是否使用了太小的软件依赖。

在开发方面，尽量采用主流的开发设计模式。虽然技术没有好坏之分，但需要限制反射、AOP等实现方法的使用范围。因为这些技术会影响代码的可读性，在不断增加的AOP中，性能会逐渐恶化。此外，在尝试新技术方面，尽量从边缘业务开始。在核心应用程序中，首先要考虑的是稳定性。这种意识可以避免踩到一些别人难以遇到的坑，从而减少不必要的麻烦。

作者：京东物流 陈昊龙

资料来源：京东云开发者社区