来自公众号:Gopher指北

偈语: 未经别人苦,莫劝别人善

酣战两周无余,为了排查线上某接口百分百超时的起因,现在总算有些成绩。尽管仍有疑虑然而碍于工夫不容许和集体能力问题先做如下总结以备来日再战。

进口带宽拉满

可能发现这个问题实属幸运。依稀记得这是一个风雨交加的夜晚,这风、这雨注定了今夜的不平庸。果然线上百分百超时的根因被发现了!

咱们的线上接口须要对外申请,而咱们的流出带宽被拉满天然耗时就长因而导致超时。当然这都是后果,毕竟两头过程的艰苦曾经远远超出老许的文字所能形容的范畴。

反思

后果有了,该有的反思仍旧不能少。比方流出带宽被拉满为什么没有提前预警!无论是自信带宽足够还是经验不足都值得老许记上一笔。

而在带宽问题被真正发现之前,老许心田对带宽其实已有所狐疑,然而却没有认真进行验证,只听信了别人的揣测导致发现问题的工夫被推延。

httptrace

有时候不得不吹一波Go对http trace的良好反对。老许也是基于此做了一个demo,该demo能够打印http申请各阶段耗时。

上述为一次http申请各阶段耗时输入,有趣味的可去https://github.com/Isites/go-...拿到源码。

老许对带宽的狐疑次要就是基于此demo中的源码进行线上分析测试给到的揣测。

框架问题

本局部更加适宜腾讯系的兄弟们去浏览,其余非腾讯系技术能够间接跳过。

我司的框架为TarsGo,咱们在线上设置handletimeout为1500ms,该参数次要用于管制某一接口总耗时不超过1500ms,而咱们的超时告警均为3s,因而即便带宽已满这个百分百超时告警也不应呈现。

为了钻研这个起因,老许只好花些系统的工夫去浏览源码,最终发现了TarsGo@v1.1.6handletimeout管制是有效的。

上面看一下有问题的源码:

func (s *TarsProtocol) InvokeTimeout(pkg []byte) []byte {    rspPackage := requestf.ResponsePacket{}    rspPackage.IRet = 1    rspPackage.SResultDesc = "server invoke timeout"    return s.rsp2Byte(&rspPackage)}

当某接口总执行工夫超过handletimeout时,会调用InvokeTimeout办法告知client调用超时,而上述的逻辑中疏忽了IRequestId的响应,这就导致client收到响应包时无奈将响应包和某次的申请对应起来,从而导致客户端始终期待响应直至超时。

最终批改如下:

func (s *TarsProtocol) InvokeTimeout(pkg []byte) []byte {    rspPackage := requestf.ResponsePacket{}    //  invoketimeout need to return IRequestId    reqPackage := requestf.RequestPacket{}    is := codec.NewReader(pkg[4:])    reqPackage.ReadFrom(is)    rspPackage.IRequestId = reqPackage.IRequestId    rspPackage.IRet = 1    rspPackage.SResultDesc = "server invoke timeout"    return s.rsp2Byte(&rspPackage)}

起初老许在本地用demo验证handletimeout终于能够管制失效。当然本次批改老许曾经在github下面提交issue和pr,目前已被合入master。相干issue和pr如下:

https://github.com/TarsCloud/...

https://github.com/TarsCloud/...

仍有疑虑

到这里,事件仍然没有失去完满的解决。

上图为咱们对外部申请做的最大耗时统计,毛刺重大且耗时几乎不合乎常理。图中标红局部耗时约为881秒,而实际上咱们在发动http申请时均做了严格的超时管制,这也是令老许最为头疼的问题,这几天脸上冒的痘都是为它熬夜的证实。

更加令人惊恐的事件是,咱们将官网的http替换为fasthttp后,毛刺没有了!老许自认为对go的http源码还有几分肤浅的了解,而残暴的事实几乎令人狐疑人生。

到目前,老许再次简阅了一遍http的源码,仍未发现问题,这大概率会成为一桩悬案了,还望各位有教训的大佬分享一二,至多让这篇文章善始善终。

替换fasthttp时还未发现带宽被拉满

美妙愿景

最初,别无他言,间接上图!