看了对方的反馈,对方在服务内部也设置了超时,如果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请求。
正常三方返回如下: