记一次线上超时问题的发现、排查、定位以及解决过程

C语言题库

共 4695字,需浏览 10分钟

 ·

2022-05-15 00:10


你好,我是雨乐!

在上一篇文章问题解决了,我却不知道原因中提到,最近从性能、监控方面对引擎进行优化,这不,监控刚上了,就发现了一个很严重的问题--超时

今天,借助此文,分享下该问题的发现、排查以及解决过程!

业务背景

在广告业务中,分为效果广告、KA广告以及三方广告等。效果广告和KA广告一般都仅限于内网,也就是说在内网中通过RPC进行访问,而三方广告,则需要访问外网,因为外网环境以及每家三方广告主的处理能力不同,导致性能不同。本次的超时就是针对的某个三方广告主。

本次针对三方的业务监控中,包括对三方广告主的请求数、返回数、qps、rt等指标。

收到报警

增加了监控的业务上线后,根据引擎监控系统来查看三方的基础数据监控,如下:

通过上述图表,看了下平均rt等业务指标,一切正常。开始着手配置超时等监控报警指标。鉴于业务的重要性,配置了邮件告警和短信告警两种,配置完成后,一键生效。结果,过了没几分钟,就收到了告警。

看到超时这么多,第一时间先ping下,看看网络间耗时咋样,结果如下:

64 bytes from 114.67.237.131: icmp_seq=1 ttl=49 time=7.13 ms
64 bytes from 114.67.237.131: icmp_seq=2 ttl=49 time=6.37 ms
64 bytes from 114.67.237.131: icmp_seq=3 ttl=49 time=6.10 ms
64 bytes from 114.67.237.131: icmp_seq=4 ttl=49 time=6.07 ms
64 bytes from 114.67.237.131: icmp_seq=5 ttl=49 time=6.04 ms
64 bytes from 114.67.237.131: icmp_seq=6 ttl=49 time=6.07 ms
64 bytes from 114.67.237.131: icmp_seq=7 ttl=49 time=6.03 ms
64 bytes from 114.67.237.131: icmp_seq=8 ttl=49 time=6.09 ms
64 bytes from 114.67.237.131: icmp_seq=9 ttl=49 time=6.11 ms
64 bytes from 114.67.237.131: icmp_seq=10 ttl=49 time=6.03 ms
64 bytes from 114.67.237.131: icmp_seq=11 ttl=49 time=6.07 ms

网络很稳定,看来跟网络没关系,只能通知对方。

双方沟通

跟对方反馈其rt超时很严重后,对方第一反应是内部有些广告主太耗时,于是其关闭了超时严重的广告主,然后让我这边继续观察。

待对方关闭耗时长的广告主后,重新打开监控报警(之前因为报警太频繁,暂时关闭了报警),然后没有几分钟,报警又又又来了。

赶紧在群里跟对方反馈,对方也是一脸懵逼,双方开始一起排查问题,毕竟没人跟钱过不去😁

为了便于尽快发现,在测试环境尝试将超时时间设置为2s,然后模拟发送请求,果不其然,超时。。。

看了对方的反馈,对方在服务内部也设置了超时,如果200ms内没有得到有效广告,则返回,也就是说对方也做了200ms的超时控制,很奇怪。。。

在测试环境将超时时间设置为50s,仍然有超时现象。。。

对接群沟通多少有点影响到别人,于是勾搭了对方的技术,开始私聊(此处开始甩锅模式)

不过,甩锅归甩锅,问题还得解决。开始尝试使用curl来分析各个阶段的耗时:

curl  -o /dev/null -s -w %{time_namelookup}::%{time_connect}::%{time_starttransfer}::%{time_total}::%{speed_download}"\n" --data-binary @req.dat https://www.baidu.com

输出结果如下:

从上述结构可以看出,在time_starttransfe阶段,也就是说对方业务处理结果仍然会出现2s耗时,问题复现。

业务代码

虽然该模块的核心代码在线上稳定运行了5年多,但是为了保险起见,还是得再分析下,免得再遗漏了某个分支条件,导致这种现象发生。

一般情况下,log是最直接也是最有效的方式,于是在每个步骤每个运行函数中加了日志,然后编译、运行,使用之前的测试case重新发送请求。分析日志,一切都在预期内,看来业务代码没问题,只能通过其它方式进行排查了。

线上抓包

既然业务代码没问题,那就只能通过tcpdump抓包来分析了,然后经过wireshark解析后,结果如下:

从上面抓包结果来看,在序号为6的位置,对方返回了http 204,然后又重新手动发了一次curl请求,在序号10的时候,对方又返回了http 204(从发送请求到收到对方响应耗时38ms),但是奇怪的时候,在后面50s后,client端(发送方)开发发送FIN请求关闭连接,从代码逻辑来分析,是因为超时导致的关闭连接。

从抓包现象只能得出上述结论,没什么有用的结论,看来只能通过其它方式继续分析。

同类对比

既然抓包都不能得到有用的结论,那就只能通过与其它家正常返回的做对比,看看能不能得到有用结论。

通过修改业务代码,输出http相关信息,如下:

curl_easy_setopt(handle_, CURLOPT_VERBOSE, 1L);

编译,运行,发起curl请求。

正常三方返回如下:

而超时的该家返回如下:

通过对比上述两家的区别,发现超时的该家较正常的三方返回,多了Content-LengthContent-Type等字段,那么有没有可能跟这几个字段的返回有关呢?

问题解决

让对方在其测试环境,在没有广告返回的时候,将这几个字段去掉。然后我这边重新发起curl请求。。。

然后发起curl请求,一切正常,在超时范围内返回。wrk压测,平均rt符合预期,看来问题就在这。

跟对方沟通后,对方修改代码,然后着手上线,上线后结果如下:

效果很明显,看来就是这个原因导致,超时问题解决了,收入也就蹭蹭地往上涨了😃。

分析原因

既然问题已经解决了,多少得知道原因吧,于是在搜索引擎上输入http 204 Content-Length hang,找到了有用信息,如下:

看来wget之前也存在此类问题,于是继续搜索标准,输出如下:

The presence of a message body in a response depends on both the request method to which it is responding and the response status code (Section 3.1.2). Responses to the HEAD request method (Section 4.3.2 of [RFC7231]) never include a message body because the associated response header fields (e.g., Transfer-Encoding, Content-Length, etc.), if present, indicate only what their values would have been if the request method had been GET (Section 4.3.1 of [RFC7231]). 2xx (Successful) responses to a CONNECT request method (Section 4.3.6 of [RFC7231]) switch to tunnel mode instead of having a message body. All 1xx (Informational), 204 (No Content), and 304 (Not Modified) responses do not include a message body. All other responses do include a message body, although the body might be of zero length.

深入源码

从上节标准可以看出,在http 204、304的时候,不允许返回Content-Length,那么如果返回了,libcurl又是如何处理的呢?

于是在curl的issue上进行了关键字搜索,得到了如下结果:

看来已经有人提过这个问题了,于是看了下当前线上libcurl的源码:

switch(k->httpcode) {
        case 204:
           /* (quote from RFC2616, section 10.2.5): The server has
            * fulfilled the request but does not need to return an
            * entity-body ... The 204 response MUST NOT include a
            * message-body, and thus is always terminated by the first
            * empty line after the header fields. */

           /* FALLTHROUGH */
                case 304:
           /* (quote from RFC2616, section 10.3.5): The 304 response
            * MUST NOT contain a message-body, and thus is always
            * terminated by the first empty line after the header
            * fields.  */

           if(data->set.timecondition)
             data->info.timecond = TRUE;
           k->size=0;
           k->maxdownload=0;
           k->ignorecl = TRUE; /* ignore Content-Length headers */
           break;

线上使用的版本果然没有处理此种情况,再跟线上做对比,改动如下:

好了,问题已经解决,原因也已经找到,毕竟不是大bug,为了稳妥起见,还是不升级了,以稳定为主,谁知道升级后又会出现什么意想不到的问题呢😁

结语

该问题从发现到解决,大概用了2天的时间。其实,从文章的目录结构就能发现,整个问题发现以及解决过程跟文章目录结构一致:收到报警->双方沟通->业务代码->线上抓包->同类对比->问题解决->原因分析->深入源码

好了,今天的文章就到这,我们下期见!

浏览 6
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报
评论
图片
表情
推荐
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报