來源于公眾號Java藝術 ，

作者wujiuye

兩耳不聞窗外事，一心只讀圣賢書。又是一個美好的周末，一覺睡到自然醒，寫寫文章看看書！這周原計劃是寫Dubbo注冊中心的，但這周先說故事。

上次服務雪崩還是一個月前的事情，雖然上次雪崩事件之后加了熔斷器，但這次服務崩潰原因并未達到限流的QPS值。由于前一次雪崩后做了些參數上的調整，比如取消dubbo重試機制，減小超時時間，添加mock機制等，不至于服務完全癱瘓，但請求平均耗時異常彪升，超出臨界值的請求全部處理異常。

項目不斷新增需求，難免不會出現問題，特別是近期新增的增加請求處理耗時的需求。以及一些配置的修改而忽略掉的問題，如dubbo工作線程數調增時，忽略了redis連接池的修改。由于redis可用連接遠小于工作線程數，就會出現多個線程競爭redis連接，影響性能。

在發現請求平均耗時超出異常，而并發量卻未有異常突增時，查看服務器日記發現日記打印了密密麻麻的遠程調用超時異常，看日記就能很清楚的知道是哪個服務哪個接口調用超時。日記內容大致如下，詳細信息能夠看到調用的類、方法名以及參數。

org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer.

對外服務(下文統稱服務A)處理終端一次請求的平均耗時在25ms左右，正常情況下并發量突增到服務所能承受的最高點時，最大耗時也在200ms以內，而一次請求中調用某個服務(下文統稱服務B)的耗時必然會小于一次請求的處理耗時，所以我把服務A調用服務B的rpc調用超時設置為500ms，避免因調用阻塞等待導致請求堆積問題，所以本次服務崩潰并未看到文件句柄數達上限的異常，也因如此，只會有部分請求處理失敗，不止于整個服務完全不可用。

看到請求處理耗時，首先想到的是redis，但通過redis-cli工具排除了redis性能問題。通過SSH連上到服務B的某個節點，也并未發現jedis連接超時或是查詢超時異常，暫時排除redis性能問題。最后通過htop命令，發現cpu使用率一直居高不下，根據經驗判斷，要么程序中出現什么死循環，要么就是代碼執行計算任務耗時，非IO操作，比如大量for循環計算。

從日記中已經能定位到服務B的某個接口執行耗時，但接口的實現很復雜。通過過濾器鏈封裝了具體調用邏輯，而過濾器鏈中大概有六七個過濾器，過濾器鏈按照注冊順序調用過濾器的filter方法，當某個過濾器返回true時，后面的過濾器就不會執行。

如果項目中加入分布式系統調用鏈追蹤系統，比如Zipkin+Brave+Elasticsearch，那么排查問題就會非常簡單，但需要為此花費大日記存儲的費用，因此我們項目中并未使用。除此之外，要定位到線上問題，找出哪個方法耗時，或者都有哪些方法比較耗時，就需要借助一些Agent工具，監控或取樣每個方法的執行耗時，從而定位到具體的過濾器具體的某個方法，比如Jprofile、Arthas。

Jprofile對線上高并發服務影響比較大，且需要在本地使用Jprofile應用遠程連接。關于Jprofile的介紹以及使用可以查看我的歷史文章：使用Jprofiler遠程監控線上服務。Arthas在線文檔https://alibaba.github.io/arthas/watch.html。

在此次問題排除過程中，watch、monitor、trace這三個命令都起了很大的作用。

首先使用watch監控服務B對外提供服務(provider)的接口處理耗時，通過'#cost>500'輸出耗時大于500ms的調用日記， -x 指定參數和返回打印的深度，在不關心方法具體參數內容時，也可去掉“{params,returnObj}”。

通過watch命令發現，服務B暴露給其它服務調用的接口，調用耗時大于500ms的非常多，因此，根據代碼層面的理解，大概定位到會出現耗時如此高的過濾器。繼續使用watch監控具體某個過濾器的過濾方法的耗時。

在監控某個過濾器的方法執行耗時上找到了答案。arthas頻繁打印記錄，單個過濾器的一個過濾方法執行耗時就超過1000ms，將'#cost'降到到500ms后更多。

繼續使用monitor命令監控某個方法的執行信息，包括執行總數、執行成功次數、異常失敗次數、平均耗時、失敗率等，通過 -c 1 指定統計周期為1s。

當前服務B配置的Dubbo工作線程池的大小為256，圖中接口的平均耗時最大達到1s，圖中最大QPS為300，此時CPU使用率接近百分百，假設該服務部署兩個節點，以此估算最大QPS為600。

當服務A并發數達到11w每分鐘時，三個節點，轉為QPS就是每節點每秒處理611個請求，剛好就是服務B的QPS，所以當服務A并發量超過11w/min的閾值時，服務就變得不可用，大量請求得不到處理，平均耗時異常飆升。

由于之前根據每請求耗時最大25ms計算的QPS，設置限流規則，而當前rpc遠程調用并未達到限流的條件，遠端沒有空閑線程能夠處理rpc調用，所以consumer端就會收到provider端線程池已滿無法處理請求的異常，以及大量的rpc遠程調用超時異常。

我們還可以使用Arthas的trace命令輸出方法調用棧上的每個方法執行耗時。--skipJDKMethod true指定跳過jdk的函數調用，"#cost>100"指定只會展示耗時大于100ms的調用路徑。

使用--skipJDKMethod true跳過jdk方法在此處會有問題。因為我用jdk的List存放過濾器，通過遍歷List來順序調用過濾器鏈，過濾了jdk方法調用鏈就斷開了。

Dubbo處理遠程調用配置使用固定線程池，當所有線程都處于工作狀態時，并不會將新請求放入阻塞隊列，而是放棄請求，拋出異常。解決方案有三，一是優化代碼，如果代碼實在優化不了，那就方案二，改用非固定線程池或增加線程數，但200個線程已經讓cpu處于百分百的使用率，且增加線程也并不能解決耗時問題，反而耗時會上漲，那么，最后就只剩方法三，橫向擴展節點。

此次代碼層面的優化包括，使用zcount替換redis的hgetall優化了業務邏輯，以及以內存換性能，在redis緩存上再加一層內存緩存，內存緩存緩存方法返回結果，在redis數據更新時移除內存記錄。優化后，服務B的QPS有了顯著的提升，像極了牙膏，擠擠又省幾臺機器。

上圖是我在服務達到同樣并發量的條件下，用arthas驗證調優后的效果截圖。可以看到，請求平均耗時降低了100倍，QPS上去了。但是，事情并未結束，好戲才剛剛開始。

墨菲定律，每到下班時間準沒好事，果然，服務又崩潰了。但這次內部服務都正常，cpu使用率在正常范圍內，各個服務都沒有任何異常日記，服務A的rpc遠程調用超時問題也不存在了。可服務A打印的每個請求的處理耗時都超過500ms，明顯的非常不正常，于是又是一波Arthas操作。

終于找到問題，所以我說，這次Arthas是大功臣。在調用IP庫服務提供的restful接口出了問題，耗時全在這里。最后的優化是把IP位置信息的查詢由調用接口改為直接依賴封裝的組件從redis緩存中查，問題得以解決。關于IP庫可看我往期文章：基于Redis實現范圍查詢的IP庫緩存設計方案。

我們一直忽略了一個問題，就是并發量上升時，只考慮為接收外部請求的服務A添加節點，卻忘了大部分業務邏輯都是由內部的兩個服務去處理的，解決內部服務的性能問題才是提高對外服務A的QPS的關鍵。加節點應該先看各各服務的狀態，給最需要加節點的服務添加節點才是重中之重。否者服務A加的節點越多，接收的請求越多，越容易打垮內部服務。

也因此得出，現在我們的服務部署方案是有問題的。太關注對外服務A的處理能力而忽略了內部提供業務支持的服務。但這結論也會隨著外部服務不斷添加新需求的情況下被推翻，定期檢查各服務狀態將變得非常有必要。

排查項目性能瓶頸需要考慮到各方面，一是緩存redis的性能瓶頸，二是外部服務性能瓶頸，三是內部各服務的性能瓶頸，最后數據庫性能瓶頸。調優包括：業務邏輯優化、代碼調優、緩存調優、SQL調優、JVM調優。遇到問題一定要去找到問題的根源，只通過加機器處理問題，問題將會惡化得越來越嚴重，因為毒瘤一直都在！

總結

以上是生活随笔為你收集整理的某个软件调用目标异常_线上RPC远程调用频繁超时问题排查，大功臣Arthas的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。