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

原文：

https://blog.csdn.net/m0_73311735/article/details/131806588

引言

看到一篇不错的线上问题排查文章，这里做一个分享，下面内容对于这篇文章做一个精简和总结。

归纳

问题

广告业务三方对接，个别广告主出现“超时”告警。

排查手段

1. ping检查网络连接。
2. curl分析各阶段业务耗时。
3. 检查业务代码，增加日志断点调试。
4. tcpdump抓包 +wireshark 分析
5. 抓包对比其他对接方正常请求。
6. 删除几个返回字段，问题解决。
7. libcurl的源码分析，发现204的处理存在BUG。
8. 修改服务器的libcurl的源码，问题解决。

结论

libcurl 源码存在缺陷。

业务背景

本文介绍了一次 超时 问题，问题点是广告业务中第三方接口调用性能问题产生的超时问题排查。

针对三方的业务监控中，包括对三方广告主的请求数、返回数、qps、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

网络很稳定，排除网络问题。

双方沟通，对接方第一时间关闭超时严重广告主，但是发现还是有超时的情况，并且后续沟通了解到对方在服务内部也设置了超时，如果200ms内没有得到有效广告，则返回。

继续分析

尝试使用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 解析后结果如下：

image.png

image.png

从上面抓包结果来看，在序号为6的位置，对方返回了http 204，然后又重新手动发了一次curl请求，在序号10的时候，对方又返回了http 204。

从发送请求到收到对方响应耗时38ms

此外，后面50s后client端（发送方）发送FIN请求关闭连接，从代码逻辑来分析，是因为超时导致的关闭连接。

所以结论就是抓包也没看出端倪。

同类对比

与其它家正常返回的做对比。具体做法是通过修改业务代码，输出http相关信息，输出内容如下：

curl_easy_setopt(handle_, CURLOPT_VERBOSE, 1L);

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

正常三方返回如下：

image.png

而超时的该家返回如下：

image.png

对比超时和正常的报文，超时的较正常的那一家，多了Content-Length、Content-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上进行了关键字搜索，得到了如下结果：

image.png

看来已经有人提过这个问题了，于是看了下当前线上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;

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

image.png

最后的解决办法是改动源码而不是进行升级。

结语

整个问题发现以及解决过程跟文章目录结构一致:收到报警->双方沟通->业务代码->线上抓包->同类对比->问题解决->原因分析->深入源码。