堆内存泄漏排查-框架

原创 于 2020-12-07 16:36:33 发布 · 657 阅读 · 0 ·
CC 4.0 BY-SA版权
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
文章标签：

#java #oom

本文分析了一个接口服务在新开发两个接口后出现的内存溢出问题。通过对堆内存文件的分析，发现了导致内存泄漏的原因在于一个死循环上报逻辑，以及对象序列化过程中产生的大量转义字符。

摘要生成于 C知道 ，由 DeepSeek-R1 满血版支持， 前往体验 >

堆内存泄漏排查

起因

正在调试接口服务，突然发现控制台出现OOM的异常，这让我有点吃惊。这个服务在线上的内容一直是非常正常的，这次新开发了两个接口就导致OOM了？3G的堆内存就被这两个接口占用了？而且我还只是调用几次，不至于导致OOM啊。除了OOM的错误外还有前不久接的微能力报的错误，错误如下：

Caused by: com.ppdai.infrastructure.radar.biz.common.util.RadarException: 502 error,and message is Bad Gateway,json is

OOM的错误不搞清楚，可不敢上线。于是立即dump出dump文件。发现dump文件确实很大,有2.94G。
与此同时其他同事也反馈微能力报错应用无法启动,报502的也有，报OOM的也有，测试人员也反馈微能力报错导致测试环境的应用挂了。
大概原因知道了，肯定是微能力的锅了。但是一想微能力的服务挂了报502错误能理解，但是为什么会导致接微能力的服务OOM呢？
不查出原因心里不会安心。

排查

掏出堆内存文件分析利器MAT。导入刚才的dump文件。导入时选择Leak Suspects Report，结果立即呈现在眼前。
1
结果如下：

2
3
从上面的结果可以看出内存都是被java.util.concurrent.LinkedBlockingQueue$Node占满了。

  1. Problem Suspect 1：LinkedBlockingQueue被RadarResourceIml（公司微能力的代码）引用占用了49%的内存
    Problem Suspect
    2：LinkedBlockingQueue被com.dianping.cat.message.io.DefaultMessageQueue（CAT打点的代码）引用。
    MAT已经指明了方向，接来下就需要去看下源码了。

Problem Suspect 1 分析

针对Problem Suspect 1，查看RadarResourceIml的源码。从源码RadarResourceIml的构造函数可以看出使用线程池，线程池的workQueue使用了LinkedBlockingQueue刚好与MAT分析的结果一样。

	public RadarResourceIml(IHttpClient httpClient, String url) {
		this.urlsG1.set(Arrays.asList(url.trim().split(",")));
		this.urlsOrigin.get().addAll(this.urlsG1.get());
		this.httpClient = httpClient;
		// this.metricRegistry = IMetric.getMetricRegistry();
		executor = new ThreadPoolExecutor(0, 1, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<Runnable>(500),
				SoaThreadFactory.create("RadarResource", true), new ThreadPoolExecutor.DiscardOldestPolicy());

	}

既然找到与线程池有关，接下来就要看看这个线程在哪里使用的，在当前类里搜executor 可以发现下面的代码段在使用，从方法的字面意思看应该是上报cat使用的。

	public void addCat(CatRequest request) {
		if (request == null) {
			return;
		}
		if (request.getMethod().indexOf("setMethod") != -1)
			return;
		executor.submit(new Runnable() {
			@Override
			public void run() {
			  //public static final String TOOLPRE="/api/client/tool";
				String url = RadarConstanst.TOOLPRE + "/addCat";
				try {
					post(url, request, CatResponse.class);
				} catch (Exception e) {
					// TODO: handle exception
				}
			}
		});

	}

关于ThreadPoolExecutor的参数以及原理已经有很多资料了，这里就不赘述了。
但是创建ThreadPoolExecutor线程池的时候workQueue LinkedBlockingQueue的大小设置的是500，且使用了DiscardOldestPolicy抛弃旧任务的策略。即使需要上报的消息很多超过了处理能力，最多在内存里也只会有500个任务积压啊，按道理说不应该导致OOM啊。到这里无法继续分析了，需要再去MAT上进一步分析。

4
List objects->with outgoing references查看我(当前对象)引用了哪些对象
图片5
从上面可以看出是com.ppdai.infrastructure.radar.biz.dto.client.CatRequest对象占用了近145M的空间，而LinkedBlockingQueue的next节点里还有近298M的对象。仅这里就占了400多M的空间。CatRequest这对象为什么这么大呢，进一步分析
图片6
从上面可以看出CatRequest对象的msg字段和json字段占的空间几乎一样，都占用了很多空间。

public class BaseRequest {
    @ApiModelProperty(value ="语言")
	private String lan;
    @ApiModelProperty(value ="客户端版本")
	private String sdkVersion;
    @ApiModelProperty(value ="客户端ip")
	private String clientIp = IPUtil.getLocalIP();
	public BaseRequest(){
		lan="java";
		sdkVersion=PropUtil.getSdkVersion();
	}
	//省略getter setter
}
public class CatRequest extends BaseRequest {
	private String method;
	private String json;
	private String msg;
	//省略getter setter
}

查看addCat方法的Call Hierarchy
图片7
通过上面的查找结果猜测route()方法应该是微能力路由应用的请求使用
route()的部分代码如下

if (last == null||(last!=null&&System.currentTimeMillis()-last>30*60*1000)) {
 //代码没有对CatRequest对象设置字段json的值
                    CatRequest catRequest = new CatRequest();
                    catRequest.setMethod(method);
                    catRequest.setMsg("RadarSub:" + RadarConfig.getRadarZKSubFlag() + ", ZkRg:" + RadarConfig.getZkRegistFlag() + ",Sofa:" + Util.isSofa());
                    RadarClient.getContext().getRadarClient().addCat(catRequest);
                    catLog.put(method,System.currentTimeMillis());
                }

通过上面代码发现这里没有对CatRequest对象设置字段json的值。
而下面的addErrorCat()方法里设置了json字段的值。

	private void addErrorCat(Exception e, Object request, String api, String url) {
		try {
			CatRequest request2 = new CatRequest();
			request2.setJson("url is " + url + "," + JsonUtil.toJson(request));
			request2.setMethod(api);
			request2.setMsg(e.getMessage());
			addCat(request2);
		} catch (Exception ee) {
			// TODO: handle exception
		}

	}

从上面的分析结果看应该是执行addErrorCat方法造成的。接下来看看什么情况下执行addErrorCat方法。
通过代码查找发现是调用RadarResourceIml.post方法里的try…catch…里跑异常时会调用。那就是在执行httpClient.post()方法失败时就会调用。

private <T extends BaseResponse> T post(String api, Object request, Class<T> class1) throws Exception {
		T response = null;
       //省略部分代码
		String host = null;
		String url = null;
		try {
			host = getRegistryUrl();
			url = host + api;
			response = httpClient.post(url, request, class1);
		} catch (IOException e) {
		 //省略部分代码
			addErrorCat(e, request, api, url);
			}
			throw e;
		} catch (Exception e) {
      //省略部分代码
			addErrorCat(e, request, api, url);
			throw new IOException("failed to post " + url + ", request: " + JsonUtil.toJsonNull(request) + ", error: "
					+ e.getMessage(), e);
		} finally {
			 //省略部分代码
		}
		 //省略部分代码
		return response;
	}

从上面的代码可以得出httpClient.post()抛异常时，会用post请求的内容Object request参数填充CatRequest 的字段json的值，用Exception 的Message内容填充msg的值。但是为什么这个http请求的参数request怎么会这么大呢?
还得分析CatRequest字段json的内容。
从弹出的列表里选择Copy->Save Value To File 把内容导出到文件里，因为内容比较大直接copy value的话可能会失败。
图片8
145M的文件用Notepad++打开，Notepad++直接挂了。用记事本打开，发现里面出现了非常多的“\”字符。即使request2.setJson("url is " + url + “,” + JsonUtil.toJson(request));把对象http请求的Object request参数转换json也不会出现这么多的“\”字符啊。比较费解。
图片9
通过上面的文件里发现有如下内容
RadarException:413 error,and message is Request Entity Too Large
url is http://fat-radar1.xxxx.com/api/client/tool/addCat
推断应该是post方法里response = httpClient.post(url, request, class1);
请求 http://fat-radar1.xxxx.com/api/client/tool/addCat失败了。
突然灵光乍现，应该是这样一个流程
addErrorCat()->addCat()->post()->addErrorCat()
没错就是你想的那样，死循环！！！，一直报错，一直被catch，一直被post。而post请求的Object request就是CatRequest对象。而当时微能力http://fat-radar1.xxxx.com服务正好挂了。
还是存在如下疑点
通过前面的分析线程池的工作队列大小是500，但是这个循环请求失败导致

  1. 一直上报radar服务，最多也就500个任务在线程里堆积，500个任务不至于占用这么大内存啊
    前面也看到一个任务里的CatRequest的json值达到了145M，怎么来的呢？，里面的“\”字符哪里来的？
    突然想起以前在做JSON.toJSONString(Object object)转换字符串时，如果object本身是对象转换后字符串，里面带引号的，再次JSON.toJSONString后就会出现“\”的转义符合。想到这里感觉真相已经快要浮出水面了。
    再来看下addErrorCat方法的代码
	private void addErrorCat(Exception e, Object request, String api, String url) {
		try {
			CatRequest request2 = new CatRequest();
			request2.setJson("url is " + url + "," + JsonUtil.toJson(request));
			request2.setMethod(api);
			request2.setMsg(e.getMessage());
			addCat(request2);
		} catch (Exception ee) {
			// TODO: handle exception
		}

	}

第一次报错时，request2.setJson("url is " + url + “,” + JsonUtil.toJson(request))把request转换为json字符串了，里面是代码引号的，这时候请求post失败，再一次把带引号的字符串再次toJson就会出现转义字符“\”，因为前面分析了http://fat-radar1.xxxx.com服务挂了会有出现死循环，那么就会导致后面的请求不断的在前面的字符串上做toJson就会导致这个Object request不断的增大，一直到145M，甚至可能会更大。
为了验证猜想，就把用代码了的JsonUtil.toJson进行了如下的实验：

 @Test
    public void shouldAnswerWithTrue()
    {
        Map <String,String>map=new HashMap();
        map.put("key","value");
        String s=JsonUtil.toJson(map);
        System.out.println(s);
        System.out.println("-------------分隔--------------");
        for (int i=0;i<4;i++){
            s=JsonUtil.toJson(s);
        }
        System.out.println(s);
    }

结果

{"key":"value"}
-------------分隔--------------
"\"\\\"\\\\\\\"{\\\\\\\\\\\\\\\"key\\\\\\\\\\\\\\\":\\\\\\\\\\\\\\\"value\\\\\\\\\\\\\\\"}\\\\\\\"\\\"\""

从这个测试结果可以说明一切了。

Problem Suspect 1 的结论：

微能力的一个上报消息服务http://fat-radar1.xxxx.com挂了，而代码里上报消息的逻辑有问题导致上报消息一直死循环上报，导致不断在第一次对象json序列化后的字符串上继续进行json序列化，进而转义字符“\”每次循环中不断的增长，这样就会有很多post请求的CatRequest的json字段的值增长到145M。这还是其中某一个请求，还有很多请求也是同样的情况。前面看到的字符串里有413 error以及Request Entity Too Large信息就不奇怪了。肯定是请求内容过大导致的。

Problem Suspect 2 分析

同样的分析方法，可以发现CAT上报的内容更前面分析的内容查不多，都是相同的字符串导致的。
图片10
这样的现象可以猜想是对post请求进行CAT打点导致，进一步查看post方法的httpClient实例是用com.xxxx.infrastructure.radar.biz.common.util.RdHttpClient实例化来的。

public <T> T post(String url, Object request, Class<T> class1) throws IOException, RadarException {
		return post(url, null, request, class1);
	}
	
	public <T> T post(String url, Map<String, String> header, Object reqObj, Class<T> class1)
			throws IOException, RadarException {
		String json = "";
		if (reqObj != null) {
			if (!(reqObj instanceof String)) {
				json = JsonUtil.toJsonNull(reqObj);
			} else {
				json = (String) reqObj;
			}
		}
		Response response = null;
		Transaction transaction = Tracer.newTransaction("rd-http", url);
		try {
			RequestBody body = RequestBody.create(JSONTYPE, json);
			Request.Builder requestbuilder = new Request.Builder().url(url).post(body);
			if (header != null) {
				header.entrySet().forEach(t1 -> {
					requestbuilder.addHeader(t1.getKey(), t1.getValue());
				});
			}
			requestbuilder.addHeader("radar_flag", "1");
			CatContext catContext = Tracer.logRemoteCallClient();
			if (catContext != null) {
				addCat(requestbuilder,catContext);
			}
			Request request = requestbuilder.build();
			response = client.newCall(request).execute();
			transaction.setStatus(Transaction.SUCCESS);
			if (response.isSuccessful()) {
				if (class1 == String.class) {
					return (T) (response.body().string());
				} else {
					return JsonUtil.parseJson(response.body().string(), class1);
				}
			} else {
				RadarException exception = new RadarException(
						response.code() + " error,and message is " + response.message() + ",json is " + json);
				throw exception;
			}
		} catch (Exception e) {
			transaction.setStatus(new RdException(e));
			throw e;
		} finally {
			transaction.complete();
			try {
				if (response != null) {
					response.close();
				}
			} catch (Exception e) {

			}
		}
	}

从代码不难发现，代码印证了我的猜想是正确的。

Problem Suspect 2 的结论：

代码里对post请求的成功失败进行CAT打点拦截，大对象请求的内容同样也在CAT打点里复杂一份，导致CAT里也占用了几乎相同的内存。
这一点也可以从第一张图的内存占用情况可以证明。

解决办法

错误上报方法里addErrorCat的post请求应该使用单独方法，不应该使用被try…catch…，且catch的逻辑还是调用addErrorCat()方法。

渡舟人
关注
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值