查看原文
其他

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

SRE team eBay技术荟 2022-03-15

供稿 | 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 overheadCPU使用率告警(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和超时问题

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


下集预告:

关键应用非正常重启

8G内存服务器

Metaspace区霸占2G多

高达17万多ClassLoader

heap dump不堪负重

真相到底是什么?

SRE“侦探”度出山!

9月6日 下下周五 敬请关注:

SRE重案调查组 第四集 

一起查找JVM元数据区内存泄漏的真相吧!

不见不散!


上集回顾:

SRE重案调查组 第一集 | 高延迟问题的罪魁祸首System.gc()SRE重案调查组 第二集 | 挖掘应用处理变慢的“真相”
eBay2020校招现已正式启动!详情点击下方链接:

2020校招 | 你想要的eBay全都有!eBay校园招聘正式启动!

你还可以:

↓点击阅读原文,直接开启网申之旅!

您可能也对以下帖子感兴趣

文章有问题?点此查看未经处理的缓存