来自公众号:Gopher 指北
偈语: 未经别人苦, 莫劝别人善
酣战两周无余,为了排查线上某接口百分百超时的起因,现在总算有些成绩。尽管仍有疑虑然而碍于工夫不容许和集体能力问题先做如下总结以备来日再战。
进口带宽拉满
可能发现这个问题实属幸运。依稀记得这是一个风雨交加的夜晚,这风、这雨注定了今夜的不平庸。果然线上百分百超时的根因被发现了!
咱们的线上接口须要对外申请,而咱们的流出带宽被拉满天然耗时就长因而导致超时。当然这都是后果,毕竟两头过程的艰苦曾经远远超出老许的文字所能形容的范畴。
反思
后果有了,该有的反思仍旧不能少。比方流出带宽被拉满为什么没有提前预警!无论是自信带宽足够还是经验不足都值得老许记上一笔。
而在带宽问题被真正发现之前,老许心田对带宽其实已有所狐疑,然而却没有认真进行验证,只听信了别人的揣测导致发现问题的工夫被推延。
httptrace
有时候不得不吹一波 Go 对 http trace 的良好反对。老许也是基于此做了一个 demo,该 demo 能够打印 http 申请各阶段耗时。
上述为一次 http 申请各阶段耗时输入,有趣味的可去 https://github.com/Isites/go-… 拿到源码。
老许对带宽的狐疑次要就是基于此 demo 中的源码进行线上分析测试给到的揣测。
框架问题
本局部更加适宜腾讯系的兄弟们去浏览,其余非腾讯系技术能够间接跳过。
我司的框架为 TarsGo,咱们在线上设置 handletimeout
为 1500ms,该参数次要用于管制某一接口总耗时不超过 1500ms,而咱们的超时告警均为 3s,因而即便带宽已满这个百分百超时告警也不应呈现。
为了钻研这个起因,老许只好花些系统的工夫去浏览源码,最终发现了 TarsGo@v1.1.6
的handletimeout
管制是有效的。
上面看一下有问题的源码:
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 时还未发现带宽被拉满
美妙愿景
最初,别无他言,间接上图!