小白7码-后端番外篇-记一次Java内存优化的心路历程

660 阅读8分钟

看着眼前这份数据,犹如收到了一份病危通知单,让人如临晴天霹雳,心神震荡不已。大概一个月前,在例行服务巡检过程中,突然看到了下面这份服务进程内存使用情况数据。正是这份数据,让我接下来经历了一段艰难的内存优化旅程。

不是希望的希望

Java的内存优化是一门系统性的学问,需要敏锐的洞察力和冷静的分析判断。通常遇到Java程序内存问题,我们不能简单的通过过去的经验直接定位问题所在。所以我们需要极度的冷静,认真地分析,执着于数据。然而大多的时候我们通常为过去的经验所左右,盲目自信地认定心中的某个猜测。这个看似希望的念头,其实只是自我安慰的欺骗。

正如小白刚开始拿到这份数据时候,虽然惊讶于22.2%RSS内存占用的同时,心里立马有了一个非常笃定的猜测:堆栈内存溢出。因为代号cloud.hfdata的服务进程确实过去在某一时刻出现过内存溢出的问题,根源在于内部一个文件对象构建器被不当调用。正因为如此,小白先入为主地认为一定是堆栈内存溢出搞的鬼,从而忽略了几个关键性的数据特征。

首先开始一套轻车熟路的堆栈内存分析的组合拳:测试环境+ jmap + Memory Analyzer。

内存分析不能直接在产品环境下进行,这应该是基本的操守。所以小白在测试环境下拿到了一份样本:

虽然看上去这份数据没有很多问题,但是实际上这台测试服务器的内存是产品服务器的2倍,所以9.1%的RSS也比较高了。然后通过jmap小白拿到了该样本的内存数据资料,在jdk安装目录bin下运行如下命令:

sudo ./jmap -dump:live,format=b,file=23856.hprof 23856

接下来小白导出内存数据资料到本地电脑上,通过jhat或者Memory Analyzer查看具体的数据报告。小白使用eclipse中的Memory Analyzer插件。通过Memory Analyzer小白拿到了下面这份报告:

                                                           图1 堆内存对象数据

当拿到这份数据的时候,JVM进程堆内存并没有异常峰值,而且23.5MB的内存和719MB+的RSS相去甚远。堆内存很正常,小白就有点蒙圈了,但是小白这时候依然认为堆栈很可疑。就这样折腾了一下午,暴躁的小白的心情可想而知。又是一个天打雷劈的一天。啊啊啊啊。。。。。。

绝望前的一缕曙光

有时候运气也是实力的一部分。当我们没有找到问题的所在的时候,不妨找一面镜子。正当小白为是不是堆栈搞得鬼疑神疑鬼的时候,某一刻突然不由自主的冒出一个念头:我为什么不找一个其他的JVM服务进程比较一下呢?对啊,找一个正常工作的JVM服务进程,看一下它的堆栈情况不就清楚了。说干就干,然后小白就找了代号为cloud.throat的服务进程:

然后继续拿出我们的堆栈分析的组合拳:测试环境+ jmap + Memory Analyzer。同样我们可以拿到一份分析报告:

图2 对照样本堆栈

从图1 和 图2对比来看,两者虽然有细微的差异,但是差异并不大。正是这份报告让小白排除了堆栈的问题。从而让小白的视线重新回归数据本身,去客观地寻找原因。

最后的救命稻草

虽然小白排除了堆栈溢出的嫌疑,但是案情到这里再一次陷入了死胡同。即然一切又回到了原点,那么就让工作回到开始。到这个时候,小白也慢慢冷静下来了。即然需要解决问题,那么首先需要定位问题。即然要定位问题,就需要寻找线索。即然需要线索,那么离不开数据。

得了,还是先收集一下基本的数据吧。虽然前面走了一些弯路,但也不是没有价值的,至少获得了一些数据。既然是解决内存问题,那么首先要了解程序的内存成份。在这里小白不得不安利一下jstat这个工具。jstate是一款JVM的性能统计工具。它能让我们看到JVM内存使用情况,例如新生代,老生代还有永生代(新版中叫做metadata)等。吸取了上面的教训,小白同时收集了cloud.hfdata和cloud.throat的数据:

不可放弃的诊断

在上述数据中,我们可以提取到几个关键性的指标EC,OC以及MC。其中新生代容量EC差异不大。而老生代容量OC虽然有比较大的差异,但是并没有超纲超线。但是MC就不一样了,两者整整差了将近100MB,然后cloud.hfdata和cloud.throat也就相差200MB而已。虽然仅仅相差100MB,但是正常么?小白认为是不正常的。占比24%的metadata占比是非常不健康的。

当然占比并不能完全证明metadata内存问题。所以小白重新部署了cloud.hfdata,同时收集了初始时候的内存占比:

从时间上纵向对比,EC,OC以及MC都有不同程度的增长。从比例上开来,分别增长了45.3%, 820%和148.9%。乍看起来,貌似OC才是大问题。但是千万别忘了,抛开剂量谈比例都是刷流氓。我们再看看分别增加的剂量分别是:82MB,41MB和103MB。

此外有一点我们需要知道EC,OC是会随着程序的运行情况在不停地变动,而metadata通常是不太会剧烈变动的。因为metadata通常用于存储程序代码等静态资源,不太会剧烈大幅度变动。但是MC却有了巨大的增幅,显得极其不正常。最后,小白再采集了cloud.hfdata和cloud.throat多天的内存变化情况:

所以从上面可以看出来,cloud.throat基本保持着6.4%的内存比例,但是cloud.hfdata却有持续地以固定的量增加。另外有点比较重要,其实小白已经对堆栈内存做了约束。如果真的是新生代或者老生代出现内存溢出。那么程序一定会因为堆栈异常而被强制退出。所以小白确定metadata生病了。

元凶的浮出水面

Java程序使用一定的metadata内存是正常的,同时metadata部分内存有增加也是正常。但是如果metadata内存持续大幅度的增加,就是很大的问题了。那么新的问题就来了,是什么导致了metadata的增加呢?

带着这个疑问,小白查询了一些关于metadata的资料。Meta Space元空间,存储metadata数据,是新的JVM用于替代perm(永久代)的替代品。而导致Meta Space元空间内存增加的其中一个原因是过多的反射调用。更准确的来说是,过多地通过classloader加载类。

上面这条原因,让小白感觉到自己即将获得答案。然后小白开始分析cloud.hfdata中是否有使用反射的程序。但是忙活了一大圈,并没有发现什么可疑对象。难道又错了么?

一边继续分析代码,一边继续收集更多关于metadata这方面的资料。随着时间的推移和更多资料的收集,终于一个可以对象就出现在小白的眼里:com.googlecode.aviator.AviatorEvaluator,这是google退出的一个表达式引擎工具,用于文本表达式计算。类似的还有Apache的Exp4计算引擎。

最终来自官方文档的一段话让小白真正确定真凶就是aviator:

                                    图3 来自AviatorScript官方文档

最后的救赎

众多证据都指向aviator这个凶手。并且小白也从官网也获得解决方案:缓存。那么小白就需要对aviator进行重新设计。

首先小白通过测试代码比对确定缓存前后的性能:

public void testCache() throws Exception {
		Date startTime = new Date();
		int count = 100000;
		for(int i = 0;i<count;i++) {
			Expression script = AviatorEvaluator.getInstance().compile("#`v_a`+#`v_b`", true);
			Map<String, Object> env = new HashMap<String, Object>(2);
			env.put("v_a", i);
			env.put("v_b", i+1);
			Object value = script.execute(env);
		}
		System.out.println(String.format("缓存耗时:%d ms", new Date().getTime() - startTime.getTime()));
		System.out.println(String.format("缓存时内存使用情况: %d", Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory()));
	}
	
	public void testNoCache() throws Exception {
		Date startTime = new Date();
		int count = 100000;
		for(int i = 0;i<count;i++) {
			Expression script = AviatorEvaluator.getInstance().compile(String.format("%d+%d", i, i+1));
			Object value = script.execute();
		}
		
		System.out.println(String.format("无缓存耗时:%d ms", new Date().getTime() - startTime.getTime()));
		System.out.println(String.format("无缓存时内存使用情况: %d", Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory()));
	}

                                           图4 Aviator无缓存时耗时和内存

                                              图5 Aviator缓存时耗时和内存

通过上述实验可以看出在100000次Aviator表达式引擎调用情况下,有无缓存会很大程度影响aviator耗时和内存的使用。也从侧面证明aviator无缓存使用是有meta space内存问题的。

总结

最后,小白重新优化了cloud.hfdata的服务程序。虽然经历一段纠结的日子,但是也收获满满。对于Java程序的性能优化也有一些感触:

第一,在定位问题的时候,不要被过去的经验或者经历所左右,要保持客观冷静。

第二,问题的定位一定要以数据为基础,活用统计分析以及对比工具。

第三,熟悉JVM程序内存模型和jmap,jstat, MAT(Memory Analyser Tool)等分析工具

第四,总结过程,形成自己的一套性能优化解决方案。