SRE重案调查组 第三集 | 探秘HTTP异步请求的“潘多拉魔盒”

原文地址: https://mp.weixin.qq.com/s/kVA4vrrk-UbttChu2zhaFA

 

供稿 | eBay Infrastructure Engineering

翻译&编辑 | 顾欣怡

本文共3365字，预计阅读时间11分钟

更多干货请关注“eBay技术荟”公众号

 

导读

  HttpAsyncClient 是基于Httpcore NIO 和Httpclient基础上做的进一步封装，主要利用异步回调方式，能够高效处理HTTP请求。可一旦使用不当，就会产生问题。本文将跟随eBay SRE部门人员视角，探索HTTP 异步请求导致的系统性能问题。

 

现在大型互联网的应用基本都采用微服务架构,内部各个组件之间相互调用产生的流量要比外部进来的流量大很多。对于基于Java的应用程序来说，内部组件之间相互调用的客户端很多都使用基于Apache社区提供的HttpAsyncClient。因为它能很好地封装HTTP请求的底层处理逻辑，开发人员只需要关注业务逻辑即可。

HttpAsyncClient是一个I/O(Input/Output)事件驱动的异步请求封装库，能够高效地处理HTTP请求。但是如果使用不当，就可能会造成一些意想不到的问题，犹如打开了“潘多拉魔盒”，让网络运维人员费尽心思才终于成功解决。

在此，本文将介绍一个与HTTP异步请求相关，发生在生产环境的真实案例。

 

01

“魔盒”初启

一天，运维人员发现某个应用的一些服务器JVM CPU使用率很高，同时GC overhead也升高，看上去很像内存泄漏。不过一段时间之后，在没有任何人工干预的情况下，部分机器倒也能够自愈。但有时，该应用内竟有80%的机器发生这一问题，且自愈时间从几分钟到几小时不等。甚至有时候，还没等它开始恢复，这些服务器就被云平台的智能修复系统给替换掉了。

图1为GC overhead和CPU使用率告警(GC overhead数据是×10之后的数据，所以1000代表100%):

图1（点击可查看大图）

 

02

相关背景

发生上述问题的是一个向外部提供主动通知的应用，它不断地从内部的某些消息队列拿最新消息，然后根据消息内设置的访问点去调用外部的某些API，以提供及时通知。

为了最大程度地提高系统吞吐量，该应用使用了内部定制版本的HttpAsyncClient，以异步的方式提高系统的整体性能。因为调用的是各种不同的外部API，所以这些API的稳定性可能无法保证，其网络状况也无法确保。

因此我们设置了最长的连接超时(Connect Timeout)时间为10秒，最长的网络通信超时(Socket Timeout)时长为30秒，以减少不必要的等待。

 

03

“案情”分析

拿到这个问题之后，我们首先注意到：当时的出错事件(Error)也增高了很多。仔细查看这些事件，发现很多都是超时(Timeout)错误。进一步查看出错的第三方API，手工验证一下，发现第三方的服务非常不稳定。有时候服务特别慢，直接导致我们的应用读取超时。开发人员第一时间联系了这个出错最多的第三方公司，确认了他们内部的应用问题，并进行了紧急修复。

然而，即使该第三方的服务趋于稳定，不再发生超时，可是我们的应用还是继续出现CPU和GC overhead告警。再次查看，发现还有其他第三方服务超时。因为要调用的第三方服务取决于每个客户自己在系统上的设置，所以我们根本无法预计到底有多少第三方，也不可能要求所有第三方都能稳定地提供服务。

况且，不论第三方服务是否稳定，我们都已设置超时时间，所以理论上我们的应用可能会变慢，但是不会影响整体运行状态。现在却不断发生CPU使用率和GC overhead告警，那么问题到底出在哪里呢?

根据对该应用指标数据的分析，发现CPU使用率的增高很大程度上是由Java GC引起的，所以我们可以从GC overhead查起。简单分析了一下GC日志，原来是heap不够用导致不断地做full GC。

于是我们进一步对获取的heap dump做内存使用状况分析，发现heap里竟然有几万个ScheduledFutureTask在Scheduler的DelayWorkQueue里面。正是这么多的ScheduledFutureTask才导致堆内存消耗殆尽。

那么，为什么会有这么多的Scheduled FutureTask堆积在内存里面呢? 它们是做什么用的呢?

图2为堆内存分析: 

4万多ScheduledFutureTask堆积在内存

图2（点击可查看大图）

根据DelayWorkQueue所在Scheduler的引用关系，以及相关的业务逻辑关系和源代码，我们终于厘清了这里面的逻辑:

图3为简化版本的业务逻辑图:

图3（点击可查看大图）

一个简化版本的业务逻辑可以描述为:

1) 应用首先从消息队列里面获取最新消息;

2) 根据消息的内容，使用HttpAsyncClient发出一个第三方API调用，在发出外部请求的同时，HttpAsyncClient新建一个TimeoutTask，根据设置的超时时间调度到未来的某个时间去执行。

这个TimeoutTask就是上面堆内存中积压的ScheduledFutureTask。由于该应用使用异步请求，所以对应的正常结果处理和出错业务处理都在回调函数里面;

3) 如果收到第三方回应(response)的时间早于预设的超时时间，那么就取消掉它对应的TimeoutTask，同时注册的正常处理的回调函数被执行;

4) 如果在还没有收到回应之前，就已经超时，那么这个TimeoutTask就会执行，并抛出一个TimeoutTask异常，接着超时的回调函数被执行。

这里的TimeoutTask有2种可能:

1)回应正常返回，TimeoutTask被取消。

2)回应超时，TimeoutTask在30秒之后被执行。

不论哪种情况，都不大可能产生积压。

那么为什么这个案例中还会堆积那么多ScheduledFutureTask呢?

 

04

“魔盒”揭秘

我们继续追查了处理超时的线程，发现当前的HttpAsyncClient版本里，有一个线程池专门处理这类TimeoutTask。而且，这个线程池里面只有一个线程。

当时设置该线程池大小的逻辑可能是这样的: 大部分调用都会在正常的时间内被处理，只有非常少的部分需要处理TimeoutTask。这一逻辑在绝大部分内网情况下是正常合理的，甚至在正常的互联网情况下都是正常的。因为通常我们定义一个99%的服务SLA，也就是99%的服务都在某个时间内能保证完成，正常情况下需要做超时处理的不超过1%，所以绝大多数情况下一个线程就足够了。

但问题，偏偏就出在了这1%上。

具体到我们这个案例里面，进一步查看后，发现该线程大多数情况下都在正常运行，要么等待超时任务到来，要么处理超时任务。可出人意料的是，有时候它竟然被阻塞(block)住了! 一旦唯一的线程被阻塞，就没有其他线程去处理超时队列里的任务了，直接导致了超时任务的积压。

问题逐渐明朗，真相就在眼前！“潘多拉魔盒”的奥秘即将解开！

我们继续探索，提出疑问：

那么该线程为什么会被阻塞呢?

原来这个应用的处理逻辑是这样的：

1) 先从消息队列拿到某种类型的消息，再根据消息设置使用异步HttpAsyncClient去调用第三方服务；

2) 不管消息返回成功还是失败，当执行调用服务的回调函数时，一处理完这个消息，就根据消息类型继续去拿下一个消息，并返回第1步。

问题的关键就在于：当去拿某种类型的新消息时，如果队列里面还没有该类型的消息，那么这个线程就会被阻塞在这里，直到获得新消息。

具体到我们这个案例里面，因为处理超时的线程只有一个，当它去超时的回调函数里拿最新消息时，就被阻塞住了。直接导致后续的超时消息都堆积起来，没有线程去处理。最终引发了GC overhead。

总的来说，这里有两方面的原因导致整个结果：

1）超时请求比较多，如果超时请求较少，就不会把堆内存填满，也就不会导致GC overhead。

2）超时线程被阻塞，直接导致处理超时的任务不能被及时清理。

 

05

举一反三

总算找出了症结所在，走到这一步，着实不易。但解决问题不仅要有一说一，更要举一反三。

其实不仅仅是处理超时的线程会出这样的问题，即便是处理IO的线程，也会有相同情况。众所周知，处理IO的线程也是有限的，也是处理正常结束的回调函数的线程。如果处理正常结束的线程都被阻塞，那么就没有线程去处理系统IO，最终也会出问题。

虽然我们使用的HttpAsyncClient是包含了内部优化的早期版本，不过即便是最新的稳定版本 4.1.4，大致也是这么工作的。

下面我们以最新版本的HttpAsyncClient为例，使用最小的原型去验证该问题。

我们设置连接超时（Connect Timeout）和网络通信超时（Socket Timeout）分别为2秒和5秒，分别去请求不同的站点。其中有三个站点是肯定连接失败的，另外两个本地的请求都是故意设置成8秒之后才返回数据，所以一定会发生网络通信超时。另外我们在请求出错时的回调函数里面，让处理出错的线程休眠(sleep)30秒。

图4为代码示例:

图4（点击可查看大图）

图5（点击可查看大图）

从上图5的运行结果可以看出：

1) 2个访问ebay.com 的请求都在最快的时间内收到回复，处理回复的线程是"I/O dispatcher"线程。默认情况下，"I/O dispatcher"的数目是系统可以使用CPU的数目(本例测试环境有16个CPU);

2) 访问facebook.com 的请求在2秒之后抛出了连接超时异常。执行回调函数的线程是"pool-1-thread-1"，是线程池里面的一个线程。根据回调函数的代码，这个线程将会休眠30秒;

3) 接着是访问localhost:3000的2个请求，因为我们设置服务器8秒之后才返回，这里的网络通信超时是5秒，所以基本在请求发出5秒之后，就发生超时了。处理这种读取超时的线程也是"I/O dispatcher";

4) 然后是twitter.com，在请求发出32秒之后抛出连接超时异常，处理这个回调函数的线程是"pool-1-thread-1"。虽然我们设置的连接超时时长是2秒，可是因为之前该线程被休眠了30秒，所以这里需要32秒才报错;

5) 最后一个google.com同样是连接超时，也是"pool-1-thread-1"处理，因为同样的原因需要2次休眠之后才被处理。

这里我们观察到：有16个"I/O dispatcher"线程，跟CPU个数一样多，所以我们的I/O处理没有任何延迟。但当请求大大超过这个数目时，加之正常处理I/O的回调函数又很耗时间，最终就会造成I/O处理积压。

处理连接超时的线程池"pool-1"默认只有一个线程，任何在超时的回调函数里面的耗时操作，都会影响该问题的及时处理。同时这里使用休眠(sleep)方式去暂停回调函数执行线程，一旦使用阻塞(block)的方式，效果将会更糟。

 

06

案例总结

经过SRE部门人员的一番寻根究底，HTTP异步请求的“潘多拉魔盒”之秘终于解开，在抓住“元凶”，合上魔盒的那一刹那，运维“侦探们”总算可以暂缓片刻，歇息一会儿了。

最后在这里提供几点建议，以免同业人员误启魔盒，为此困扰：

首先，在使用HttpAsyncClient的程序代码中，回调函数处理不能过长，绝对不能被阻塞。

同时，要根据系统的具体情况，设置处理IO的线程和处理超时的线程的数量，从而保证有足够线程去及时处理系统的IO和超时问题。

希望本案例能给大家有所启发，让同业朋友们有所收获！