一次带宽拉满引发的百分百超时血案!
来自公众号:Gopher指北
偈语: 未经他人苦,莫劝他人善
鏖战两周有余,为了排查线上某接口百分百超时的原因,如今总算有些成果。虽然仍有疑虑但是碍于时间不允许和个人能力问题先做如下总结以备来日再战。
出口带宽拉满
能够发现这个问题实属侥幸。依稀记得这是一个风雨交加的夜晚,这风、这雨注定了今夜的不平凡。果然线上百分百超时的根因被发现了!
我们的线上接口需要对外请求,而我们的流出带宽被拉满自然耗时就长因此导致超时。当然这都是结果,毕竟中间过程的艰辛已经远远超出老许的文字所能描述的范围。
反思
结果有了,该有的反思仍旧不能少。比如流出带宽被拉满为什么没有提前预警!无论是自信带宽足够还是经验不足都值得老许记上一笔。
而在带宽问题被真正发现之前,老许内心对带宽其实已有所怀疑,但是却没有认真进行验证,只听信了他人的推测导致发现问题的时间被推迟。
httptrace
有时候不得不吹一波 Go 对 http trace 的良好支持。老许也是基于此做了一个 demo,该 demo 可以打印 http 请求各阶段耗时。
上述为一次 http 请求各阶段耗时输出,有兴趣的可去https://github.com/Isites/go-coder/blob/master/httptrace/trace.go拿到源码。
老许对带宽的怀疑主要就是基于此 demo 中的源码进行线上分析测试给到的推测。
框架问题
本部分更加适合腾讯系的兄弟们去阅读,其他非腾讯系技术可以直接跳过。
我司的框架为 TarsGo,我们在线上设置handletimeout
为 1500ms,该参数主要用于控制某一接口总耗时不超过 1500ms,而我们的超时告警均为 3s,因此即使带宽已满这个百分百超时告警也不应出现。
为了研究这个原因,老许只好花些零碎的时间去阅读源码,最终发现了TarsGo@v1.1.6
的handletimeout
控制是无效的。
下面看一下有问题的源码:
当某接口总执行时间超过handletimeout
时,会调用InvokeTimeout
方法告知 client 调用超时,而上述的逻辑中忽略了IRequestId
的响应,这就导致 client 收到响应包时无法将响应包和某次的请求对应起来,从而导致客户端一直等待响应直至超时。
最终修改如下:
后来老许在本地用 demo 验证handletimeout
终于可以控制生效。当然本次修改老许已经在 github 上面提交 issue 和 pr,目前已被合入 master。相关 issue 和 pr 如下:
https://github.com/TarsCloud/TarsGo/issues/294
https://github.com/TarsCloud/TarsGo/pull/295
仍有疑虑
到这里,事情依然没有得到完美的解决。
上图为我们对外部请求做的最大耗时统计,毛刺严重且耗时简直不符合常理。图中标红部分耗时约为 881 秒,而实际上我们在发起 http 请求时均做了严格的超时控制,这也是令老许最为头疼的问题,这几天脸上冒的痘都是为它熬夜的证明。
更加令人惊恐的事情是,我们将官方的http
替换为fasthttp
后,毛刺没有了!老许自认为对 go 的 http 源码还有几分浅薄的理解,而残酷的现实简直令人怀疑人生。
到目前,老许再次简阅了一遍 http 的源码,仍未发现问题,这大概率会成为一桩悬案了,还望各位有经验的大佬分享一二,至少让这篇文章有始有终。
替换 fasthttp 时还未发现带宽被拉满
美好愿景
最后,别无他言,直接上图!
版权声明: 本文为 InfoQ 作者【Gopher指北】的原创文章。
原文链接:【http://xie.infoq.cn/article/92a15ef7389dcb66a8a132428】。未经作者许可,禁止转载。
评论