一次 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 的内存，当时咱们有不少更重要的工做。

所以，虽然从纯技术的角度来讲，这个问题如此长时间没解决确实很丢人，然而从战略性的角度来看，或许留着这个浪费内存的问题无论，是更务实的选择。固然，另外一个考虑就是这个问题一旦发生，会形成什么影响。咱们几乎没有对用户形成任何影响，不过结果有可能更糟糕。软件工程就是权衡利弊，决定不一样任务的优先级也不例外。

仍是不行

有了更多使用 RX 的经验以后，咱们能够很简单的解决 ComplerableFurue 的问题。重写代码，只使用 RX；在重写的过程当中，升级到 RX2；真正的流式处理数据，而不是在内存里收集它们。这些改动经过 code review 以后，部署到开发环境进行测试。让咱们吃惊的是，应用所需的内存丝毫没有减小。内存抽样显示，相较以前，内存中广告对象的数量有所减小。并且对象的数量如今不会一直增加，有时也会降低，所以他们不是所有在内存里收集的。仍是老问题，看起来这些数据仍然没有真正的被归集成流。

那如今是怎么回事？

相关的关键词刚才已经提到了：背压。当数据被流式处理，生产者和消费者的速度不一样是很正常的。若是生产者比消费者快，而且不能把速度降下来，它就会一直生产愈来愈多的数据，消费者没法以一样的速度处理掉他们。现象就是未处理数据的缓存不断增加，而这就是咱们应用中真正发生的。背压就是一套机制，它容许一个较慢的消费者告诉较快的生产者去降速。

咱们的索引系统没有背压的概念，这在以前没什么问题，反正咱们把整个索引都保存到内存里了。一旦咱们解决了以前的问题，开始真正的流式处理数据，缺乏背压的问题就变得很明显了。

这个模式我在解决性能问题时见过不少次了：解决一个问题时会浮现另外一个你甚至没有据说过的问题，由于其余问题把它隐藏起来了。若是你的房子常常被淹，你不会注意到它有火灾隐患。

修复由修复引发的问题

在 RxJava 2 里，原来的 Observable 类被拆成了不支持背压的 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 的性能。所以，咱们想竭力避免过早提高。

咱们的应用在索引的过程当中会产生大量短生命周期的对象，所以一些过早提高是正常的，可是不该该如此严重。当应用产生大量短生命周期的对象时，能想到的第一件事就是简单的增长新生代的空间。默认状况下，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），而后 full GC 就消失了。咱们仍然观察到大量的过早提高，不过既然性能是没问题的，咱们就不在意这些了。一个咱们能够尝试的选项是转换到 GMS（Concurrent Mark Sweep）GC，不过因为它已经被废弃了，咱们仍是尽可能不去使用它。

那么这个故事的寓意是什么呢？首先，性能问题很容易让你误入歧途。一开始看起来是 ZooKeeper 或者 网络的问题，最后发现是咱们代码的问题。即便意识到了这一点，我首先采起的措施也没有考虑周全。为了防止 full GC，我在检查到底发生了什么以前就开始调优 GC。这是一个常见的陷阱，所以记住：即便你有一个直觉去作什么，先检查一下到底发生了什么，再检查一遍，防止浪费时间去错误的问题。

第二条，性能问题太难解决了。咱们的代码有良好的测试覆盖率，并且运行的特别好，可是它也没有知足性能的要求，它在开始的时候就没有清晰的定义好。性能问题直到部署以后好久才浮现出来。因为一般很难真实的再现你的生产环境，你常常被迫在生产环境测试性能，即便那听起来很是糟糕。

第三条，解决一个问题有可能引起另外一个潜在问题的浮现，强迫你不断挖的比你预想的更深。咱们没有背压的事实足以中断这个系统，可是直到咱们解决了内存泄漏的问题后，它才浮现。

欢迎工做一到五年的Java工程师朋友们加入Java填坑之路：86011    3481

群内提供免费的Java架构学习资料（里面有高可用、高并发、高性能及分布式、Jvm性能调优、Spring源码，MyBatis，Netty,Redis,Kafka,Mysql,Zookeeper,Tomcat,Docker,Dubbo,Nginx等多个知识点的架构资料）合理利用本身每一分每一秒的时间来学习提高本身，不要再用"没有时间“来掩饰本身思想上的懒惰！趁年轻，使劲拼，给将来的本身一个交代！