一次帶寬拉滿引發(fā)的百分百超時血案！
偈語: 未經(jīng)他人苦,莫勸他人善
鏖戰(zhàn)兩周有余，為了排查線上某接口百分百超時的原因，如今總算有些成果。雖然仍有疑慮但是礙于時間不允許和個人能力問題先做如下總結(jié)以備來日再戰(zhàn)。
出口帶寬拉滿
能夠發(fā)現(xiàn)這個問題實屬僥幸。依稀記得這是一個風(fēng)雨交加的夜晚，這風(fēng)、這雨注定了今夜的不平凡。果然線上百分百超時的根因被發(fā)現(xiàn)了!
我們的線上接口需要對外請求，而我們的流出帶寬被拉滿自然耗時就長因此導(dǎo)致超時。當(dāng)然這都是結(jié)果，畢竟中間過程的艱辛已經(jīng)遠(yuǎn)遠(yuǎn)超出老許的文字所能描述的范圍。
反思
結(jié)果有了，該有的反思仍舊不能少。比如流出帶寬被拉滿為什么沒有提前預(yù)警!無論是自信帶寬足夠還是經(jīng)驗不足都值得老許記上一筆。
而在帶寬問題被真正發(fā)現(xiàn)之前，老許內(nèi)心對帶寬其實已有所懷疑，但是卻沒有認(rèn)真進行驗證，只聽信了他人的推測導(dǎo)致發(fā)現(xiàn)問題的時間被推遲。
httptrace
有時候不得不吹一波Go對http trace的良好支持。老許也是基于此做了一個demo，該demo可以打印http請求各階段耗時。
上述為一次http請求各階段耗時輸出，有興趣的可去https://github.com/Isites/go-coder/blob/master/httptrace/trace.go拿到源碼。
老許對帶寬的懷疑主要就是基于此demo中的源碼進行線上分析測試給到的推測。
框架問題
本部分更加適合騰訊系的兄弟們?nèi)ラ喿x，其他非騰訊系技術(shù)可以直接跳過。
我司的框架為TarsGo，我們在線上設(shè)置handletimeout為1500ms，該參數(shù)主要用于控制某一接口總耗時不超過1500ms，而我們的超時告警均為3s，因此即使帶寬已滿這個百分百超時告警也不應(yīng)出現(xiàn)。
為了研究這個原因，老許只好花些零碎的時間去閱讀源碼，最終發(fā)現(xiàn)了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)
- }
當(dāng)某接口總執(zhí)行時間超過handletimeout時，會調(diào)用InvokeTimeout方法告知client調(diào)用超時，而上述的邏輯中忽略了IRequestId的響應(yīng)，這就導(dǎo)致client收到響應(yīng)包時無法將響應(yīng)包和某次的請求對應(yīng)起來，從而導(dǎo)致客戶端一直等待響應(yīng)直至超時。
最終修改如下：
- 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終于可以控制生效。當(dāng)然本次修改老許已經(jīng)在github上面提交issue和pr，目前已被合入master。相關(guān)issue和pr如下：
https://github.com/TarsCloud/TarsGo/issues/294
https://github.com/TarsCloud/TarsGo/pull/295
仍有疑慮
到這里，事情依然沒有得到完美的解決。
上圖為我們對外部請求做的最大耗時統(tǒng)計，毛刺嚴(yán)重且耗時簡直不符合常理。圖中標(biāo)紅部分耗時約為881秒，而實際上我們在發(fā)起http請求時均做了嚴(yán)格的超時控制，這也是令老許最為頭疼的問題，這幾天臉上冒的痘都是為它熬夜的證明。
更加令人驚恐的事情是，我們將官方的http替換為fasthttp后，毛刺沒有了!老許自認(rèn)為對go的http源碼還有幾分淺薄的理解，而殘酷的現(xiàn)實簡直令人懷疑人生。
到目前，老許再次簡閱了一遍http的源碼，仍未發(fā)現(xiàn)問題，這大概率會成為一樁懸案了，還望各位有經(jīng)驗的大佬分享一二，至少讓這篇文章有始有終。
替換fasthttp時還未發(fā)現(xiàn)帶寬被拉滿
美好愿景
最后，別無他言，直接上圖!
