背景
《50 ways to say goodbye》中文名《前任的50種死法》是我之前報的英語班里外教老師放給我們聽的歌。老外說很困惑為什么我們還在聽《Take me home,Country Road》這種老掉牙的歌。
《前任的50種死法》里因為生女友的氣幻想她的各種死法：飛機墜機、曬日光浴被曬死、被獅子吃掉、泡澡被淹死……
等等，聽着咋就這么像做項目：看起來根本就不可能的原因，結果服務被整死了。本系列文章匯總了50個項目中“下水被鯊魚吃掉”這樣的離奇的服務出錯分析。
案例分析-超時導致接口報500錯誤
引發問題
我做的heimdal和carter這兩個產品一期上線，heimdal是k8s的事件監聽服務。在設計為了驗證是否有事件丟失、對事件的處理是否正確等正確性驗證，carter作為heimdal的事件處理，並對外直接暴露接口提供服務。一期使用了mysql做存儲。因為mysql非常成熟，不會干擾對結果的驗證。
但實際上因為涉及各種過濾式的查詢。用sql來查詢的時候，這么來說吧，如果直接寫sql語句要嵌套幾十個in的子查詢。在代碼編寫的時候為了適應各種情況，分查詢語句的，就是說要建立多次連接。
來看上面的數據，resource這個接口TP90已經超過2秒了。上游調用在服務治理框架OCTO中顯示上游因為設置了超時時間為2秒，結果有0.4%的請求都調用失敗了。因為在核心鏈路里有10次重試，而且如果10次重試還是獲取不到結果，會在請求層失敗。調用方看到這個錯誤會再次發起請求，實際上是可以得到正確結果的。但是上游會有監控報警，觸發了報警，上游同學就來找我了。
我記得第一次處理這個問題是晚上11點多在地鐵上。用手機連vpn處理的。怎么應急處理這種事情呢？就是將堵塞的mysql慢查詢kill掉。
問題解決初版
綜合考慮已有問題的影響：實際上對業務沒有影響。所以決定先按照原有的計划先完成標簽管理系統hydra。用hydra的標簽過濾來代替幾十個in的子查詢。這個方法可以徹底解決對mysql的壓力。
hydra采用ElasticSearch做底層存儲，將原有的sql查詢轉化為ES查詢。並且因為標簽的修改頻率低，延時不敏感。我在編寫客戶端引用包的時候做了客戶端本地緩存處理。緩存最近30條查詢條件，每100ms取拉取最新條件對應的結果。所以條件命中的情況下，10ms完全可以返回結果。下面是端到端(最上游調用方的耗時，中間有很多網絡傳輸)的響應耗時數據：
因為2s超時，而時間上TP99可以在200ms內返回。所以理論上是完全可以解決問題的。
看起來很完美，線下環境運行非常正常。但是線上環境運行了1天之后，超時現象卻又復發了！在cat日志上還發現了大量由於mysql引起的錯誤。
mysql優化
下面是cat監控得到的結果，主要問題是數據庫獲取物理連接超時和內存溢出！
我們剛上線的服務qps每秒都沒有幾個請求，由於占用數據庫連接池太多而引起內存溢出很蹊蹺。並且查看數據庫日志，並沒有特別嚴重的慢查詢。了解到這不是背后的根因，但是同時也暴露出另外一個問題：數據庫參數設置是不合理的。
由於目前的報錯實際上對業務沒有影響。所以決定先不解決真正問題，而先借這個契機對數據庫進行一版優化。主要做了兩個優化：
第一，由於之前有部分的服務是主從延時敏感的，后面的同學新建服務的時候都一直采用“只讀主庫”的路由方式。考慮carter實際上對主從延時不敏感，同時從庫需要一定的流量來保證萬一主庫出現問題進行主從切換的時候，從庫是真正的熱備，不需要額外的激活操作。所以將carter改成主從分離。
第二，對物理連接不是很苛刻的情況下，可以適當調大checkoutTimeout這個參數，以免不斷的重連造成性能的反而下降。
通過這一版優化，cat上的錯誤日志確實是消失了。但是仍然超時！
解決根因
解決問題先看現象。下面是出現問題的那段時間的內存和cpu。能夠看到有明顯的攀升和尖刺。
從cat日志上找到耗時最長的那個記錄，點進入看到有個方法調用是不該出現的。就是本來我做了客戶端本地緩存，那就不應該在實際請求的時候走遠程調用。除非超過了30個的存儲限制，本地緩存失效！
果然，因為線上環境比線下復雜，30個不夠用了。通過配置管理改成150個緩存，問題解決。上面內存和cpu是顯示了1個月的數據。可以看到調整之后內存和cpu使用情況恢復了正常。
總結
慢就是錯。響應速度不符合預期要當做錯誤進行徹底的排查。
相關閱讀