一次 Java 内存泄漏排查过程,涨姿势

作者:yizhe
出处:http://www.importnew.com/29591.html

人人都会犯错,但一些过错是如此的荒唐,我想不通怎样会有人犯这种过错。更没想到的是,这种事竟发作在了咱们身上。当然,这种东西只需过后才干发现本相。接下来,我将叙述一系列最近在咱们一个运用上犯过的这种过错。最有意思的是,一开端的痕迹提醒的问题,与实践发作的问题彻底不同。

在一个苍凉的午夜

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

一定是网络的问题

我看到服务在衔接 ZooKeeper 时发作了数次超时。咱们运用 ZooKeeper(ZK)和谐多个实例间的索引操作,并依靠它完结鲁棒性。很显着,一次 Zookeeper 失利会阻挠索引操作的持续运转,不过它应该不会导致整个体系挂掉。并且,这种状况十分稀有(这是我榜首次标签14遇到 ZK 在出产环境挂掉),我觉得这一次 Java 内存走漏排查进程,涨姿态个问题或许不太简略搞定。所以我把 ZooKeeper 的值班人员喊醒了,让他们看看发作了什么。

一起,我查看了咱们的装备,发现 ZooKeeper 衔接的超时时刻是秒级的。很显着,ZooKeeper 全挂了,因为其他服务也在运用它,这意味着问题十分严峻。我给其他几个团队发了音讯,他们显着还不知道这事儿。

ZooKeeper 团队的搭档回复我了,在他看来,体系运转一切正常。因为其他用户看起来没有受到影响,我渐渐认识到不是 ZooKeeper 的问题。日志里显着是网络超时,所以我把担任网络的搭档叫醒了。

担任网络的团队查看了他们的监控,没有发现任何反常。因为单个网段,乃至单个节点,都有或许和剩下的其他节点断开衔接,他们查看了咱们体系实例地点的几台机器,没有发现反常。其间,我测验了其他几种思路,不过都行不通,我也到了自一次 Java 内存走漏排查进程,涨姿态己智力的极限。时刻现已很晚了(或许说很早了),一起,跟我的测验没有任何关系,重启变得不那么频频了。因为这个服务只是担任数据的改写,并不会影响到数据的可用性,咱们决议把问题放到上午再说。

一定是 GC 的问题

有时分把难题放一放,睡一觉,等脑子清醒了再去处理是一个好主意。没人知道其时发作了什么,服务体现的十分奇怪。突然间,我想到了什么。Java 服务体现奇怪的首要本源是什么?当然是废物收回。

为了应对现在这种状况的发作,咱们一向打印着 GC 的标签11日志。我立刻把 GC 日志下载了下来,然后翻开 Censum开端剖析日志。我还没细心看,就发现了一个恐惧的状况:每15分钟发作一次 full GC,每次标签19 GC 引发长达 20 秒的服务中止。怪不得衔接 ZooKeeper 超时了,即便 ZooKeeper 和网络都没有问题。

这些中止也解说了为什么整个服务一向是死掉的,而不是超时之后只打一条过错日志。咱们的服务运转在 Marathon 上,它守时查看每个实例的健康状况,假如某个端点在一段时刻内没有呼应,Marathon 就重启那个服务。

知道原因之后,问题就处理一半了,因而我信任这个问题很快就能处理。为了解说后边的推理,我需求阐明一下 Adventory 是怎么作业的,它不像你们那种规范的微服务。

Adventory 是用来把咱们的广告索引到 ElasticSearch (ES) 的。这需求两个进程。榜首步是获取所需的数据。到现在为止,这个服务从其他几个体系中接纳经过 Hermes 发来的作业。数据保存到 MongoDB 集群中。数据量最多每秒几百个恳求,每个操作都特别轻量,因而即便触发一些内存的收回,也消耗不了多少资源。第二步便是数据的索引。这个操作守时履行(大约两分钟履行一次),把一切 MongoDB 集群存储的数据经过 RxJava 搜集到一个流中,组合为非范式的记载,发送给 ElasticSearch。这部分操作相似离线的批处理使命,而不是一个服务。

因为常常需求对数据做许多的更新,保护索引就不太值得,所以每履行一次守时使命,整个索引都会重建一次。这意味着一整块数据都要经过这个体系标签19,然后引发许多的内存收回。虽然运用了流的方法,咱们也被逼把一次 Java 内存走漏排查进程,涨姿态堆加到了 12 GB 这么大。因为堆是如此巨大(并且现在标签5被全力支撑),咱们的 GC 挑选了 G1。

我曾经处理过的服务中,也会收回许多生命周期很短的目标。有了那些经历,我一起添加了 -XX:G1NewSizePercent标签19 和 -XX:G1MaxNewSizePercent 的默许值,这样新生代会变得更大,young GC 就能够处理更多的数据,而不必把它们送到老时代。Censum 也显现有许多过早提高。这和一段时刻之后发作的 full GC 也是共同的。不幸的是,这些设置没有起到任何效果。

接下来我想,或许出产者制作数据太快了,顾客来不及消费,导致这些记载在它们被处理前就被收回了。我测验减小出产数据的线程数量,下降数据发作的速度,一起坚持顾客发送给 ES 的数据池巨细不变。这首要是运用背压(backpressure)机制,不过它也没有起到效果。

一定是内存走漏

这时,一个其时脑筋还坚持镇定的搭档,主张咱们应该做一开端就做的作业:查看堆中的数据。咱们预备了一个开发环境的实例,具有和线上实例相同的数据量,堆的巨细也大致相同。把它衔接到 jnisualvm ,剖析内存的样本,咱们能够看到堆中目标的大致数量和巨细。大眼一看,能够发现咱们域中Ad目标的数量高的不标签11正常,并且在索引的进程中一向在添加,一向添加到咱们处理的广告的数量等级。可是……这不应该啊。究竟,咱们经过 RX 把这些数据整理成流,便是为了避免把一切的数据都加载到内存里。

跟着置疑越来越强,我查看了这部分代码。它们是两年前写的,之后就没有再被细心的查看过。果不其然,咱们实践上把一切的数据都加载到了内存里。这当然不是故意的。因为其时对 RxJava 的了解不可全面,咱们想让代码以一种特别的方法并行运转。为了从 RX 的主作业流中剥离出来一些作业,咱们决议用一个独自的 executor 跑 CompetableFuture。可是,咱们因而就需求等候一切的 CompetableFuture 都作业完……经过存储他们的引证,然后调用 join()。这导致一向到索引完结,一切的 future 的引证,以及它们引证到的数据,都坚持着生计的状况。这阻挠了废物搜集器及时的把它们整理掉。

真有这么糟糕吗?

当然这是一个很愚笨的过错,关于发现得这么晚,咱们也很厌恶。我乃至想起好久之前,关于这个运用需求 12 GB 的堆的问题,曾有个简略的评论。12 GB 的堆,的确有点大了。可是另一方面,这些代码现已运转了将近两年了,没有发作过任何问题。咱们能够在其时相对简略的修正它,可是假如是两年前,这或许需求咱们花费更多的时刻,并且相关于节约几个 G 的内存标签5,其时咱们有许多更重要的作业。

因而,虽然从纯技能的视点来说,这个问题如此长时刻没处理的确很丢人,可是从战略性的视点来看,或许藏着这个糟蹋内存的问题不论,是更务实的挑选。当然,另一个考虑便是这个问题一旦发作,会形成什么影标签5响。咱们几乎没有对用户形成任何影响,不过成果有或许更糟糕。软件工程便是权衡利弊,决议不同使命的优先级也不破例。

仍是不可

有了更多运用 RX 的经历之后,咱们能够很简略的处理 ComplerableFurue 的问题。重一次 Java 内存走漏排查进程,涨姿态写代码,只运用 RX;在重写的进程中,晋级到 RX2;实在的流式处理数据,而不是在内存里搜集它们。这些改动经过 code review 之后,布置到开发环境进行测验。让咱们吃惊的是,运用所需的内存一点点没有削减。内存抽样显现,相较之前,内存中广告目标的数量有所削减。并且目标的数量现在不会一向添加,有时也会下降,因而他们不是悉数在内存里搜集的。仍是老问题,看起来这些数据依然没有实在的被归集成流。

那现在是怎样回事?

相关的关标签10键词方才现已提到了:背压。当数据被流式处理,出产者和顾客的速度不同是很正常的。假如出产者比顾客快,并且不能把速度降下来,它就会一向出产越来越多的数据,顾客无法以相同的速度处理掉他们。现象便是未处理数据的缓存不断添加,而这便是咱们运用中实在发作的。背压便是一套机制,它答应一个较慢的顾客告知较快的出产者去降速。

咱们的索引体系没有背压的概念,这在之前没什么问题,横竖咱们把整个索引都保存到内存里了。一旦咱们处理了之前的问题,开端实在的流式处理数据,缺少背压的问题就变得很显着了。

这个形式我在处理功能问题时见过许屡次了:处理一个问题时会显现另一个你乃至没有听说过的问题,因为其他问题把它躲藏起来了。假如你的房子常常被淹,你不会注意到它有火灾危险。

修正标签20由修正引起的问题

在 RxJava 2 里,本来的 Observable 一次 Java 内存走漏排查进程,涨姿态类被拆成了不支撑背压的 Observable 和支撑背压的 Flowable。走运的是,有一些简略的方法,能够开箱即用的把不支撑背压的 Observable 改形成支撑背压的 Flowable。其间包括从非呼应式的资源比方 Iterable 创立 Flowable。把这些 Flowable 交融起来能够生成相同支撑背压的 Flowable,因而只需快速处理一个点,整个体系就有了背压的支撑。

有了这个改动之后,咱们把堆从 12 GB 削减到了 3 GB ,一起让体系坚持和之前相同的速度。咱们依然每隔数小时就会有一次暂停长达 2 秒的 full GC,不过这比咱们之前见到的 20 秒的暂停(还有体系溃散)要好多了。

再次优化 GC

可是,故事到此还没有完毕。查看 GC 的日志,咱们注意到许多的过早提高,占到 70%。虽然功能现已能够接受了,咱们也测验去处理这个问题,期望或许能够一起处理 full GC 的问题。

假如一个目标的生命周期很短,可是它依然提高到了老时代,咱们就把这种现象叫做过早提高(premature tenuring)(或许叫过早晋级)。老时代里的目标一般都比较大,运用与新生代不同的 GC 算法,而这些过早提高的目标占有了老时代的空间,所以它们会影响 GC 的功能。因而,咱们想极力避免过早提高。

咱们的运用在索引的进程中一次 Java 内存走漏排查进程,涨姿态会发作许多短生命周期的目标,因而一些过早提高是正常的,可是不应该如此严峻。当运用发作许多短生命周期的目标时,能想到的榜首件事便是简略的添加新生代的空间。默许状况下,G1 的 GC 能够主动的调整新生代的空间,答应新生代运用堆内存的 5% 至 60%。我注意到运转的运用里,新生代和老时代的份额一向在一个很宽的起伏里改变,不过我依然着手修正了两个参数:-XX:G1NewSizePercent=40 和 -XX:G1MaxNewSizePercent=90看看会发作什么。这没起效果,乃至让作业变得更糟糕了,运用一发动就触发了 full GC。我也测验了其他的份额,不过最好的状况便是只添加 G1MaxNewSizePercent而不修正最小值。这起了效果,大约和默许值的体现差不多,也没有变好。

测验了许多方法后,也没有获得什么成果,我就抛弃了,然后给 Kirk Pepperdine 发了封邮件。他是位很闻名的 Java 功能专家,我碰巧在 Allegro 举行的 Devoxx 会议的练习课程里认识了他。经过查看 GC 的日志以及几封邮件的沟通,Kirk 主张试试设置 -XX:G1MixedGCLiveThresholdPercent=100。这个设置应该会强制 G1 GC 在 mixed GC 时不去考虑它们被填充了多少,而是强制整理一切的老时代,因而也一起整理了从新生代过早提高的目标。这应该会阻挠老时代被填满然后发作一次 full GC。可是,在运转一段时刻今后,咱们再次惊奇的发现了一次 full GC。Kirk 揣度说他在其他运用里也见到过这种状况,它是 G1 GC 的一个 bug:mixed GC 显着没有整理一切的废物,让它们一向堆积直到发作 full GC。他说他现已把这个问题通知了 Oracle,不过他们坚称咱们观察到的这个现象不是一个 bug,而是正常的。

定论

咱们最终做的便是把运用的内存调大了一点点(从 3 GB 到 4 GB标签11),然后 full GC 就消失了。咱们依然观察到许多的过早提高一次 Java 内存走漏排查进程,涨姿态,不过已然功能是没问题的,咱们就不在乎这些了。一个咱们能够测验的选项是转换到 GMS(Concurrent Mark Sweep)GC,不过因为它现已被抛弃了,咱们仍是尽量不去运用它。

那么这个故事的涵义是什么呢?首要,功能问题很简略让你误入歧途。一开端看起来是 ZooKeeper 或许 网络的问题,最终发现是咱们代码的问题。即便认识到了这一点,我首要采纳的办法标签5也没有考虑周全。为了避免 full GC,我在查看究竟发作了什么之前就开端调优 GC。这是一个常见的圈套,因而记住:即便你有一个直觉去做什么,先查看一下究竟发作了什么标签5,再查看一遍,避免糟蹋时刻去过错的问题。

第二条,功能问题太难处理了。咱们的代码有杰出的测验覆盖率,并且运转的特别好标签1,可是它也没有满意功能的要求,它在开端的时分就没有明晰的界说好。功能问题直到布置之后好久才显现出来。因为一般很难实在的再现你的出产环境,你常常被逼在出产环境测验功能,即便那听起来十分糟糕。

第三条,处理一个问题有或许引发另一个潜在问题的显现,逼迫你不断挖的比你料想的更深。咱们没有背压的现实足以中止这个体系,可是直到咱们处理了内存走漏的问题后,它才显现。