一次Java内存泄漏调试的有趣经历 - JAVA - 编程开发
设为首页 加入收藏

TOP

一次Java内存泄漏调试的有趣经历(一)
2018-08-31 18:27:08 】 浏览:28
Tags:一次 Java 内存 泄漏 调试 有趣 经历

人人都会犯错,但一些错误是如此的荒谬,我想不通怎么会有人犯这种错误。更没想到的是,这种事竟发生在了我们身上。当然,这种东西只有事后才能发现真相。接下来,我将讲述一系列最近在我们一个应用上犯过的这种错误。最有意思的是,一开始的迹象揭示的问题,与实际发生的问题完全不同。

在一个凄凉的午夜

午夜刚过,我就被一条来自监控系统的警报吵醒了。Adventory,我们的 PPC (以点击次数收费)广告系统中一个负责索引广告的应用,很明显连续重启了好几次。在云端的环境里,实例的重启是很正常的,也不会触发报警,但这次实例重启的次数在短时间内超过了阈值。我打开了笔记本电脑,一头扎进项目的日志里。

一定是网络的问题

我看到服务在连接 ZooKeeper 时发生了数次超时。我们使用 ZooKeeper(ZK)协调多个实例间的索引操作,并依赖它实现鲁棒性。很显然,一次 Zookeeper 失败会阻止索引操作的继续运行,不过它应该不会导致整个系统挂掉。而且,这种情况非常罕见(这是我第一次遇到 ZK 在生产环境挂掉),我觉得这个问题可能不太容易搞定。于是我把 ZooKeeper 的值班人员喊醒了,让他们看看发生了什么。

同时,我检查了我们的配置,发现 ZooKeeper 连接的超时时间是秒级的。很明显,ZooKeeper 全挂了,由于其他服务也在使用它,这意味着问题非常严重。我给其他几个团队发了消息,他们显然还不知道这事儿。

ZooKeeper 团队的同事回复我了,在他看来,系统运行一切正常。由于其他用户看起来没有受到影响,我慢慢意识到不是 ZooKeeper 的问题。日志里明显是网络超时,于是我把负责网络的同事叫醒了。

负责网络的团队检查了他们的监控,没有发现任何异常。由于单个网段,甚至单个节点,都有可能和剩余的其他节点断开连接,他们检查了我们系统实例所在的几台机器,没有发现异常。其间,我尝试了其他几种思路,不过都行不通,我也到了自己智力的极限。时间已经很晚了(或者说很早了),同时,跟我的尝试没有任何关系,重启变得不那么频繁了。由于这个服务仅仅负责数据的刷新,并不会影响到数据的可用性,我们决定把问题放到上午再说。

一定是 GC 的问题

有时候把难题放一放,睡一觉,等脑子清醒了再去解决是一个好主意。没人知道当时发生了什么,服务表现的非常怪异。突然间,我想到了什么。Java 服务表现怪异的主要根源是什么?当然是垃圾回收。

为了应对目前这种情况的发生,我们一直打印着 GC 的日志。我马上把 GC 日志下载了下来,然后打开 Censum开始分析日志。我还没仔细看,就发现了一个恐怖的情况:每15分钟发生一次 full GC,每次 GC 引发长达 20 秒的服务停顿。怪不得连接 ZooKeeper 超时了,即使 ZooKeeper 和网络都没有问题。

这些停顿也解释了为什么整个服务一直是死掉的,而不是超时之后只打一条错误日志。我们的服务运行在 Marathon 上,它定时检查每个实例的健康状态,如果某个端点在一段时间内没有响应,Marathon 就重启那个服务。

 

知道原因之后,问题就解决一半了,因此我相信这个问题很快就能解决。为了解释后面的推理,我需要说明一下 Adventory 是如何工作的,它不像你们那种标准的微服务。

Adventory 是用来把我们的广告索引到 ElasticSearch (ES) 的。这需要两个步骤。第一步是获取所需的数据。到目前为止,这个服务从其他几个系统中接收通过 Hermes 发来的事件。数据保存到 MongoDB 集群中。数据量最多每秒几百个请求,每个操作都特别轻量,因此即便触发一些内存的回收,也耗费不了多少资源。第二步就是数据的索引。这个操作定时执行(大概两分钟执行一次),把所有 MongoDB 集群存储的数据通过 RxJava 收集到一个流中,组合为非范式的记录,发送给 ElasticSearch。这部分操作类似离线的批处理任务,而不是一个服务。

由于经常需要对数据做大量的更新,维护索引就不太值得,所以每执行一次定时任务,整个索引都会重建一次。这意味着一整块数据都要经过这个系统,从而引发大量的内存回收。尽管使用了流的方式,我们也被迫把堆加到了 12 GB 这么大。由于堆是如此巨大(而且目前被全力支持),我们的 GC 选择了 G1。

我以前处理过的服务中,也会回收大量生命周期很短的对象。有了那些经验,我同时增加了 -XX:G1NewSizePercent 和 -XX:G1MaxNewSizePercent 的默认值,这样新生代会变得更大,young GC 就可以处理更多的数据,而不用把它们送到老年代。Censum 也显示有很多过早提升。这和一段时间之后发生的 full GC 也是一致的。不幸的是,这些设置没有起到任何作用。

接下来我想,或许生产者制造数据太快了,消费者来不及消费,导致这些记录在它们被处理前就被回收了。我尝试减小生产数据的线程数量,降低数据产生的速度,同时保持消费者发送给 ES 的数据池大小不变。这主要是使用背压(backpressure)机制,不过它也没有起到作用。

一定是内存泄漏

这时,一个当时头脑还保持冷静的同事,建议我们应该做一开始就做的事情:检查堆中的数据。我们准备了一个开发环境的实例,拥有和线上实例相同的数据量,堆的大小也大致相同。把它连接到 jnisualvm ,分析内存的样本,我们可以看到堆中对象的大致数量和大小。大眼一看,可以发现我们域中Ad对象的数量高的不正常,并且在索引的过程中一直在增长,一直增长到我们处理的广告的数量级别。但是……这不应该啊。毕竟,我们通过 RX 把这些数据整理成流,就是为了防止把所有的数据都加载到内存里。

 

随着怀疑越来越强,我检查了这部分代码。它们是两年前写的,之后就没有再被仔细的检查过。果不其然,我们实际上把所有的数据都加载到了内存里。这当然不是故意的。由于当时对 RxJava 的理解不够全面,我们想让代码以一种特殊的方式并行运行。为了从 RX 的主工作流中剥离出来一些工作,我们决定用一个单独的 executor 跑 CompetableFuture。但是,我们因此就需要等待所有的 CompetableFuture 都工作完……通过存储他们的引用,然后调用 join()。这导致一直到索引完成,所有的 future 的引用,以及它们引用到的数据,都保持着生存的状态。这阻止了垃圾收集器及时的把它们清理掉。

真有这么糟糕吗?

当然这是一个很愚蠢的错误,对于发现得这么晚,我们也很恶心。我甚至想起很久之前,关于这个应用需要 12 GB 的堆的问题,曾有个简短的讨论。12 GB 的堆,确实有点大了。但是另一方面,这些代码已经运行了将近两年了,没有发生过任何问题。我们可以在当时相对容易的修复它,然而如果是两年前,这可能需要我们花费更多的时间,而且相对于节省几个 G 的内存,当时我们有很多更重要的工作。
编程开发网

首页 上一页 1 2 下一页 尾页 1/2/2
】【打印繁体】【投稿】【收藏】 【推荐】【举报】【评论】 【关闭】 【返回顶部
上一篇Map大家族的那点事儿(2) :Abstra.. 下一篇Java异常处理的9个最佳实践

评论

帐  号: 密码: (新用户注册)
验 证 码:
表  情:
内  容:

最新文章

热门文章

C 语言

C++基础

windows编程基础

linux编程基础

C/C++面试题目