使用dubbo进行消费者端调用导致内存溢出问题排查
程序员文章站
2022-05-11 15:24:57
...
公司某流程系统项目组出现内存溢出问题，场景是使用dubbo进行文件传输。首先，dubbo协议不适合进行文件传输，这个做法本身有问题，该项目组可能出于开发效率，历史原因等情况，使用了这样的技术方案。
发生内存溢出的场景是 测试人员连续的上传一个144M大小的文件，在上传四五次后，出现内存溢出。web接收文件，通过dubbo传输给service端进行文件处理。web和service端设置堆内存都是1g。在没有并发的情况下，连续上传144M的文件不应该出现内存溢出。初步怀疑是发生的内存泄露导致文件占用的内存没有被回收。
把项目组的代码down下来本地运行系统对场景进行复现。
设置相关JVM参数便于观察现象和保留现场：
-XX:+PrintGCDetails -Xmx1024m -Xms1024m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:/heapdump.hprof
本地在连续上传五次这个144M的文件后，也出现了内存溢出。
java.lang.OutOfMemoryError: Java heap space at java.util.Arrays.copyOf(Arrays.java:3236) at java.io.ByteArrayOutputStream.grow(ByteArrayOutputStream.java:113) at java.io.ByteArrayOutputStream.ensureCapacity(ByteArrayOutputStream.java:93) at java.io.ByteArrayOutputStream.write(ByteArrayOutputStream.java:140) at org.springframework.util.StreamUtils.copy(StreamUtils.java:128) at org.springframework.util.FileCopyUtils.copy(FileCopyUtils.java:109) at org.springframework.util.FileCopyUtils.copyToByteArray(FileCopyUtils.java:156) at org.springframework.web.multipart.support.StandardMultipartHttpServletRequest$StandardMultipartFile.getBytes(StandardMultipartHttpServletRequest.java:291) at com.gforc.biz.controller.FileController.uploadFile(FileController.java:526) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:483) at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:114) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
可以看到，web容器使用的是undertow，undertow在接受http请求时，是先把http请求内容存放在直接内存中，在需要读取http的formdata内容时，对于非文件内容，直接复制到堆内存中，对于文件内容，则以nio的方式把文件信息从直接内存拷贝到临时文件中，整个过程，堆内存都没有申请文件大小的内存空间。
在controller层调用springmvc的MultipartFile的file.getBytes()时，申请了一个文件大小的字节数组内存空间来存放文件流信息，此时内存不足，导致内存溢出。
再观察GC日志：
[GC (Allocation Failure) --[PSYoungGen: 280566K->280566K(316928K)] 733103K->733103K(1016320K), 0.0048276 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] [Full GC (Ergonomics) [PSYoungGen: 280566K->0K(316928K)] [ParOldGen: 452537K->329663K(699392K)] 733103K->329663K(1016320K), [Metaspace: 52711K->52711K(1097728K)], 0.0958676 secs] [Times: user=0.16 sys=0.00, real=0.10 secs] [GC (Allocation Failure) [PSYoungGen: 249872K->32K(286208K)] 841679K->591839K(985600K), 0.0033714 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] [GC (Allocation Failure) [PSYoungGen: 254214K->220K(315904K)] 846021K->624795K(1015296K), 0.0139206 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] [Full GC (Ergonomics) [PSYoungGen: 220K->0K(315904K)] [ParOldGen: 624575K->354325K(699392K)] 624795K->354325K(1015296K), [Metaspace: 52764K->52764K(1097728K)], 0.1000608 secs] [Times: user=0.19 sys=0.00, real=0.10 secs] [Full GC (Ergonomics) [PSYoungGen: 197604K->0K(315904K)] [ParOldGen: 616469K->583688K(699392K)] 814074K->583688K(1015296K), [Metaspace: 52764K->52764K(1097728K)], 0.1123836 secs] [Times: user=0.25 sys=0.00, real=0.11 secs] [GC (Allocation Failure) --[PSYoungGen: 280208K->280208K(315904K)] 863896K->929432K(1015296K), 0.0161663 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] [Full GC (Ergonomics) [PSYoungGen: 280208K->0K(315904K)] [ParOldGen: 649224K->535404K(699392K)] 929432K->535404K(1015296K), [Metaspace: 52764K->52764K(1097728K)], 0.1258771 secs] [Times: user=0.33 sys=0.00, real=0.13 secs] [GC (Allocation Failure) [PSYoungGen: 131074K->32K(316416K)] 666479K->666508K(1015808K), 0.0250249 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] [Full GC (Ergonomics) [PSYoungGen: 32K->0K(316416K)] [ParOldGen: 666476K->600940K(699392K)] 666508K->600940K(1015808K), [Metaspace: 52764K->52764K(1097728K)], 0.1091046 secs] [Times: user=0.22 sys=0.00, real=0.11 secs] [Full GC (Ergonomics) [PSYoungGen: 280433K->0K(316416K)] [ParOldGen: 600940K->478067K(699392K)] 881374K->478067K(1015808K), [Metaspace: 52765K->52765K(1097728K)], 0.1074561 secs] [Times: user=0.17 sys=0.00, real=0.11 secs] [GC (Allocation Failure) --[PSYoungGen: 250120K->250120K(316416K)] 728188K->859260K(1015808K), 0.0216361 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] [Full GC (Ergonomics) [PSYoungGen: 250120K->0K(316416K)] [ParOldGen: 609139K->600946K(699392K)] 859260K->600946K(1015808K), [Metaspace: 52765K->52765K(1097728K)], 0.1163858 secs] [Times: user=0.30 sys=0.00, real=0.12 secs] [Full GC (Ergonomics) [PSYoungGen: 262146K->262144K(316416K)] [ParOldGen: 600946K->469724K(699392K)] 863092K->731868K(1015808K), [Metaspace: 52765K->52765K(1097728K)], 0.2965119 secs] [Times: user=0.92 sys=0.00, real=0.30 secs] [Full GC (Ergonomics) [PSYoungGen: 283648K->0K(316416K)] [ParOldGen: 618040K->469741K(699392K)] 901688K->469741K(1015808K), [Metaspace: 52786K->52786K(1097728K)], 0.1205818 secs] [Times: user=0.23 sys=0.00, real=0.12 secs] [GC (Allocation Failure) [PSYoungGen: 279648K->128K(316928K)] 749390K->600942K(1016320K), 0.0325090 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] [Full GC (Ergonomics) [PSYoungGen: 128K->0K(316928K)] [ParOldGen: 600814K->600782K(699392K)] 600942K->600782K(1016320K), [Metaspace: 52788K->52788K(1097728K)], 0.2549737 secs] [Times: user=0.81 sys=0.00, real=0.25 secs] [Full GC (Ergonomics) [PSYoungGen: 262149K->262144K(316928K)] [ParOldGen: 600782K->467200K(699392K)] 862931K->729344K(1016320K), [Metaspace: 52788K->52598K(1097728K)], 0.2826828 secs] [Times: user=0.70 sys=0.00, real=0.28 secs] [Full GC (Ergonomics) [PSYoungGen: 278623K->0K(316928K)] [ParOldGen: 615516K->622978K(699392K)] 894139K->622978K(1016320K), [Metaspace: 52598K->52562K(1097728K)], 0.3579903 secs] [Times: user=0.98 sys=0.00, real=0.36 secs] [Full GC (Ergonomics) [PSYoungGen: 248317K->131072K(316928K)] [ParOldGen: 622978K->614786K(699392K)] 871295K->745858K(1016320K), [Metaspace: 52562K->52562K(1097728K)], 0.1744845 secs] [Times: user=0.44 sys=0.00, real=0.17 secs] [Full GC (Allocation Failure) [PSYoungGen: 131072K->131072K(316928K)] [ParOldGen: 614786K->614707K(699392K)] 745858K->745779K(1016320K), [Metaspace: 52562K->52460K(1097728K)], 0.3197632 secs] [Times: user=0.92 sys=0.02, real=0.32 secs] java.lang.OutOfMemoryError: Java heap space Dumping heap to D:/heapdump.hprof ...
通过GC日志可以发现，最后一个fullGC，老年代申请不到空间，导致了内存溢出。日志前面是新生代申请不到内存，触发fullGC,并把新生代存活的对象转移到老年代，老年代的存活对象不断增加，最终老年代内存不足。
按道理，我连续的上传文件，在上传第二个文件时，第一个文件在堆内存的对象应该可以被JVM回收才对。可以发现，实际上JVM并没有办法回收文件对象。初步判定发生了内存泄漏。
利用jdk自带的visualVM对内存溢出时保存的堆内存对象进行查看，
可以看到字节数组对象占了96.5%的内存。
可以看出来此时堆内存中的四个大小为151876120的对象就是我们上传的文件
可以看出来，因为内存中的这四个文件对应的字节数组大内存对象没有被垃圾回收，导致内存溢出的发生。
再看字节数组存在的引用，
可以看出来，字节数组作为RPC接口的参数，被rpcContext的arguments属性和rpcInvocation的arguments属性引用，导致了字节数组无法被gc回收。可以看到，rpcContext被线程变量threadLocal引用。稍微熟悉dubbo的应该都清楚。rpcContext作为dubbo在rpc传输的上下文，经常被用来在dubbo消费者端和服务端之间通过线程变量，隐性的传递一些参数。
由于使用dubbo的版本为2.5.7，翻阅dubbo源码，很快就看到dubbo自带的消费者端过滤器ConsumerContextFilter的代码：
/**
* ConsumerContextInvokerFilter
*
* @author william.liangf
*/
@Activate(group = Constants.CONSUMER, order = -10000)
public class ConsumerContextFilter implements Filter {
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
RpcContext.getContext()
.setInvoker(invoker)
.setInvocation(invocation)
.setLocalAddress(NetUtils.getLocalHost(), 0)
.setRemoteAddress(invoker.getUrl().getHost(),
invoker.getUrl().getPort());
if (invocation instanceof RpcInvocation) {
((RpcInvocation) invocation).setInvoker(invoker);
}
try {
return invoker.invoke(invocation);
} finally {
RpcContext.getContext().clearAttachments();
}
}
}
RpcContext代码：
public RpcContext setInvocation(Invocation invocation) {
this.invocation = invocation;
if (invocation != null) {
setMethodName(invocation.getMethodName());
setParameterTypes(invocation.getParameterTypes());
setArguments(invocation.getArguments());
}
return this;
}
通过上面代码可以看出，dubbo在每次消费者端调用服务端时，会把rpc调用的方法，参数等信息通过线程变量的方式记录下来，但在rpc调用完，只清除了rpcContext中的attachment属性。导致线程一直持有rpc调用传参的引用。
在线程再次进行rpc调用时，线程变量会引用新的rpc调用的传参，旧的rpc调用传参就可被回收。由于dubbo本身使用于小数据量的传输，所以这种轻微的内存泄漏，在普通业务调用中并不会暴露出问题，但是在用来做文件传输时，特别是大文件传输时，问题就暴露出来了。 可以说，这是dubbo的一个bug，查看了github上dubbo的最新源码，发现该问题已被修复。在2019年5月23日提交的dubbo2.7.2版本代码中修复了该问题。dubbo2.7.2版本中ConsumerContextFilter代码：
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
RpcContext.getContext()
.setInvoker(invoker)
.setInvocation(invocation)
.setLocalAddress(NetUtils.getLocalHost(), 0)
.setRemoteAddress(invoker.getUrl().getHost(),
invoker.getUrl().getPort());
if (invocation instanceof RpcInvocation) {
((RpcInvocation) invocation).setInvoker(invoker);
}
try {
RpcContext.removeServerContext();
return invoker.invoke(invocation);
} finally {
RpcContext.removeContext();
}
}
可以看到，在代码的finally代码块中，把整个rpcContext清除了。即修复了该问题。
内存泄漏的问题定位已经非常明确，要解决这个问题也显得很简单了。考虑升级dubbo框架可能会引入不必要的风险，针对该问题，我添加了一个dubbo过滤器RemoveRpcContextFilter，用于解决该问题。
package com.xxx.framework;
import com.alibaba.dubbo.common.Constants;
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.*;
/**
* dubbo消费服务后移除线程变量
* dubbo当前2.5.7版本ConsumerContextFilter中通过RpcContext以线程变量的方式引用接口中的参数对象,且没有移除线程变量，导致参数无法被GC，
* 只能在线程下次执行dubbo调用时线程变量指向新的参数对象的方式，让旧参数对象进行垃圾回收。这里手动清除线程变量，helpGC
* dubbo适用于小数据传输，线程变量引用部分旧请求参数对象影响不大，该问题在dubbo 2019.5.23提交的2.7.2版本已修复。
* Created by cd_huang on 2019/6/4.
*/
@Activate(group = Constants.CONSUMER, order = -10001)
public class RemoveRpcContextFilter implements Filter {
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
try {
return invoker.invoke(invocation);
} finally {
RpcContext.removeContext();
}
}
}
然后在resouce目录下META-INF/dubbo目录下新建com.alibaba.dubbo.rpc.Filter文件，内容为
RemoveRpcContextFilter=com.xxx.framework.RemoveRpcContextFilter即以dubbo的SPI机制注入该过滤器，使其生效。
本地验证后提交到测试，测试人员验证通过，即解决该问题。
使用dubbo进行文件传输这种做法本身就是有问题的。dubbo协议默认采用单一长连接进行NIO传输。在传输大文件网络传输过程，对导致该消费者端和服务端网络阻塞。dubbo配置使用多个连接可以一定程度上规避该问题。
考虑到管理类流程类系统本身用量不大，基本不存在并发，以快速实现业务功能为主，暂时使用dubbo进行大文件传输，后续考虑其他方案。
